[U-Boot] [PATCH 0/4] Accurate boot time measurement

[Graeme Russ]

On Mon, May 16, 2011 at 7:58 AM, Simon Glass <sjg at chromium.org> wrote:
> On Sun, May 15, 2011 at 4:53 AM, Wolfgang Denk <wd at denx.de> wrote:
>
>> Dear Simon Glass,
>>
>> In message <1305319923-9477-1-git-send-email-sjg at chromium.org> you wrote:
>> > This defines the basics of a new boot time measurement feature. This
>> allows
>> > logging of very accurate time measurements as the boot proceeds, by using
>> > an available microsecond counter.
>>
>> Well, as long as we talk about microsecond resolution, I do not see
>> the compelling advantage over the classic method of timing the output
>> on the serial console port.  At 115200 bps we have a "resolution" of
>> better than 0.1 millisecond per character; this should be precise
>> enough for most practical purposes.
>>

But at 9600 baud it is over 1ms - 9600 is still considered the lowest
common denominator for serial comms for diagnostic output for a lot of
devices such as industrial PLCs etc.

> Hi Wolfgang,
>
> This is 100us which is pretty good although you are assuming that there is
> no FIFO holding things. Also on modern ARM CPUs the 'processing' part of
> U-Boot (where it is not just waiting on a device) can be over in under
> 100ms, and if you are wanting to reduce this, a little more resolution
> doesn't hurt.
>
>
>> Logging and timing the serial output has a number of advantages over
>> other solutions:
>>
>> - It requires zero code changes.  You can run the production code and
>>  time it.  You can use it without rebuilding / reinstalling the
>>  software, yes even without access to the source code.
>>
>
> Are you not ignoring the timing parser on the serial port which must be
> written and changed to cope with the different output of U-Boot (net boot,
> USB boot, MMC boot, SD boot, etc.)? We have a lot of boot paths, different
> architectures, etc. We want a simple solution.
>
> In our case the console is silent on boot, so this solution does not work.
> Secondly it requires a listener on the serial port which we often don't
> have. Thirdly we want to log this information and record it in the field so
> that we track boot time. This means that it has to be done by the device
> itself.

I concur - Obtaining the timing information requires that the serial
console application can generate it - something most default terminal apps
(Hyperterminal for example) do not do. Also, timing is skewed by the UART
FIFO on the device and the UART FIFO on the host.

And in the field, you may be interested more in transient timing anomalies
which may result from network issues if the device is obtaining an IP address
or loading an image file. In such scenarios, you will need to log the boot
timing of every boot, not just when a serial terminal is connected

And finally, the lack of a serial port is a biggie - There are devices out
there that do not have serial ports

>> - It is completely platform, SoC and board idependent - we do not need
>>  to provide any specific timer servcies etc. which are inherently
>>  platform-dependent.
>>
>
> Is this really an advantage?
>
>
>> - It does not cause execution overhead on the running system - it
>>  affects neither the execution speed not the memory footprint of the
>>  target under test.
>>
>
> Write to the serial port costs about 30ms on our platform at minimum. I
> have't looked at why, but the serial FIFO is only so big so I assume that is
> what is happening. The overhead of bootstage is a function call, a readl(),
> a a few memory accesses and an optional strcpy. It is much cheaper than
> outputting a serial character.

The strcpy can be avoided for the 'bootstage' call (more info in another
post later)

>>
>> Can you please explain where your solution is better than this
>> approach, i. e. which problems can be addressed with your code where
>> the output timing method cannot be used, or where it is less
>> efficient?
>>
>
> With a little bit of cheating I can think of 10:
>
> 1. It doesn't need a serial watcher to be connected, which is not available
> in the field, and is something that anyway would only be attached when the
> engineer is not using the console for actually typing commands.
>
> 2. It is internal to the code, so as different code paths are taken it still
> has working timing, and doesn't rely on separate serial traffic parsing code
> to work out what happened
>
> 3. It still works with a silent console (we can either unmute the console
> and print the info, or pass it on to Linux for logging)
>
> 4. It is simpler to write and extend (just add a new bootstage call around
> any interesting section even if there is no serial output there)
>
> 5. It allows timing of things which don't result in serial output.
>
> 6. It times when the event actually happens rather than when a character
> makes its way through a UART FIFO. At worst the character might take a few
> ms to get through the FIFO which will skew timings.
>
> 7. It potentially allows two CPUs to run concurrently and log progress (no I
> am not working on that yet).

Not really a benefit for U-Boot as we don't run multi-cpu (we only
initialise additional CPUs)

> 8. We can log the information in the field, perhaps by passing it to Linux

Same as 3

> 9. There is only one code base to be changed when a boot path is adjusted.
>
> 10. It has higher resolution.
>

I think an 'boot profiling' API will be a useful thing to have

Regards,

Graeme