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

[Aaron Durbin]

On Sat, Jul 11, 2015 at 4:34 AM, Paul Menzel
<paulepanter at users.sourceforge.net> 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: coreboot at coreboot.org
> http://www.coreboot.org/mailman/listinfo/coreboot