README.trace 10 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346
  1. # SPDX-License-Identifier: GPL-2.0+
  2. #
  3. # Copyright (c) 2013 The Chromium OS Authors.
  4. Tracing in U-Boot
  5. =================
  6. U-Boot supports a simple tracing feature which allows a record of excecution
  7. to be collected and sent to a host machine for analysis. At present the
  8. main use for this is to profile boot time.
  9. Overview
  10. --------
  11. The trace feature uses GCC's instrument-functions feature to trace all
  12. function entry/exit points. These are then recorded in a memory buffer.
  13. The memory buffer can be saved to the host over a network link using
  14. tftpput or by writing to an attached memory device such as MMC.
  15. On the host, the file is first converted with a tool called 'proftool',
  16. which extracts useful information from it. The resulting trace output
  17. resembles that emitted by Linux's ftrace feature, so can be visually
  18. displayed by pytimechart.
  19. Quick-start using Sandbox
  20. -------------------------
  21. Sandbox is a build of U-Boot that can run under Linux so it is a convenient
  22. way of trying out tracing before you use it on your actual board. To do
  23. this, follow these steps:
  24. Add the following to include/configs/sandbox.h (if not already there)
  25. #define CONFIG_TRACE
  26. #define CONFIG_CMD_TRACE
  27. #define CONFIG_TRACE_BUFFER_SIZE (16 << 20)
  28. #define CONFIG_TRACE_EARLY_SIZE (8 << 20)
  29. #define CONFIG_TRACE_EARLY
  30. #define CONFIG_TRACE_EARLY_ADDR 0x00100000
  31. Build sandbox U-Boot with tracing enabled:
  32. $ make FTRACE=1 O=sandbox sandbox_config
  33. $ make FTRACE=1 O=sandbox
  34. Run sandbox, wait for a bit of trace information to appear, and then capture
  35. a trace:
  36. $ ./sandbox/u-boot
  37. U-Boot 2013.04-rc2-00100-ga72fcef (Apr 17 2013 - 19:25:24)
  38. DRAM: 128 MiB
  39. trace: enabled
  40. Using default environment
  41. In: serial
  42. Out: serial
  43. Err: serial
  44. =>trace stats
  45. 671,406 function sites
  46. 69,712 function calls
  47. 0 untracked function calls
  48. 73,373 traced function calls
  49. 16 maximum observed call depth
  50. 15 call depth limit
  51. 66,491 calls not traced due to depth
  52. =>trace stats
  53. 671,406 function sites
  54. 1,279,450 function calls
  55. 0 untracked function calls
  56. 950,490 traced function calls (333217 dropped due to overflow)
  57. 16 maximum observed call depth
  58. 15 call depth limit
  59. 1,275,767 calls not traced due to depth
  60. =>trace calls 0 e00000
  61. Call list dumped to 00000000, size 0xae0a40
  62. =>print
  63. baudrate=115200
  64. profbase=0
  65. profoffset=ae0a40
  66. profsize=e00000
  67. stderr=serial
  68. stdin=serial
  69. stdout=serial
  70. Environment size: 117/8188 bytes
  71. =>host save host 0 trace 0 ${profoffset}
  72. 11405888 bytes written in 10 ms (1.1 GiB/s)
  73. =>reset
  74. Then run proftool to convert the trace information to ftrace format.
  75. $ ./sandbox/tools/proftool -m sandbox/System.map -p trace dump-ftrace >trace.txt
  76. Finally run pytimechart to display it:
  77. $ pytimechart trace.txt
  78. Using this tool you can zoom and pan across the trace, with the function
  79. calls on the left and little marks representing the start and end of each
  80. function.
  81. CONFIG Options
  82. --------------
  83. - CONFIG_TRACE
  84. Enables the trace feature in U-Boot.
  85. - CONFIG_CMD_TRACE
  86. Enables the trace command.
  87. - CONFIG_TRACE_BUFFER_SIZE
  88. Size of trace buffer to allocate for U-Boot. This buffer is
  89. used after relocation, as a place to put function tracing
  90. information. The address of the buffer is determined by
  91. the relocation code.
  92. - CONFIG_TRACE_EARLY
  93. Define this to start tracing early, before relocation.
  94. - CONFIG_TRACE_EARLY_SIZE
  95. Size of 'early' trace buffer. Before U-Boot has relocated
  96. it doesn't have a proper trace buffer. On many boards
  97. you can define an area of memory to use for the trace
  98. buffer until the 'real' trace buffer is available after
  99. relocation. The contents of this buffer are then copied to
  100. the real buffer.
  101. - CONFIG_TRACE_EARLY_ADDR
  102. Address of early trace buffer
  103. Building U-Boot with Tracing Enabled
  104. ------------------------------------
  105. Pass 'FTRACE=1' to the U-Boot Makefile to actually instrument the code.
  106. This is kept as a separate option so that it is easy to enable/disable
  107. instrumenting from the command line instead of having to change board
  108. config files.
  109. Collecting Trace Data
  110. ---------------------
  111. When you run U-Boot on your board it will collect trace data up to the
  112. limit of the trace buffer size you have specified. Once that is exhausted
  113. no more data will be collected.
  114. Collecting trace data has an affect on execution time/performance. You
  115. will notice this particularly with trvial functions - the overhead of
  116. recording their execution may even exceed their normal execution time.
  117. In practice this doesn't matter much so long as you are aware of the
  118. effect. Once you have done your optimisations, turn off tracing before
  119. doing end-to-end timing.
  120. The best time to start tracing is right at the beginning of U-Boot. The
  121. best time to stop tracing is right at the end. In practice it is hard
  122. to achieve these ideals.
  123. This implementation enables tracing early in board_init_f(). This means
  124. that it captures most of the board init process, missing only the
  125. early architecture-specific init. However, it also misses the entire
  126. SPL stage if there is one.
  127. U-Boot typically ends with a 'bootm' command which loads and runs an
  128. OS. There is useful trace data in the execution of that bootm
  129. command. Therefore this implementation provides a way to collect trace
  130. data after bootm has finished processing, but just before it jumps to
  131. the OS. In practical terms, U-Boot runs the 'fakegocmd' environment
  132. variable at this point. This variable should have a short script which
  133. collects the trace data and writes it somewhere.
  134. Trace data collection relies on a microsecond timer, accesed through
  135. timer_get_us(). So the first think you should do is make sure that
  136. this produces sensible results for your board. Suitable sources for
  137. this timer include high resolution timers, PWMs or profile timers if
  138. available. Most modern SOCs have a suitable timer for this. Make sure
  139. that you mark this timer (and anything it calls) with
  140. __attribute__((no_instrument_function)) so that the trace library can
  141. use it without causing an infinite loop.
  142. Commands
  143. --------
  144. The trace command has variable sub-commands:
  145. - stats
  146. Display tracing statistics
  147. - pause
  148. Pause tracing
  149. - resume
  150. Resume tracing
  151. - funclist [<addr> <size>]
  152. Dump a list of functions into the buffer
  153. - calls [<addr> <size>]
  154. Dump function call trace into buffer
  155. If the address and size are not given, these are obtained from environment
  156. variables (see below). In any case the environment variables are updated
  157. after the command runs.
  158. Environment Variables
  159. ---------------------
  160. The following are used:
  161. - profbase
  162. Base address of trace output buffer
  163. - profoffset
  164. Offset of first unwritten byte in trace output buffer
  165. - profsize
  166. Size of trace output buffer
  167. All of these are set by the 'trace calls' command.
  168. These variables keep track of the amount of data written to the trace
  169. output buffer by the 'trace' command. The trace commands which write data
  170. to the output buffer can use these to specify the buffer to write to, and
  171. update profoffset each time. This allows successive commands to append data
  172. to the same buffer, for example:
  173. trace funclist 10000 e00000
  174. trace calls
  175. (the latter command appends more data to the buffer).
  176. - fakegocmd
  177. Specifies commands to run just before booting the OS. This
  178. is a useful time to write the trace data to the host for
  179. processing.
  180. Writing Out Trace Data
  181. ----------------------
  182. Once the trace data is in an output buffer in memory there are various ways
  183. to transmit it to the host. Notably you can use tftput to send the data
  184. over a network link:
  185. fakegocmd=trace pause; usb start; set autoload n; bootp;
  186. trace calls 10000000 1000000;
  187. tftpput ${profbase} ${profoffset} 192.168.1.4:/tftpboot/calls
  188. This starts up USB (to talk to an attached USB Ethernet dongle), writes
  189. a trace log to address 10000000 and sends it to a host machine using
  190. TFTP. After this, U-Boot will boot the OS normally, albeit a little
  191. later.
  192. Converting Trace Output Data
  193. ----------------------------
  194. The trace output data is kept in a binary format which is not documented
  195. here. To convert it into something useful, you can use proftool.
  196. This tool must be given the U-Boot map file and the trace data received
  197. from running that U-Boot. It produces a text output file.
  198. Options
  199. -m <map_file>
  200. Specify U-Boot map file
  201. -p <trace_file>
  202. Specifiy profile/trace file
  203. Commands:
  204. - dump-ftrace
  205. Write a text dump of the file in Linux ftrace format to stdout
  206. Viewing the Trace Data
  207. ----------------------
  208. You can use pytimechart for this (sudo apt-get pytimechart might work on
  209. your Debian-style machine, and use your favourite search engine to obtain
  210. documentation). It expects the file to have a .txt extension. The program
  211. has terse user interface but is very convenient for viewing U-Boot
  212. profile information.
  213. Workflow Suggestions
  214. --------------------
  215. The following suggestions may be helpful if you are trying to reduce boot
  216. time:
  217. 1. Enable CONFIG_BOOTSTAGE and CONFIG_BOOTSTAGE_REPORT. This should get
  218. you are helpful overall snapshot of the boot time.
  219. 2. Build U-Boot with tracing and run it. Note the difference in boot time
  220. (it is common for tracing to add 10% to the time)
  221. 3. Collect the trace information as descibed above. Use this to find where
  222. all the time is being spent.
  223. 4. Take a look at that code and see if you can optimise it. Perhaps it is
  224. possible to speed up the initialisation of a device, or remove an unused
  225. feature.
  226. 5. Rebuild, run and collect again. Compare your results.
  227. 6. Keep going until you run out of steam, or your boot is fast enough.
  228. Configuring Trace
  229. -----------------
  230. There are a few parameters in the code that you may want to consider.
  231. There is a function call depth limit (set to 15 by default). When the
  232. stack depth goes above this then no tracing information is recorded.
  233. The maximum depth reached is recorded and displayed by the 'trace stats'
  234. command.
  235. Future Work
  236. -----------
  237. Tracing could be a little tidier in some areas, for example providing
  238. run-time configuration options for trace.
  239. Some other features that might be useful:
  240. - Trace filter to select which functions are recorded
  241. - Sample-based profiling using a timer interrupt
  242. - Better control over trace depth
  243. - Compression of trace information
  244. Simon Glass <sjg@chromium.org>
  245. April 2013