Convert README.trace to reStructured text and move it to develop/trace.rst.
Signed-off-by: Heinrich Schuchardt <xypron.g...@gmx.de> --- doc/README.trace | 346 ---------------------------------------- doc/develop/index.rst | 1 + doc/develop/trace.rst | 355 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 356 insertions(+), 346 deletions(-) delete mode 100644 doc/README.trace create mode 100644 doc/develop/trace.rst diff --git a/doc/README.trace b/doc/README.trace deleted file mode 100644 index 2e7ca3319a..0000000000 --- a/doc/README.trace +++ /dev/null @@ -1,346 +0,0 @@ -# SPDX-License-Identifier: GPL-2.0+ -# -# Copyright (c) 2013 The Chromium OS Authors. - -Tracing in U-Boot -================= - -U-Boot supports a simple tracing feature which allows a record of excecution -to be collected and sent to a host machine for analysis. At present the -main use for this is to profile boot time. - - -Overview --------- - -The trace feature uses GCC's instrument-functions feature to trace all -function entry/exit points. These are then recorded in a memory buffer. -The memory buffer can be saved to the host over a network link using -tftpput or by writing to an attached memory device such as MMC. - -On the host, the file is first converted with a tool called 'proftool', -which extracts useful information from it. The resulting trace output -resembles that emitted by Linux's ftrace feature, so can be visually -displayed by pytimechart. - - -Quick-start using Sandbox -------------------------- - -Sandbox is a build of U-Boot that can run under Linux so it is a convenient -way of trying out tracing before you use it on your actual board. To do -this, follow these steps: - -Add the following to include/configs/sandbox.h (if not already there) - -#define CONFIG_TRACE -#define CONFIG_CMD_TRACE -#define CONFIG_TRACE_BUFFER_SIZE (16 << 20) -#define CONFIG_TRACE_EARLY_SIZE (8 << 20) -#define CONFIG_TRACE_EARLY -#define CONFIG_TRACE_EARLY_ADDR 0x00100000 - -Build sandbox U-Boot with tracing enabled: - -$ make FTRACE=1 O=sandbox sandbox_config -$ make FTRACE=1 O=sandbox - -Run sandbox, wait for a bit of trace information to appear, and then capture -a trace: - -$ ./sandbox/u-boot - - -U-Boot 2013.04-rc2-00100-ga72fcef (Apr 17 2013 - 19:25:24) - -DRAM: 128 MiB -trace: enabled -Using default environment - -In: serial -Out: serial -Err: serial -=>trace stats - 671,406 function sites - 69,712 function calls - 0 untracked function calls - 73,373 traced function calls - 16 maximum observed call depth - 15 call depth limit - 66,491 calls not traced due to depth -=>trace stats - 671,406 function sites - 1,279,450 function calls - 0 untracked function calls - 950,490 traced function calls (333217 dropped due to overflow) - 16 maximum observed call depth - 15 call depth limit - 1,275,767 calls not traced due to depth -=>trace calls 0 e00000 -Call list dumped to 00000000, size 0xae0a40 -=>print -baudrate=115200 -profbase=0 -profoffset=ae0a40 -profsize=e00000 -stderr=serial -stdin=serial -stdout=serial - -Environment size: 117/8188 bytes -=>host save host 0 trace 0 ${profoffset} -11405888 bytes written in 10 ms (1.1 GiB/s) -=>reset - - -Then run proftool to convert the trace information to ftrace format. - -$ ./sandbox/tools/proftool -m sandbox/System.map -p trace dump-ftrace >trace.txt - -Finally run pytimechart to display it: - -$ pytimechart trace.txt - -Using this tool you can zoom and pan across the trace, with the function -calls on the left and little marks representing the start and end of each -function. - - -CONFIG Options --------------- - -- CONFIG_TRACE - Enables the trace feature in U-Boot. - -- CONFIG_CMD_TRACE - Enables the trace command. - -- CONFIG_TRACE_BUFFER_SIZE - Size of trace buffer to allocate for U-Boot. This buffer is - used after relocation, as a place to put function tracing - information. The address of the buffer is determined by - the relocation code. - -- CONFIG_TRACE_EARLY - Define this to start tracing early, before relocation. - -- CONFIG_TRACE_EARLY_SIZE - Size of 'early' trace buffer. Before U-Boot has relocated - it doesn't have a proper trace buffer. On many boards - you can define an area of memory to use for the trace - buffer until the 'real' trace buffer is available after - relocation. The contents of this buffer are then copied to - the real buffer. - -- CONFIG_TRACE_EARLY_ADDR - Address of early trace buffer - - -Building U-Boot with Tracing Enabled ------------------------------------- - -Pass 'FTRACE=1' to the U-Boot Makefile to actually instrument the code. -This is kept as a separate option so that it is easy to enable/disable -instrumenting from the command line instead of having to change board -config files. - - -Collecting Trace Data ---------------------- - -When you run U-Boot on your board it will collect trace data up to the -limit of the trace buffer size you have specified. Once that is exhausted -no more data will be collected. - -Collecting trace data has an affect on execution time/performance. You -will notice this particularly with trvial functions - the overhead of -recording their execution may even exceed their normal execution time. -In practice this doesn't matter much so long as you are aware of the -effect. Once you have done your optimisations, turn off tracing before -doing end-to-end timing. - -The best time to start tracing is right at the beginning of U-Boot. The -best time to stop tracing is right at the end. In practice it is hard -to achieve these ideals. - -This implementation enables tracing early in board_init_f(). This means -that it captures most of the board init process, missing only the -early architecture-specific init. However, it also misses the entire -SPL stage if there is one. - -U-Boot typically ends with a 'bootm' command which loads and runs an -OS. There is useful trace data in the execution of that bootm -command. Therefore this implementation provides a way to collect trace -data after bootm has finished processing, but just before it jumps to -the OS. In practical terms, U-Boot runs the 'fakegocmd' environment -variable at this point. This variable should have a short script which -collects the trace data and writes it somewhere. - -Trace data collection relies on a microsecond timer, accesed through -timer_get_us(). So the first think you should do is make sure that -this produces sensible results for your board. Suitable sources for -this timer include high resolution timers, PWMs or profile timers if -available. Most modern SOCs have a suitable timer for this. Make sure -that you mark this timer (and anything it calls) with -__attribute__((no_instrument_function)) so that the trace library can -use it without causing an infinite loop. - - -Commands --------- - -The trace command has variable sub-commands: - -- stats - Display tracing statistics - -- pause - Pause tracing - -- resume - Resume tracing - -- funclist [<addr> <size>] - Dump a list of functions into the buffer - -- calls [<addr> <size>] - Dump function call trace into buffer - -If the address and size are not given, these are obtained from environment -variables (see below). In any case the environment variables are updated -after the command runs. - - -Environment Variables ---------------------- - -The following are used: - -- profbase - Base address of trace output buffer - -- profoffset - Offset of first unwritten byte in trace output buffer - -- profsize - Size of trace output buffer - -All of these are set by the 'trace calls' command. - -These variables keep track of the amount of data written to the trace -output buffer by the 'trace' command. The trace commands which write data -to the output buffer can use these to specify the buffer to write to, and -update profoffset each time. This allows successive commands to append data -to the same buffer, for example: - - trace funclist 10000 e00000 - trace calls - -(the latter command appends more data to the buffer). - - -- fakegocmd - Specifies commands to run just before booting the OS. This - is a useful time to write the trace data to the host for - processing. - - -Writing Out Trace Data ----------------------- - -Once the trace data is in an output buffer in memory there are various ways -to transmit it to the host. Notably you can use tftput to send the data -over a network link: - -fakegocmd=trace pause; usb start; set autoload n; bootp; - trace calls 10000000 1000000; - tftpput ${profbase} ${profoffset} 192.168.1.4:/tftpboot/calls - -This starts up USB (to talk to an attached USB Ethernet dongle), writes -a trace log to address 10000000 and sends it to a host machine using -TFTP. After this, U-Boot will boot the OS normally, albeit a little -later. - - -Converting Trace Output Data ----------------------------- - -The trace output data is kept in a binary format which is not documented -here. To convert it into something useful, you can use proftool. - -This tool must be given the U-Boot map file and the trace data received -from running that U-Boot. It produces a text output file. - -Options - -m <map_file> - Specify U-Boot map file - - -p <trace_file> - Specifiy profile/trace file - -Commands: - -- dump-ftrace - Write a text dump of the file in Linux ftrace format to stdout - - -Viewing the Trace Data ----------------------- - -You can use pytimechart for this (sudo apt-get pytimechart might work on -your Debian-style machine, and use your favourite search engine to obtain -documentation). It expects the file to have a .txt extension. The program -has terse user interface but is very convenient for viewing U-Boot -profile information. - - -Workflow Suggestions --------------------- - -The following suggestions may be helpful if you are trying to reduce boot -time: - -1. Enable CONFIG_BOOTSTAGE and CONFIG_BOOTSTAGE_REPORT. This should get -you are helpful overall snapshot of the boot time. - -2. Build U-Boot with tracing and run it. Note the difference in boot time -(it is common for tracing to add 10% to the time) - -3. Collect the trace information as descibed above. Use this to find where -all the time is being spent. - -4. Take a look at that code and see if you can optimise it. Perhaps it is -possible to speed up the initialisation of a device, or remove an unused -feature. - -5. Rebuild, run and collect again. Compare your results. - -6. Keep going until you run out of steam, or your boot is fast enough. - - -Configuring Trace ------------------ - -There are a few parameters in the code that you may want to consider. -There is a function call depth limit (set to 15 by default). When the -stack depth goes above this then no tracing information is recorded. -The maximum depth reached is recorded and displayed by the 'trace stats' -command. - - -Future Work ------------ - -Tracing could be a little tidier in some areas, for example providing -run-time configuration options for trace. - -Some other features that might be useful: - -- Trace filter to select which functions are recorded -- Sample-based profiling using a timer interrupt -- Better control over trace depth -- Compression of trace information - - -Simon Glass <s...@chromium.org> -April 2013 diff --git a/doc/develop/index.rst b/doc/develop/index.rst index c95a8d6b12..0a7e204b34 100644 --- a/doc/develop/index.rst +++ b/doc/develop/index.rst @@ -12,3 +12,4 @@ Develop U-Boot crash_dumps global_data logging + trace diff --git a/doc/develop/trace.rst b/doc/develop/trace.rst new file mode 100644 index 0000000000..7776c48428 --- /dev/null +++ b/doc/develop/trace.rst @@ -0,0 +1,355 @@ +.. SPDX-License-Identifier: GPL-2.0+ +.. Copyright (c) 2013 The Chromium OS Authors. + +Tracing in U-Boot +================= + +U-Boot supports a simple tracing feature which allows a record of excecution +to be collected and sent to a host machine for analysis. At present the +main use for this is to profile boot time. + + +Overview +-------- + +The trace feature uses GCC's instrument-functions feature to trace all +function entry/exit points. These are then recorded in a memory buffer. +The memory buffer can be saved to the host over a network link using +tftpput or by writing to an attached memory device such as MMC. + +On the host, the file is first converted with a tool called 'proftool', +which extracts useful information from it. The resulting trace output +resembles that emitted by Linux's ftrace feature, so can be visually +displayed by pytimechart. + + +Quick-start using Sandbox +------------------------- + +Sandbox is a build of U-Boot that can run under Linux so it is a convenient +way of trying out tracing before you use it on your actual board. To do +this, follow these steps: + +Add the following to include/configs/sandbox.h (if not already there) + +.. code-block:: c + + #define CONFIG_TRACE + #define CONFIG_CMD_TRACE + #define CONFIG_TRACE_BUFFER_SIZE (16 << 20) + #define CONFIG_TRACE_EARLY_SIZE (8 << 20) + #define CONFIG_TRACE_EARLY + #define CONFIG_TRACE_EARLY_ADDR 0x00100000 + +Build sandbox U-Boot with tracing enabled: + +.. code-block:: console + + $ make FTRACE=1 O=sandbox sandbox_config + $ make FTRACE=1 O=sandbox + +Run sandbox, wait for a bit of trace information to appear, and then capture +a trace: + +.. code-block:: console + + $ ./sandbox/u-boot + + U-Boot 2013.04-rc2-00100-ga72fcef (Apr 17 2013 - 19:25:24) + + DRAM: 128 MiB + trace: enabled + Using default environment + + In: serial + Out: serial + Err: serial + =>trace stats + 671,406 function sites + 69,712 function calls + 0 untracked function calls + 73,373 traced function calls + 16 maximum observed call depth + 15 call depth limit + 66,491 calls not traced due to depth + =>trace stats + 671,406 function sites + 1,279,450 function calls + 0 untracked function calls + 950,490 traced function calls (333217 dropped due to overflow) + 16 maximum observed call depth + 15 call depth limit + 1,275,767 calls not traced due to depth + =>trace calls 0 e00000 + Call list dumped to 00000000, size 0xae0a40 + =>print + baudrate=115200 + profbase=0 + profoffset=ae0a40 + profsize=e00000 + stderr=serial + stdin=serial + stdout=serial + + Environment size: 117/8188 bytes + =>host save host 0 trace 0 ${profoffset} + 11405888 bytes written in 10 ms (1.1 GiB/s) + =>reset + + +Then run proftool to convert the trace information to ftrace format + +.. code-block:: console + + $ ./sandbox/tools/proftool -m sandbox/System.map -p trace dump-ftrace >trace.txt + +Finally run pytimechart to display it + +.. code-block:: console + + $ pytimechart trace.txt + +Using this tool you can zoom and pan across the trace, with the function +calls on the left and little marks representing the start and end of each +function. + + +CONFIG Options +-------------- + +CONFIG_TRACE + Enables the trace feature in U-Boot. + +CONFIG_CMD_TRACE + Enables the trace command. + +CONFIG_TRACE_BUFFER_SIZE + Size of trace buffer to allocate for U-Boot. This buffer is + used after relocation, as a place to put function tracing + information. The address of the buffer is determined by + the relocation code. + +CONFIG_TRACE_EARLY + Define this to start tracing early, before relocation. + +CONFIG_TRACE_EARLY_SIZE + Size of 'early' trace buffer. Before U-Boot has relocated + it doesn't have a proper trace buffer. On many boards + you can define an area of memory to use for the trace + buffer until the 'real' trace buffer is available after + relocation. The contents of this buffer are then copied to + the real buffer. + +CONFIG_TRACE_EARLY_ADDR + Address of early trace buffer + + +Building U-Boot with Tracing Enabled +------------------------------------ + +Pass 'FTRACE=1' to the U-Boot Makefile to actually instrument the code. +This is kept as a separate option so that it is easy to enable/disable +instrumenting from the command line instead of having to change board +config files. + + +Collecting Trace Data +--------------------- + +When you run U-Boot on your board it will collect trace data up to the +limit of the trace buffer size you have specified. Once that is exhausted +no more data will be collected. + +Collecting trace data has an affect on execution time/performance. You +will notice this particularly with trvial functions - the overhead of +recording their execution may even exceed their normal execution time. +In practice this doesn't matter much so long as you are aware of the +effect. Once you have done your optimisations, turn off tracing before +doing end-to-end timing. + +The best time to start tracing is right at the beginning of U-Boot. The +best time to stop tracing is right at the end. In practice it is hard +to achieve these ideals. + +This implementation enables tracing early in board_init_f(). This means +that it captures most of the board init process, missing only the +early architecture-specific init. However, it also misses the entire +SPL stage if there is one. + +U-Boot typically ends with a 'bootm' command which loads and runs an +OS. There is useful trace data in the execution of that bootm +command. Therefore this implementation provides a way to collect trace +data after bootm has finished processing, but just before it jumps to +the OS. In practical terms, U-Boot runs the 'fakegocmd' environment +variable at this point. This variable should have a short script which +collects the trace data and writes it somewhere. + +Trace data collection relies on a microsecond timer, accesed through +timer_get_us(). So the first think you should do is make sure that +this produces sensible results for your board. Suitable sources for +this timer include high resolution timers, PWMs or profile timers if +available. Most modern SOCs have a suitable timer for this. Make sure +that you mark this timer (and anything it calls) with +__attribute__((no_instrument_function)) so that the trace library can +use it without causing an infinite loop. + + +Commands +-------- + +The trace command has variable sub-commands: + +stats + Display tracing statistics + +pause + Pause tracing + +resume + Resume tracing + +funclist [<addr> <size>] + Dump a list of functions into the buffer + +calls [<addr> <size>] + Dump function call trace into buffer + +If the address and size are not given, these are obtained from environment +variables (see below). In any case the environment variables are updated +after the command runs. + + +Environment Variables +--------------------- + +The following are used: + +profbase + Base address of trace output buffer + +profoffset + Offset of first unwritten byte in trace output buffer + +profsize + Size of trace output buffer + +All of these are set by the 'trace calls' command. + +These variables keep track of the amount of data written to the trace +output buffer by the 'trace' command. The trace commands which write data +to the output buffer can use these to specify the buffer to write to, and +update profoffset each time. This allows successive commands to append data +to the same buffer, for example:: + + => trace funclist 10000 e00000 + => trace calls + +(the latter command appends more data to the buffer). + + +fakegocmd + Specifies commands to run just before booting the OS. This + is a useful time to write the trace data to the host for + processing. + + +Writing Out Trace Data +---------------------- + +Once the trace data is in an output buffer in memory there are various ways +to transmit it to the host. Notably you can use tftput to send the data +over a network link:: + + fakegocmd=trace pause; usb start; set autoload n; bootp; + trace calls 10000000 1000000; + tftpput ${profbase} ${profoffset} 192.168.1.4:/tftpboot/calls + +This starts up USB (to talk to an attached USB Ethernet dongle), writes +a trace log to address 10000000 and sends it to a host machine using +TFTP. After this, U-Boot will boot the OS normally, albeit a little +later. + + +Converting Trace Output Data +---------------------------- + +The trace output data is kept in a binary format which is not documented +here. To convert it into something useful, you can use proftool. + +This tool must be given the U-Boot map file and the trace data received +from running that U-Boot. It produces a text output file. + +Options + +-m <map_file> + Specify U-Boot map file + +-p <trace_file> + Specifiy profile/trace file + +Commands: + +dump-ftrace + Write a text dump of the file in Linux ftrace format to stdout + + +Viewing the Trace Data +---------------------- + +You can use pytimechart for this (sudo apt-get pytimechart might work on +your Debian-style machine, and use your favourite search engine to obtain +documentation). It expects the file to have a .txt extension. The program +has terse user interface but is very convenient for viewing U-Boot +profile information. + + +Workflow Suggestions +-------------------- + +The following suggestions may be helpful if you are trying to reduce boot +time: + +1. Enable CONFIG_BOOTSTAGE and CONFIG_BOOTSTAGE_REPORT. This should get + you are helpful overall snapshot of the boot time. + +2. Build U-Boot with tracing and run it. Note the difference in boot time + (it is common for tracing to add 10% to the time) + +3. Collect the trace information as descibed above. Use this to find where + all the time is being spent. + +4. Take a look at that code and see if you can optimise it. Perhaps it is + possible to speed up the initialisation of a device, or remove an unused + feature. + +5. Rebuild, run and collect again. Compare your results. + +6. Keep going until you run out of steam, or your boot is fast enough. + + +Configuring Trace +----------------- + +There are a few parameters in the code that you may want to consider. +There is a function call depth limit (set to 15 by default). When the +stack depth goes above this then no tracing information is recorded. +The maximum depth reached is recorded and displayed by the 'trace stats' +command. + + +Future Work +----------- + +Tracing could be a little tidier in some areas, for example providing +run-time configuration options for trace. + +Some other features that might be useful: + +- Trace filter to select which functions are recorded +- Sample-based profiling using a timer interrupt +- Better control over trace depth +- Compression of trace information + + +Simon Glass <s...@chromium.org> +April 2013 -- 2.29.2