Accurate boot time measurement

include/bootstage.h new file +11 -0

+enum bootstage_id {
+	BOOTSTAGE_AWAKE,
+	BOOTSTAGE_START_UBOOT,
+	BOOTSTAGE_USB_START,
+	BOOTSTAGE_ETH_START,
+	BOOTSTAGE_BOOTP_START,
+	BOOTSTAGE_BOOTP_STOP,
+	BOOTSTAGE_KERNELREAD_START,
+	BOOTSTAGE_KERNELREAD_STOP,
+	BOOTSTAGE_BOOTM_START,
+	BOOTSTAGE_BOOTM_HANDOFF,

+static inline uint32_t bootstage_mark(enum bootstage_id id, const char *name) {}

include/common.h +1 -0

@@ -177,6 +177,14 @@ typedef void (interrupt_handler_t)(void *);
 #endif /* CONFIG_SERIAL_MULTI */
 
 /*
+ * Return the time since boot in microseconds, This is needed for

bootstage
+ * and should be defined in CPU- or board-specific code.
+ */
+unsigned long timer_get_us(void);

+

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.

To enable the feature, define CONFIG_BOOTSTAGE in your board config file. Also available is CONFIG_BOOTSTAGE_REPORT which will cause a report to be printed just before handing off to the OS.

Quoted 1 line · On Friday, May 13, 2011 16:51:59 Simon Glass wrote:

This defines the basics of a new boot time measurement feature. This

allows

Quoted 3 lines

logging of very accurate time measurements as the boot proceeds, by using an available microsecond counter.

Quoted 3 lines

To enable the feature, define CONFIG_BOOTSTAGE in your board config file. Also available is CONFIG_BOOTSTAGE_REPORT which will cause a report to be printed just before handing off to the OS.

this seems to overlap the existing show_boot_progress() code. any chance we
can look at these being merged ?
-mike

Quoted 6 lines · Mike Frysinger

Quoted 1 line · On Friday, May 13, 2011 16:51:59 Simon Glass wrote:

This defines the basics of a new boot time measurement feature. This

allows

Quoted 3 lines

logging of very accurate time measurements as the boot proceeds, by using an available microsecond counter.

Quoted 9 lines

Quoted 3 lines

To enable the feature, define CONFIG_BOOTSTAGE in your board config file. Also available is CONFIG_BOOTSTAGE_REPORT which will cause a report to be printed just before handing off to the OS.

this seems to overlap the existing show_boot_progress() code. any chance we
can look at these being merged ?
-mike

Hi Mike,

Yes I did look at this a few weeks ago. It would be a pretty invasive change. That code just uses a whole lot of numbers which presumably are approximately how far through the boot process we are. Bootstage is intended as a debugging tool for performance tune-up rather than a user display tool. I could imagine adding a table to bootstage with the progess number for each bootstage id, but then people are going to complain that the bootstage report is far to long and includes uninteresting things. I suppose I could fix that by including a flag as to whether to report each item or not...but it any case as you can see it is not a clear win.

If there is a strong appetite for that sort of patch I'm happy to do it.

Regards,
Simon

Couple of thoughts:
- Macro the definition of show_boot_progress() so it accepts a (const char *) argument if CONFIG_BOOTSTAGE is defined
- Change BOOTSTAGE_COUNT to CONFIG_MAX_BOOTSTAGE_RECORDS
- Any call to show_boot_progress() with a non-null second argument causes it to be logged in the next available bootstage record
- After the last bootstage record is filled, no further calls to show_boot_progress() cause logging to the bootstage records
- Instead of CONFIG_BOOTSTAGE_REPORT, create a command which dumps the contents of the bootstage records

No this is going to result in a big patch (every instance of show_boot_progress() will need to be touched to at least add NULL as the second parameter - Maintainers can add better text later ;)

If there is a strong appetite for that sort of patch I'm happy to do it.

Regards,

Graeme

Quoted 12 lines · Graeme Russ

Couple of thoughts:
?- Macro the definition of show_boot_progress() so it accepts a (const ? ?char *) argument if CONFIG_BOOTSTAGE is defined
?- Change BOOTSTAGE_COUNT to CONFIG_MAX_BOOTSTAGE_RECORDS
?- Any call to show_boot_progress() with a non-null second argument ? ?causes it to be logged in the next available bootstage record ?- After the last bootstage record is filled, no further calls to ? ?show_boot_progress() cause logging to the bootstage records ?- Instead of CONFIG_BOOTSTAGE_REPORT, create a command which dumps the ? ?contents of the bootstage records

Quoted 3 lines

No this is going to result in a big patch (every instance of show_boot_progress() will need to be touched to at least add NULL as the second parameter - Maintainers can add better text later ;)

Thanks for your thoughts. It can be done, but my bigger question is this:

Quoted 1 line

If there is a strong appetite for that sort of patch I'm happy to do it.

If I get some +ve responses then I will do it, otherwise I think I should assume people want this left as is.

I've thought of a 'better' approach:
- Do no modify the parameters of show_boot_progress()
- Create a new struct:

    struct boot_progress_msg {
      int boot_progress_id;
      const char *message;
    {

Dear Graeme Russ,

Quoted 8 lines · In message <[email protected]> you wrote:

I've thought of a 'better' approach:
? - Do no modify the parameters of show_boot_progress() ? - Create a new struct:
? ? struct boot_progress_msg {
? ? ? int boot_progress_id;
? ? ? const char *message;
? ? {

Where do you store this data _before_ relocation, when we have no access to RAM yet?

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.

Dear Simon Glass,

Quoted 1 line · In message <[email protected]> you wrote:

This defines the basics of a new boot time measurement feature. This

allows

Quoted 2 lines

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.

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.

- It is completely platform, SoC and board idependent - we do not need to provide any specific timer servcies etc. which are inherently platform-dependent.

- 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.

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?

Best regards,

Wolfgang Denk

--
DENX Software Engineering GmbH, MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: wd at denx.de "Oh dear, I think you'll find reality's on the blink again."
- Marvin The Paranoid Android

Quoted 8 lines · Wolfgang Denk

Dear Simon Glass,

Quoted 1 line · In message <[email protected]> you wrote:

This defines the basics of a new boot time measurement feature. This

allows

Quoted 2 lines

logging of very accurate time measurements as the boot proceeds, by using an available microsecond counter.

Quoted 6 lines

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.

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.

Quoted 7 lines

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.

Quoted 4 lines

- 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?

Quoted 4 lines

- 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.

Quoted 6 lines

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).

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

9. There is only one code base to be changed when a boot path is adjusted.

10. It has higher resolution.

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.

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

Dear Graeme Russ,

Quoted 4 lines · In message <[email protected]> you wrote:

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.

I think in the last 5 years I have seen but 2 devices using 9600 bps. All others appear to be using 115200 bps these days.

And even at 9600 we're still close to millisecond reolution...

Quoted 4 lines

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

time-stamping console output is not restricted to the serial port. ?It works as well with tty over USB, or netconsole, or even netconsole over USB.

Quoted 3 lines

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

If they have a console interface, then the output can be time-stamped.

Quoted 4 lines

time-stamping console output is not restricted to the serial port. It works as well with tty over USB, or netconsole, or even netconsole over USB.

My point is, if the device reboots in the field, you cannot recover the boot timing analysis as once it is streamed out it is gone forever

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.

Quoted 4 lines

- 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.

Quoted 3 lines

- 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?

Quoted 3 lines

- 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.

Quoted 3 lines

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).

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

9. There is only one code base to be changed when a boot path is adjusted.

10. It has higher resolution.

Dear Simon Glass,

Quoted 3 lines · In message <[email protected]> you wrote:

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

I don't see that we use any FIFOs in the output direction.

Quoted 3 lines

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.

Sorry, I cannot parse the "over in under 100 millisecond" part.

Quoted 9 lines

Quoted 4 lines

- 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.

Well, the "timing parser", as you callit, can be written in 10 lines or less of your scripting language of choice. ?See for example here for a solution in expect/tcl: ftp://ftp.denx.de/pub/tools/time_log We've been using this for about 10 years by now (see for example this 7 year old boot time analysis:
http://www.denx.de/wiki/DULG/AN2004_11_BootTimeOptimization).

As we can trivially use regular expressions, the effort to implement a "timing parser" can be ignored. And it is independet of what sort of boot device we are using.

You write: "We want a simple solution." ?I agree 100%.

Isn;t a 10 line script code solution that does not require ANY changes to the U-Boot code _much_ simpler than your approach?

This is why I was asking if your solution had any significant advantages.

Quoted 1 line

In our case the console is silent on boot, so this solution does not work.

Point taken. But, you need to output the timing information, don't you?

Quoted 2 lines

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

You must have one to rea the time logs, right?

Quoted 2 lines

that we track boot time. This means that it has to be done by the device itself.

Did you see cases where the boot time in the field differs from that in your lab? ?Can you please explain what is causing such differecnes?

Quoted 6 lines

Quoted 4 lines

- 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?

Don't you think so?

Will you provide the code to implement your solution for all currently supported BlackFin, ColdFire, MicroBlaze, MIPS, NIOS, PPC, SH, SPARC or x86 CPUs? ?Or even for all currently supported ARMN SoCs?

Quoted 6 lines

Quoted 3 lines

- 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

I think this can (and should) be fixed. It makes little sense to use a FIFO in the transmit direction in U-Boot.

Quoted 3 lines

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.

But you need storage for the timing events, and you don't have this before relocation. So you miss some really interesting parts of the boot procedure.

Quoted 6 lines

Quoted 3 lines

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:

Quoted 3 lines

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.

OK, not needing a console port during boot is indeed an advantage. ?It comes at the cost of needing log space, which is not available before relocation, so we miss some interesting parts of the boot procedure.

Quoted 3 lines

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

I don't consider this an advantage. ?On contrary.

Quoted 2 lines

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)

OK.

Quoted 2 lines

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)

This is plain wrong. ?Compare your implementation against the 10 lines of TCL code referenced above.

Quoted 1 line

5. It allows timing of things which don't result in serial output.

But to do so, you need to insert trace points. ?With the same effort we can insert a printf().

Quoted 3 lines

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.

Serial drivers are not supposed to use FIFOs in the tx direction.

Quoted 6 lines

7. It potentially allows two CPUs to run concurrently and log progress (no I am not working on that yet).

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

9. There is only one code base to be changed when a boot path is adjusted.

...which is a disadvantage, because with the externat tool nothing needs to be changed at all.

Quoted 1 line

10. It has higher resolution.

OK.

I understand your position, and I too see some advantages of your implementation. ?But I see also disadvantages, especially it being a pretty much intrusive change to large areas of the code, and being available for a single platform only. ?Also, I see it as a disadvantage that you lose pre-relocation information.

So far, I am not convinced that the result is worth the effort.

Quoted 4 lines

As we can trivially use regular expressions, the effort to implement a "timing parser" can be ignored. And it is independet of what sort of boot device we are using.

Fine if your running Linux - What if the only tool tyou have is Hyperterminal?

I've seen many instances where everything works well 'in the lab' and as soon as you put it in the field, things go pear shaped. Often you need to

Quoted 3 lines

But you need storage for the timing events, and you don't have this before relocation. So you miss some really interesting parts of the boot procedure.

Maybe a limited amount can be stored in global data by testing the relocated flag

Quoted 3 lines

OK, not needing a console port during boot is indeed an advantage. It comes at the cost of needing log space, which is not available before relocation, so we miss some interesting parts of the boot procedure.

Can use global data for a limited number of pre-relocation records. And I don't think pre-location is where a lot of problems will occur anyway unless you have flaky/misconfigured hardware

Quoted 4 lines

Quoted 1 line

5. It allows timing of things which don't result in serial output.

But to do so, you need to insert trace points. With the same effort we can insert a printf().

Which increase code/data size - If you don't care about having pretty messages in you boot profile (you can always look up source or documentation) the size impact per 'mark' is less

I think my refined suggestion has a far smaller impact than first thought and you can get pre-relocation information if you are willing to use some global data storage

Dear Graeme Russ,

Quoted 1 line · In message <[email protected]> you wrote:

Quoted 6 lines

Quoted 3 lines

As we can trivially use regular expressions, the effort to implement a "timing parser" can be ignored. And it is independet of what sort of boot device we are using.

Fine if your running Linux - What if the only tool tyou have is Hyperterminal?

AFAICT tcl is also available under Windoze...

What makes you think a call to printf()/puts()/putc() would increase the code size worse than a call to the trace function? If I don't care about pretty messages (and use silent console otherwise) my serial console based messages consist of a plain "putc('a')" or similar - certainly not more overhead than the call to the trace function.

It's not about willing or not. If willing or wanting would help, we had an ideal world. But in reality, we have a world full of restrictions.

GD is definitely not buffer space for arbitrary amounts of log data.

Dear Graeme Russ,

Quoted 7 lines · In message <[email protected]> you wrote:

Quoted 4 lines

As we can trivially use regular expressions, the effort to implement a "timing parser" can be ignored. And it is independet of what sort of boot device we are using.

Fine if your running Linux - What if the only tool tyou have is Hyperterminal?

AFAICT tcl is also available under Windoze...

Quoted 2 lines

I've seen many instances where everything works well 'in the lab' and as soon as you put it in the field, things go pear shaped. Often you need to

We all have seen this, and we all appreciate any tool that is available then.

Quoted 6 lines

Quoted 3 lines

But you need storage for the timing events, and you don't have this before relocation. So you miss some really interesting parts of the boot procedure.

Maybe a limited amount can be stored in global data by testing the relocated flag

I don't think so.

Quoted 7 lines

Quoted 3 lines

OK, not needing a console port during boot is indeed an advantage. ?It comes at the cost of needing log space, which is not available before relocation, so we miss some interesting parts of the boot procedure.

Can use global data for a limited number of pre-relocation records. And I don't think pre-location is where a lot of problems will occur anyway unless you have flaky/misconfigured ?hardware

I smell a bloated implementation which works on one specific system or two. ?This doesn't sound attractive to me.

Quoted 8 lines

Quoted 4 lines

Quoted 1 line

5. It allows timing of things which don't result in serial output.

But to do so, you need to insert trace points. ?With the same effort we can insert a printf().

Which increase code/data size - If you don't care about having pretty messages in you boot profile (you can always look up source or documentation) the size impact per 'mark' is less

What makes you think a call to printf()/puts()/putc() would increase the code size worse than a call to the trace function? If I don't care about pretty messages (and use silent console otherwise) my serial console based messages consist of a plain "putc('a')" or similar - certainly not more overhead than the call to the trace function.

Quoted 3 lines

I think my refined suggestion has a far smaller impact than first thought and you can get pre-relocation information if you are willing to use some global data storage

It's not about willing or not. ?If willing or wanting would help, we had an ideal world. ?But in reality, we have a world full of restrictions.

GD is definitely not buffer space for arbitrary amounts of log data.

-----Original Message-----
From: u-boot-bounces at lists.denx.de [mailto:u-boot-bounces at lists.denx.de] On Behalf Of Graeme Russ
Sent: Monday, May 16, 2011 11:54 AM
To: Wolfgang Denk
Cc: U-Boot Mailing List; Simon Schwarz
Subject: Re: [U-Boot] [PATCH 0/4] Accurate boot time measurement

Quoted 2 lines · Wolfgang Denk

Dear Simon Glass,

Quoted 4 lines

Well, the "timing parser", as you callit, can be written in 10 lines or less of your scripting language of choice. ?See for example here for a solution in expect/tcl: ftp://ftp.denx.de/pub/tools/time_log We've been using this for about 10 years by now (see for

example this

Quoted 3 lines

7 year old boot time analysis:
http://www.denx.de/wiki/DULG/AN2004_11_BootTimeOptimization).

Quoted 1 line

As we can trivially use regular expressions, the effort to

implement a

Quoted 3 lines

"timing parser" can be ignored. And it is independet of what sort of boot device we are using.

Fine if your running Linux - What if the only tool tyou have is Hyperterminal?

Dear Simon Glass,

Quoted 2 lines · In message <[email protected]> you wrote:

This is 100us which is pretty good although you are assuming that there

is

Quoted 1 line

no FIFO holding things. Also on modern ARM CPUs the 'processing' part of

I don't see that we use any FIFOs in the output direction.

Quoted 4 lines

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.

Sorry, I cannot parse the "over in under 100 millisecond" part.

Quoted 7 lines

Quoted 4 lines

- 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,

Quoted 1 line

USB boot, MMC boot, SD boot, etc.)? We have a lot of boot paths,

different

Quoted 1 line

architectures, etc. We want a simple solution.

Well, the "timing parser", as you callit, can be written in 10 lines or less of your scripting language of choice. See for example here for a solution in expect/tcl: ftp://ftp.denx.de/pub/tools/time_log We've been using this for about 10 years by now (see for example this 7 year old boot time analysis:
http://www.denx.de/wiki/DULG/AN2004_11_BootTimeOptimization).

As we can trivially use regular expressions, the effort to implement a "timing parser" can be ignored. And it is independet of what sort of boot device we are using.

You write: "We want a simple solution." I agree 100%.

Isn;t a 10 line script code solution that does not require ANY changes to the U-Boot code _much_ simpler than your approach?

This is why I was asking if your solution had any significant advantages.

Quoted 2 lines

In our case the console is silent on boot, so this solution does not

work.

Point taken. But, you need to output the timing information, don't you?

Quoted 3 lines

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

You must have one to rea the time logs, right?

Quoted 3 lines

that we track boot time. This means that it has to be done by the device itself.

Did you see cases where the boot time in the field differs from that in your lab? Can you please explain what is causing such differecnes?

Quoted 4 lines

Quoted 3 lines

- It is completely platform, SoC and board idependent - we do not need to provide any specific timer servcies etc. which are inherently platform-dependent.

Quoted 1 line

Is this really an advantage?

Don't you think so?

Will you provide the code to implement your solution for all currently supported BlackFin, ColdFire, MicroBlaze, MIPS, NIOS, PPC, SH, SPARC or x86 CPUs? Or even for all currently supported ARMN SoCs?

Quoted 3 lines

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

I think this can (and should) be fixed. It makes little sense to use a FIFO in the transmit direction in U-Boot.

Quoted 2 lines

what is happening. The overhead of bootstage is a function call, a

readl(),

Quoted 2 lines

a a few memory accesses and an optional strcpy. It is much cheaper than outputting a serial character.

But you need storage for the timing events, and you don't have this before relocation. So you miss some really interesting parts of the boot procedure.

Quoted 8 lines

Quoted 4 lines

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

Quoted 1 line

in the field, and is something that anyway would only be attached when

the

Quoted 1 line

engineer is not using the console for actually typing commands.

OK, not needing a console port during boot is indeed an advantage. It comes at the cost of needing log space, which is not available before relocation, so we miss some interesting parts of the boot procedure.

Quoted 2 lines

2. It is internal to the code, so as different code paths are taken it

still

Quoted 1 line

has working timing, and doesn't rely on separate serial traffic parsing

code

Quoted 1 line

to work out what happened

I don't consider this an advantage. On contrary.

4. It is simpler to write and extend (just add a new bootstage call around

Quoted 1 line

any interesting section even if there is no serial output there)

This is plain wrong. Compare your implementation against the 10 lines of TCL code referenced above.

Quoted 1 line

5. It allows timing of things which don't result in serial output.

But to do so, you need to insert trace points. With the same effort we can insert a printf().

Quoted 3 lines

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

Quoted 1 line

ms to get through the FIFO which will skew timings.

Serial drivers are not supposed to use FIFOs in the tx direction.

Quoted 2 lines

9. There is only one code base to be changed when a boot path is

adjusted.

...which is a disadvantage, because with the externat tool nothing needs to be changed at all.

I understand your position, and I too see some advantages of your implementation. But I see also disadvantages, especially it being a pretty much intrusive change to large areas of the code, and being available for a single platform only. Also, I see it as a disadvantage that you lose pre-relocation information.

So far, I am not convinced that the result is worth the effort.

Best regards,

Wolfgang Denk

--
DENX Software Engineering GmbH, MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: wd at denx.de Syntactic sugar causes cancer of the semicolon.
- Epigrams in Programming, ACM SIGPLAN Sept. 1982

Such a lot of text about such a small patch. It is clear to me that you are used to doing things one way, and this is a different approach. As I said

Quoted 1 line

I don't see that we use any FIFOs in the output direction.

Yes we do, and in fact they do improve boot performance slightly when the console is muted.

I agree it is unfortunate to have features which require platform-specific features. Perhaps we should define a microsecond timer as a requirement of a U-Boot port? Or perhaps an option which opens up new features?

Quoted 3 lines

But you need storage for the timing events, and you don't have this before relocation. So you miss some really interesting parts of the boot procedure.

It is easy enough to get storage if we want it - you can maintain a pre-reloc table which is copied over afterwards. I notice that some

I believe it compares favourably. It has a more friendly display, doesn't require a serial port, is more accurate, can run self-hosted, etc. With the TCL script you need to add a new line before you will get a new time.

Quoted 2 lines

But to do so, you need to insert trace points. With the same effort we can insert a printf().

Fair enough. If you have your heart set on the TCL script I'm really not going to get very far!

In terms of all this discussion I can see your point :-) I did have expressions of interest from two people including one I thought was at your company, which I why I went to the effort to clean up and submit this. At that time I didn't realise it would be such a touchy subject.

But if you really don't want this in U-Boot then please accept my apologies for wasting so much time on the list.

Dear Simon Glass,
...

Quoted 2 lines

Yes we do, and in fact they do improve boot performance slightly when the console is muted.

Do you have an explanation how that works? ?When there is no output on the console, the use of a FIFO in tx direction should not matter at all?

Quoted 4 lines

I agree it is unfortunate to have features which require platform-specific features. Perhaps we should define a microsecond timer as a requirement of a U-Boot port? Or perhaps an option which opens up new features?

We already have that, or better. ?The problem is that it depends on the architecture.

On PPC systems for example you always have the time base, a 64 bit counter which is clocked with something like 1/4 or 1/16 of the CPU clock.

And whe have the timer that gettime() is based on - which is in milliseocnd resolution (hence the demand that CONFIG_SYS_HZ must always be defined as 1000).

The problem comes with the multitude of different architectures and SoCs we support - there is no concept of timebase registers on ARM, on some systems we need interrupts to implement timer services so these are available only after relocation, etc.

Quoted 5 lines

Quoted 4 lines

But you need storage for the timing events, and you don't have this before relocation. So you miss some really interesting parts of the boot procedure.

Quoted 2 lines

It is easy enough to get storage if we want it - you can maintain a pre-reloc table which is copied over afterwards. I notice that some

Where will you store this "pre-reloc" table? ?Yes, there are some systems with plenty of on-chip-memory or huge caches that can beused for this. ?But there are also systems where we barely can find the room for the most vital global data before relocation.

Even worse - if you take this seriously, you will probably also get timing information from early boot stages, like how long it's taking to load the U-Boot image from NAND - but on some systems this loader code has to fit in as little as 2 KiB.

Quoted 4 lines

I believe it compares favourably. It has a more friendly display, doesn't require a serial port, is more accurate, can run self-hosted, etc. With the TCL script you need to add a new line before you will get a new time.

Well, the display format is trivial to adapt, as well as the trigger criteria. Keep in mind that this is just an example script that covers the most common use case we've seen so far.

Quoted 6 lines

Quoted 3 lines

But to do so, you need to insert trace points. ?With the same effort we can insert a printf().

Fair enough. If you have your heart set on the TCL script I'm really not going to get very far!

I haven't my heart set on it. ?It is just one example of solutions which cover a large percentage of the potential use cases. ?I am trying to understand the ration of advanatges versus effort, that's all.

Quoted 5 lines

In terms of all this discussion I can see your point :-) I did have expressions of interest from two people including one I thought was at your company, which I why I went to the effort to clean up and submit this. At that time I didn't realise it would be such a touchy subject.

Where is the problem? ?If you are convinced of you idea you should be ready to defend it. ?If you are not, it's not wort it at all. ?And if you see a voting result of 2:1 pro this is pretty good, isn't it?

Quoted 3 lines

But if you really don't want this in U-Boot then please accept my apologies for wasting so much time on the list.

I don't consider this discussion a waste of time. I hope you don't do, either.

Best regards,

Wolfgang Denk

--
DENX Software Engineering GmbH, ? ? MD: Wolfgang Denk & Detlev Zundel HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: wd at denx.de Life would be so much easier if we could ?just ?look ?at ?the ?source code. ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? -- Dave Olson

In terms of all this discussion I can see your point :-) I did have expressions of interest from two people including one I thought was at your company, which I why I went to the effort to clean up and submit this. At that time I didn't realise it would be such a touchy subject.

Hi Simon and Wolfgang,

[...]

Quoted 4 lines

In terms of all this discussion I can see your point :-) I did have expressions of interest from two people including one I thought was at your company, which I why I went to the effort to clean up and submit this. At that time I didn't realise it would be such a touchy subject.

I don't believe this topic to be touchy, it's just that Wolfgang trying to keep the whole code base in shape has a healthy inertia before introducing changes that may be difficult to keep consistent over the multitude of SoCs that we support.

To throw in my personal view again, I still would like to see such an infrastructure to get into U-Boot code. ?I fully agree with Wolfgang that practically the printfs and timing are a method already in place to do measurements. ?On the other hand my experience has shown that for some reason or other this has never been widely used. ?So effectively, it wasn't too helpful for the project itself.

So I still believe that if we _had_ an infrastructure like you propose, we would get more people interested in _actually_ measuring and improving the code base, which would certainly be a good thing.

Of course we have systems that are very limited in their ressources, but this is the reason why many features of U-Boot are opt-in features not forcing any resource usage on such boards. ?So if some of them are so short on resources that they cannot use such a timing framework, then so be it. ?But as most of the probably are in the legacy code base, they should not stop us from getting getting positive effects for the currently important boards and architectures.

Cheers
?Detlev

--
A change in language can transform our appreciation of the cosmos ? ? ? ? ? ? ? ? ? ? ? -- Benjamin Lee Whorf
--
DENX Software Engineering GmbH, ? ? ?MD: Wolfgang Denk & Detlev Zundel HRB 165235 Munich, ?Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-40 Fax: (+49)-8142-66989-80 Email: dzu at denx.de

Hi Detlev and Wolfgang,

Thanks for your comments. I understand a little bit of healthy inertia and do appreciate the constraints.

I believe I have covered this ground very thoroughly and would like advice please on what to do next. The options I can see are:

- change the code to use a fallback when a microsecond timer is not available
- integrate with boot progress
- something else? drop it?

I believe I have covered this ground very thoroughly and would like advice please on what to do next. The options I can see are:

- change the code to use a fallback when a microsecond timer is not available

- integrate with boot progress

- something else? drop it?

Hi Simon,

[...]

Quoted 2 lines

I believe I have covered this ground very thoroughly and would like advice please on what to do next. The options I can see are:

As Graeme points out, you got enough positive feedback that I encourage you to continue and address the comments.

Quoted 3 lines

- change the code to use a fallback when a microsecond timer is not available

Excuse me for not diving into that too deep, but from my top-level overview, it would seem like a good idea that if an architecture _has_ a microsecond timer, it could use generic code to massage that into the HZ=1000 API that we currently use with the addition of offering the extended precision. ?Your code then would need such a fallback and could work with the best precision offered by the architecture. ?New architectures with microsecond timers would need to only implement the new microsecond timer infrastructure and be done with it.

Quoted 1 line

- integrate with boot progress

The current boot progress to me seems pretty ugly and could do with a make-over. ?So if it is possible to merge those two logical functions, we would have a win-win situation.

Quoted 2 lines

- something else? drop it?

No, please don't - I think you created enough interest to carry on.

Cheers
?Detlev

--
Perfecting oneself is as much unlearning as it is learning.
? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?-- Edsger Dijkstra
--
DENX Software Engineering GmbH, ? ? ?MD: Wolfgang Denk & Detlev Zundel HRB 165235 Munich, ?Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-40 Fax: (+49)-8142-66989-80 Email: dzu at denx.de

Quoted 9 lines · Detlev Zundel

Hi Simon,

[...]

Quoted 2 lines

I believe I have covered this ground very thoroughly and would like advice please on what to do next. The options I can see are:

As Graeme points out, you got enough positive feedback that I encourage you to continue and address the comments.

OK, it would be nice to have a note from Wolfgang since without his OK it won't make it in, right?

Quoted 4 lines

Quoted 3 lines

- change the code to use a fallback when a microsecond timer is not available

Quoted 8 lines

Excuse me for not diving into that too deep, but from my top-level overview, it would seem like a good idea that if an architecture _has_ a microsecond timer, it could use generic code to massage that into the HZ=1000 API that we currently use with the addition of offering the extended precision. ?Your code then would need such a fallback and could work with the best precision offered by the architecture. ?New architectures with microsecond timers would need to only implement the new microsecond timer infrastructure and be done with it.

Yes I suggested that a few emails ago but didn't get a response.

Quoted 5 lines

Quoted 1 line

- integrate with boot progress

The current boot progress to me seems pretty ugly and could do with a make-over. ?So if it is possible to merge those two logical functions, we would have a win-win situation.

OK fair enough. I will do this if there is agreement that this type of boot timing is worth having.

Anyway, my point is, if the timer API wasa fixed, all the boot logging API needs to do is call get_timer() and your done - instant millisecond

timestamp - No fallbacks - Each arch just needs to implement get_timer() correctly

Quoted 5 lines

Quoted 2 lines

I believe I have covered this ground very thoroughly and would like advice please on what to do next. The options I can see are:

As Graeme points out, you got enough positive feedback that I encourage you to continue and address the comments.

OK, it would be nice to have a note from Wolfgang since without his OK it won't make it in, right?

Quoted 6 lines

Quoted 5 lines

Quoted 3 lines

I believe I have covered this ground very thoroughly and would like

advice please on what to do next. The options I can see are:

As Graeme points out, you got enough positive feedback that I encourage you to continue and address the comments.

Quoted 2 lines

OK, it would be nice to have a note from Wolfgang since without his OK it won't make it in, right?

Ultimately we are a democratic community, so when you get enough support the changes will go in. Usually we find a consensus acceptable to all parties before resorting to such formal measures however.

Ultimately, Wolfgang gets final word regardless of anything else.

Quoted 1 line · Mike Frysinger

Ultimately, Wolfgang gets final word regardless of anything else.

Do I? That's news for me.

What prevents you to continue this project as you like if I should decide something that appears to be unacceptable to the community?

Quoted 3 lines

What prevents you to continue this project as you like if I should decide something that appears to be unacceptable to the community?

yours will be "Das U-Boot" while mine will be an uppity fork

doesnt denx also own the trademark on "Das U-Boot" as applied to low level boot loaders ?