trace.rst 10 KB

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