[RFC] How to add “nested” time stamps?

[Paul Menzel]

Dear coreboot folks,

I’d like to add more time stamps for instrumentation/benchmarking.

I started with the timer initialization, and submitted two change sets
[1][2].

After rebuilding the utility `cbmem`, the relevant output looks like
below.

```
  60:device initialization                             457,880 (9,886)
 120:starting timer init                               472,001 (14,121)
 121:finished timer init                               472,008 (6)
  70:device setup done                                 472,751 (742)
```

Would that be acceptable to have nested entries? The down side is, the
time from *device initialization* to *device setup done* has to be
calculated manually now.

Also, I just chose the numbers 120 and 121 arbitrarily. Are there any
best practices for that to keep that extensible?

Thanks,

Paul

PS: If somebody has an idea on the weird build error on the DMP
Vortex86EX [3], I’d appreciate any help.

```
    ROMCC      romstage.inc
timestamp_serialized.h:23.16: 
bad type specifier :ident:
src/arch/x86/Makefile.inc:254: recipe for target '/dev/cb-build/coreboot-gerrit.0/DMP_EX/mainboard/dmp/vortex86ex/romstage.inc' failed
make[1]: *** [/dev/cb-build/coreboot-gerrit.0/DMP_EX/mainboard/dmp/vortex86ex/romstage.inc] Error 1
make[1]: Leaving directory '/home/coreboot/slave-root/workspace/coreboot-gerrit'
```

[1] https://review.coreboot.org/17701
[2] https://review.coreboot.org/17702
[3] https://qa.coreboot.org/job/coreboot-gerrit/47088/testReport/junit/%28root%2...

[Julius Werner]

We have kinda already added some cases like this so I hope nobody has
big objections to it. For example, you'll usually see
TS_START_ULZMA/TS_END_ULZMA in between TS_START_COPYRAM/TS_END_COPYRAM
so you can differentiate the transfer and decompression components of
loading the ramstage.

I don't think there are restrictions for choosing numbers apart from
what's already written in code comments in timestamp_serialized.h
(e.g. 1000+ is for payloads, 500-1000 is for vendor extensions, in
particular 500-600 Chrome OS and 950-1000 Intel). If you're adding
timestamps that will always fall between TS_DEVICE_INITIALIZE (60) and
TS_DEVICE_DONE (70), it would probably make sense to allocate them
from the range in between (e.g. 61, 62). (In general, we should
probably try to keep "generic coreboot" timestamps within 0-100 for
now so we keep 100-400 free for potential future sections we want to
add.)

Otherwise, I'd say feel free to add as many timestamps as you think
will add value. You just have to be careful that you don't risk
exceeding the available space on any board. I think that's current 84
timestamps for the total boot (shouldn't be too hard to increase if
necessary), with additional restrictions for pre-RAM environments and
super-early ramstage before CBMEM init.

[Nico Huber]

On 03.12.2016 12:52, Paul Menzel via coreboot wrote:
> After rebuilding the utility `cbmem`, the relevant output looks like
> below.
>   60:device initialization                             457,880 (9,886)
>  120:starting timer init                               472,001 (14,121)
>  121:finished timer init                               472,008 (6)
>   70:device setup done                                 472,751 (742)
>
> Would that be acceptable to have nested entries? The down side is, the
> time from *device initialization* to *device setup done* has to be
> calculated manually now.

It's actually simple to make `cbmem` aware of the nesting, if you'd
store the level of the nesting for each timestamp.

All that `cbmem` would then have to do is, store the last timestamp of
each level in an array, and everytime it encounters a decrease in level,
output a third number, that is the difference of the current to the
last timestamp of its level.

Nico