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