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