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

[Paul Menzel]

Am Samstag, den 11.07.2015, 08:00 -0500 schrieb Aaron Durbin:
> On Sat, Jul 11, 2015 at 4:34 AM, Paul Menzel wrote:

[…]
> > 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.

yes, I also assumed it was due to your change set [1].
> If I guard with CONFIG_EARLY_CBMEM_INIT it'd go back to the previous 
> way.

I do too.
> 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.

I totally agree.
> If we want to change it back it's not that hard:

[…]

I can’t think of a reason, why we’d want to have the old behavior back.

Thanks,

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

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

[Aaron Durbin]

On Sat, Jul 11, 2015 at 11:52 AM, Paul Menzel
 wrote:
> Am Samstag, den 11.07.2015, 08:00 -0500 schrieb Aaron Durbin:
> > On Sat, Jul 11, 2015 at 4:34 AM, Paul Menzel wrote:
>
> […]
> > > 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.
>
> yes, I also assumed it was due to your change set [1].
> > If I guard with CONFIG_EARLY_CBMEM_INIT it'd go back to the previous
> > way.
>
> I do too.
> > 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.
>
> I totally agree.

Care to test this and show the output? See what you like?  I don't
have a machine up to test against at the moment. The same information
is there, but it's shown in a different way in that base_time is
reported as an entry of '1st timestamp'. Your example would change to
something like this:

0:1st timestamp                                     385,974
 10:start of ramstage                                 385,975 (1)
  30:device enumeration                                385,983 (8)
...

http://review.coreboot.org/10883
> > If we want to change it back it's not that hard:
>
> […]
>
> I can’t think of a reason, why we’d want to have the old behavior back.
>
> Thanks,
>
> Paul
> > > [1] http://review.coreboot.org/10880