[HEADS UP] Time stamps for AGESA boards now measured relatively to start and not ramstage

[Paul Menzel]

Dear coreboot folks,


thanks to the latest time stamp work and especially thanks to Aaron
Durbin’s latest fix up commit bd1499d3 (timestamps: don't drop ramstage
timestamps with EARLY_CBMEM_INIT) [1], the ramstage time stamps on
AGESA boards – I only tested with the ASRock E350M1 – seem to be
measured relative to the system start and not relatively to start of
ramstage.

Before time stamps were measured relatively to ramstage.

$ more asrock/e350m1/4.0-10267-g72dd909/2015-07-10T00\:11\:47Z/coreboot_timestamps.txt
12 entries total:

  10:start of ramstage                                 0
  30:device enumeration                                8 (8)
  40:device configuration                              94,880 (94,872)
  50:device enable                                     98,697 (3,816)
  60:device initialization                             108,662 (9,965)
  70:device setup done                                 122,998 (14,335)
  75:cbmem post                                        123,369 (371)
  80:write tables                                      123,374 (4)
  90:load payload                                      128,020 (4,646)
  15:starting LZMA decompress (ignore for x86)         128,275 (254)
  16:finished LZMA decompress (ignore for x86)         146,142 (17,866)
  99:selfboot jump                                     146,163 (21)

With the latest changes we they are measured relatively to system start.

$ more asrock/e350m1/4.0-10270-gbd1499d/2015-07-10T13\:23\:53Z/coreboot_timestamps.txt
12 entries total:

  10:start of ramstage                                 385,974
  30:device enumeration                                385,982 (8)
  40:device configuration                              480,233 (94,250)
  50:device enable                                     484,088 (3,855)
  60:device initialization                             494,049 (9,960)
  70:device setup done                                 508,368 (14,318)
  75:cbmem post                                        508,736 (368)
  80:write tables                                      508,741 (4)
  90:load payload                                      513,320 (4,579)
  15:starting LZMA decompress (ignore for x86)         513,574 (253)
  16:finished LZMA decompress (ignore for x86)         531,423 (17,848)
  99:selfboot jump                                     531,445 (21)

So 386 ms for romstage with AGESA is still an acceptable number. This
confirms, which was already known. AGESA does a pretty good job.

Time stamps from romstage are still not preserved though, which is a
well known limitation though.


Thanks,

Paul


[1] http://review.coreboot.org/10880

[Aaron Durbin]

On Sat, Jul 11, 2015 at 4:34 AM, Paul Menzel
<[e-mail]> wrote:
> Dear coreboot folks,
>
> thanks to the latest time stamp work and especially thanks to Aaron
> Durbin’s latest fix up commit bd1499d3 (timestamps: don't drop ramstage
> timestamps with EARLY_CBMEM_INIT) [1], the ramstage time stamps on
> AGESA boards – I only tested with the ASRock E350M1 – seem to be
> measured relative to the system start and not relatively to start of
> ramstage.
>
> Before time stamps were measured relatively to ramstage.
>
> $ more asrock/e350m1/4.0-10267-g72dd909/2015-07-10T00\:11\:47Z/coreboot_timestamps.txt
> 12 entries total:
>
> 10:start of ramstage                                 0
>   30:device enumeration                                8 (8)
>   40:device configuration                              94,880 (94,872)
>   50:device enable                                     98,697 (3,816)
>   60:device initialization                             108,662 (9,965)
>   70:device setup done                                 122,998 (14,335)
>   75:cbmem post                                        123,369 (371)
>   80:write tables                                      123,374 (4)
>   90:load payload                                      128,020 (4,646)
>   15:starting LZMA decompress (ignore for x86)         128,275 (254)
>   16:finished LZMA decompress (ignore for x86)         146,142 (17,866)
>   99:selfboot jump                                     146,163 (21)
>
> With the latest changes we they are measured relatively to system start.
>
> $ more asrock/e350m1/4.0-10270-gbd1499d/2015-07-10T13\:23\:53Z/coreboot_timestamps.txt
> 12 entries total:
>
> 10:start of ramstage                                 385,974
>   30:device enumeration                                385,982 (8)
>   40:device configuration                              480,233 (94,250)
>   50:device enable                                     484,088 (3,855)
>   60:device initialization                             494,049 (9,960)
>   70:device setup done                                 508,368 (14,318)
>   75:cbmem post                                        508,736 (368)
>   80:write tables                                      508,741 (4)
>   90:load payload                                      513,320 (4,579)
>   15:starting LZMA decompress (ignore for x86)         513,574 (253)
>   16:finished LZMA decompress (ignore for x86)         531,423 (17,848)
>   99:selfboot jump                                     531,445 (21)

This is actually surprising, but I just looked into it. I see why;
it's from my most recent change. If I guard with
CONFIG_EARLY_CBMEM_INIT it'd go back to the previous way. But I
actually do like this way (though unintended). The base_time was never
properly exported it from cbmem:
> -------for (i = 0; i < tst_p->num_entries; i++) {
> ------->-------const struct timestamp_entry *tse_p = tst_p->entries + i;
> ------->-------timestamp_print_entry(tse_p->entry_id, tse_p->entry_stamp,
> ------->------->-------i ? tse_p[-1].entry_stamp : 0);
> -------}

It always assumed 0 as a base_time. Without the diff below base_time
is actually 0 in this case so you see the accumulated time until
ramstage started. I actually think we should fix cbmem.c to not pass 0
as prev_stamp for 0th index. It should be passing base_time as well as
reporting what base_time was from an informational perspective.

If we want to change it back it's not that hard:

diff --git a/src/lib/timestamp.c b/src/lib/timestamp.c
index 7ead383..ca25093 100644
--- a/src/lib/timestamp.c
+++ b/src/lib/timestamp.c
@@ -202,7 +202,7 @@ void timestamp_init(uint64_t base)
        /* In the EARLY_CBMEM_INIT case timestamps could have already been
         * recovered. In those circumstances honor the cache which sits in BSS
         * as it has already been initialized. */
-       if (ENV_RAMSTAGE &&
+       if (ENV_RAMSTAGE && IS_ENABLED(CONFIG_EARLY_CBMEM_INIT) &&
            ts_cache->cache_state != TIMESTAMP_CACHE_UNINITIALIZED)
                return;
> So 386 ms for romstage with AGESA is still an acceptable number. This
> confirms, which was already known. AGESA does a pretty good job.
>
> Time stamps from romstage are still not preserved though, which is a
> well known limitation though.
>
> Thanks,
>
> Paul
>
> [1] http://review.coreboot.org/10880
> --
> coreboot mailing list: [e-mail]
> http://www.coreboot.org/mailman/listinfo/coreboot