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