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