/Documentation/trace/ftrace.txt

https://bitbucket.org/sammyz/iscream_thunderc-2.6.35-rebase · Plain Text · 1946 lines · 1558 code · 388 blank · 0 comment · 0 complexity · dcf3f528e237b56b0eeeb66bce092168 MD5 · raw file

Large files are truncated click here to view the full file

    

  1. ftrace - Function Tracer
    2. 

  2. 		========================
    3. 

  3. 

  4. Copyright 2008 Red Hat Inc.
    5. 

  5.    Author:   Steven Rostedt <srostedt@redhat.com>
    6. 

  6.   License:   The GNU Free Documentation License, Version 1.2
    7. 

  7.                (dual licensed under the GPL v2)
    8. 

  8. Reviewers:   Elias Oltmanns, Randy Dunlap, Andrew Morton,
    9. 

  9. 	     John Kacur, and David Teigland.
    10. 

  10. Written for: 2.6.28-rc2
    11. 

  11. 

  12. Introduction
    13. 

  13. ------------
    14. 

  14. 

  15. Ftrace is an internal tracer designed to help out developers and
    16. 

  16. designers of systems to find what is going on inside the kernel.
    17. 

  17. It can be used for debugging or analyzing latencies and
    18. 

  18. performance issues that take place outside of user-space.
    19. 

  19. 

  20. Although ftrace is the function tracer, it also includes an
    21. 

  21. infrastructure that allows for other types of tracing. Some of
    22. 

  22. the tracers that are currently in ftrace include a tracer to
    23. 

  23. trace context switches, the time it takes for a high priority
    24. 

  24. task to run after it was woken up, the time interrupts are
    25. 

  25. disabled, and more (ftrace allows for tracer plugins, which
    26. 

  26. means that the list of tracers can always grow).
    27. 

  27. 

  28. 

  29. Implementation Details
    30. 

  30. ----------------------
    31. 

  31. 

  32. See ftrace-design.txt for details for arch porters and such.
    33. 

  33. 

  34. 

  35. The File System
    36. 

  36. ---------------
    37. 

  37. 

  38. Ftrace uses the debugfs file system to hold the control files as
    39. 

  39. well as the files to display output.
    40. 

  40. 

  41. When debugfs is configured into the kernel (which selecting any ftrace
    42. 

  42. option will do) the directory /sys/kernel/debug will be created. To mount
    43. 

  43. this directory, you can add to your /etc/fstab file:
    44. 

  44. 

  45.  debugfs       /sys/kernel/debug          debugfs defaults        0       0
    46. 

  46. 

  47. Or you can mount it at run time with:
    48. 

  48. 

  49.  mount -t debugfs nodev /sys/kernel/debug
    50. 

  50. 

  51. For quicker access to that directory you may want to make a soft link to
    52. 

  52. it:
    53. 

  53. 

  54.  ln -s /sys/kernel/debug /debug
    55. 

  55. 

  56. Any selected ftrace option will also create a directory called tracing
    57. 

  57. within the debugfs. The rest of the document will assume that you are in
    58. 

  58. the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
    59. 

  59. on the files within that directory and not distract from the content with
    60. 

  60. the extended "/sys/kernel/debug/tracing" path name.
    61. 

  61. 

  62. That's it! (assuming that you have ftrace configured into your kernel)
    63. 

    64. 

  64. After mounting the debugfs, you can see a directory called
    65. 

  65. "tracing".  This directory contains the control and output files
    66. 

  66. of ftrace. Here is a list of some of the key files:
    67. 

  67. 

  68. 

  69.  Note: all time values are in microseconds.
    70. 

  70. 

  71.   current_tracer:
    72. 

  72. 

  73. 	This is used to set or display the current tracer
    74. 

  74. 	that is configured.
    75. 

  75. 

  76.   available_tracers:
    77. 

  77. 

  78. 	This holds the different types of tracers that
    79. 

  79. 	have been compiled into the kernel. The
    80. 

  80. 	tracers listed here can be configured by
    81. 

  81. 	echoing their name into current_tracer.
    82. 

  82. 

  83.   tracing_enabled:
    84. 

  84. 

  85. 	This sets or displays whether the current_tracer
    86. 

  86. 	is activated and tracing or not. Echo 0 into this
    87. 

  87. 	file to disable the tracer or 1 to enable it.
    88. 

  88. 

  89.   trace:
    90. 

  90. 

  91. 	This file holds the output of the trace in a human
    92. 

  92. 	readable format (described below).
    93. 

  93. 

  94.   trace_pipe:
    95. 

  95. 

  96. 	The output is the same as the "trace" file but this
    97. 

  97. 	file is meant to be streamed with live tracing.
    98. 

  98. 	Reads from this file will block until new data is
    99. 

  99. 	retrieved.  Unlike the "trace" file, this file is a
    100. 

  100. 	consumer. This means reading from this file causes
    101. 

  101. 	sequential reads to display more current data. Once
    102. 

  102. 	data is read from this file, it is consumed, and
    103. 

  103. 	will not be read again with a sequential read. The
    104. 

  104. 	"trace" file is static, and if the tracer is not
    105. 

  105. 	adding more data,they will display the same
    106. 

  106. 	information every time they are read.
    107. 

  107. 

  108.   trace_options:
    109. 

  109. 

  110. 	This file lets the user control the amount of data
    111. 

  111. 	that is displayed in one of the above output
    112. 

  112. 	files.
    113. 

  113. 

  114.   tracing_max_latency:
    115. 

  115. 

  116. 	Some of the tracers record the max latency.
    117. 

  117. 	For example, the time interrupts are disabled.
    118. 

  118. 	This time is saved in this file. The max trace
    119. 

  119. 	will also be stored, and displayed by "trace".
    120. 

  120. 	A new max trace will only be recorded if the
    121. 

  121. 	latency is greater than the value in this
    122. 

  122. 	file. (in microseconds)
    123. 

  123. 

  124.   buffer_size_kb:
    125. 

  125. 

  126. 	This sets or displays the number of kilobytes each CPU
    127. 

  127. 	buffer can hold. The tracer buffers are the same size
    128. 

  128. 	for each CPU. The displayed number is the size of the
    129. 

  129. 	CPU buffer and not total size of all buffers. The
    130. 

  130. 	trace buffers are allocated in pages (blocks of memory
    131. 

  131. 	that the kernel uses for allocation, usually 4 KB in size).
    132. 

  132. 	If the last page allocated has room for more bytes
    133. 

  133. 	than requested, the rest of the page will be used,
    134. 

  134. 	making the actual allocation bigger than requested.
    135. 

  135. 	( Note, the size may not be a multiple of the page size
    136. 

  136. 	  due to buffer management overhead. )
    137. 

  137. 

  138. 	This can only be updated when the current_tracer
    139. 

  139. 	is set to "nop".
    140. 

  140. 

  141.   tracing_cpumask:
    142. 

  142. 

  143. 	This is a mask that lets the user only trace
    144. 

  144. 	on specified CPUS. The format is a hex string
    145. 

  145. 	representing the CPUS.
    146. 

  146. 

  147.   set_ftrace_filter:
    148. 

  148. 

  149. 	When dynamic ftrace is configured in (see the
    150. 

  150. 	section below "dynamic ftrace"), the code is dynamically
    151. 

  151. 	modified (code text rewrite) to disable calling of the
    152. 

  152. 	function profiler (mcount). This lets tracing be configured
    153. 

  153. 	in with practically no overhead in performance.  This also
    154. 

  154. 	has a side effect of enabling or disabling specific functions
    155. 

  155. 	to be traced. Echoing names of functions into this file
    156. 

  156. 	will limit the trace to only those functions.
    157. 

  157. 

  158. 	This interface also allows for commands to be used. See the
    159. 

  159. 	"Filter commands" section for more details.
    160. 

  160. 

  161.   set_ftrace_notrace:
    162. 

  162. 

  163. 	This has an effect opposite to that of
    164. 

  164. 	set_ftrace_filter. Any function that is added here will not
    165. 

  165. 	be traced. If a function exists in both set_ftrace_filter
    166. 

  166. 	and set_ftrace_notrace,	the function will _not_ be traced.
    167. 

  167. 

  168.   set_ftrace_pid:
    169. 

  169. 

  170. 	Have the function tracer only trace a single thread.
    171. 

  171. 

  172.   set_graph_function:
    173. 

  173. 

  174. 	Set a "trigger" function where tracing should start
    175. 

  175. 	with the function graph tracer (See the section
    176. 

  176. 	"dynamic ftrace" for more details).
    177. 

  177. 

  178.   available_filter_functions:
    179. 

  179. 

  180. 	This lists the functions that ftrace
    181. 

  181. 	has processed and can trace. These are the function
    182. 

  182. 	names that you can pass to "set_ftrace_filter" or
    183. 

  183. 	"set_ftrace_notrace". (See the section "dynamic ftrace"
    184. 

  184. 	below for more details.)
    185. 

  185. 

  186. 

  187. The Tracers
    188. 

  188. -----------
    189. 

  189. 

  190. Here is the list of current tracers that may be configured.
    191. 

  191. 

  192.   "function"
    193. 

  193. 

  194. 	Function call tracer to trace all kernel functions.
    195. 

  195. 

  196.   "function_graph"
    197. 

  197. 

  198. 	Similar to the function tracer except that the
    199. 

  199. 	function tracer probes the functions on their entry
    200. 

  200. 	whereas the function graph tracer traces on both entry
    201. 

  201. 	and exit of the functions. It then provides the ability
    202. 

  202. 	to draw a graph of function calls similar to C code
    203. 

  203. 	source.
    204. 

  204. 

  205.   "sched_switch"
    206. 

  206. 

  207. 	Traces the context switches and wakeups between tasks.
    208. 

  208. 

  209.   "irqsoff"
    210. 

  210. 

  211. 	Traces the areas that disable interrupts and saves
    212. 

  212. 	the trace with the longest max latency.
    213. 

  213. 	See tracing_max_latency. When a new max is recorded,
    214. 

  214. 	it replaces the old trace. It is best to view this
    215. 

  215. 	trace with the latency-format option enabled.
    216. 

  216. 

  217.   "preemptoff"
    218. 

  218. 

  219. 	Similar to irqsoff but traces and records the amount of
    220. 

  220. 	time for which preemption is disabled.
    221. 

  221. 

  222.   "preemptirqsoff"
    223. 

  223. 

  224. 	Similar to irqsoff and preemptoff, but traces and
    225. 

  225. 	records the largest time for which irqs and/or preemption
    226. 

  226. 	is disabled.
    227. 

  227. 

  228.   "wakeup"
    229. 

  229. 

  230. 	Traces and records the max latency that it takes for
    231. 

  231. 	the highest priority task to get scheduled after
    232. 

  232. 	it has been woken up.
    233. 

  233. 

  234.   "hw-branch-tracer"
    235. 

  235. 

  236. 	Uses the BTS CPU feature on x86 CPUs to traces all
    237. 

  237. 	branches executed.
    238. 

  238. 

  239.   "nop"
    240. 

  240. 

  241. 	This is the "trace nothing" tracer. To remove all
    242. 

  242. 	tracers from tracing simply echo "nop" into
    243. 

  243. 	current_tracer.
    244. 

  244. 

  245. 

  246. Examples of using the tracer
    247. 

  247. ----------------------------
    248. 

  248. 

  249. Here are typical examples of using the tracers when controlling
    250. 

  250. them only with the debugfs interface (without using any
    251. 

  251. user-land utilities).
    252. 

  252. 

  253. Output format:
    254. 

  254. --------------
    255. 

  255. 

  256. Here is an example of the output format of the file "trace"
    257. 

  257. 

  258.                              --------
    259. 

  259. # tracer: function
    260. 

  260. #
    261. 

  261. #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
    262. 

  262. #              | |      |          |         |
    263. 

  263.             bash-4251  [01] 10152.583854: path_put <-path_walk
    264. 

  264.             bash-4251  [01] 10152.583855: dput <-path_put
    265. 

  265.             bash-4251  [01] 10152.583855: _atomic_dec_and_lock <-dput
    266. 

  266.                              --------
    267. 

  267. 

  268. A header is printed with the tracer name that is represented by
    269. 

  269. the trace. In this case the tracer is "function". Then a header
    270. 

  270. showing the format. Task name "bash", the task PID "4251", the
    271. 

  271. CPU that it was running on "01", the timestamp in <secs>.<usecs>
    272. 

  272. format, the function name that was traced "path_put" and the
    273. 

  273. parent function that called this function "path_walk". The
    274. 

  274. timestamp is the time at which the function was entered.
    275. 

  275. 

  276. The sched_switch tracer also includes tracing of task wakeups
    277. 

  277. and context switches.
    278. 

  278. 

  279.      ksoftirqd/1-7     [01]  1453.070013:      7:115:R   +  2916:115:S
    280. 

  280.      ksoftirqd/1-7     [01]  1453.070013:      7:115:R   +    10:115:S
    281. 

  281.      ksoftirqd/1-7     [01]  1453.070013:      7:115:R ==>    10:115:R
    282. 

  282.         events/1-10    [01]  1453.070013:     10:115:S ==>  2916:115:R
    283. 

  283.      kondemand/1-2916  [01]  1453.070013:   2916:115:S ==>     7:115:R
    284. 

  284.      ksoftirqd/1-7     [01]  1453.070013:      7:115:S ==>     0:140:R
    285. 

  285. 

  286. Wake ups are represented by a "+" and the context switches are
    287. 

  287. shown as "==>".  The format is:
    288. 

  288. 

  289.  Context switches:
    290. 

  290. 

  291.        Previous task              Next Task
    292. 

  292. 

  293.   <pid>:<prio>:<state>  ==>  <pid>:<prio>:<state>
    294. 

  294. 

  295.  Wake ups:
    296. 

  296. 

  297.        Current task               Task waking up
    298. 

  298. 

  299.   <pid>:<prio>:<state>    +  <pid>:<prio>:<state>
    300. 

  300. 

  301. The prio is the internal kernel priority, which is the inverse
    302. 

  302. of the priority that is usually displayed by user-space tools.
    303. 

  303. Zero represents the highest priority (99). Prio 100 starts the
    304. 

  304. "nice" priorities with 100 being equal to nice -20 and 139 being
    305. 

  305. nice 19. The prio "140" is reserved for the idle task which is
    306. 

  306. the lowest priority thread (pid 0).
    307. 

  307. 

  308. 

  309. Latency trace format
    310. 

  310. --------------------
    311. 

  311. 

  312. When the latency-format option is enabled, the trace file gives
    313. 

  313. somewhat more information to see why a latency happened.
    314. 

  314. Here is a typical trace.
    315. 

  315. 

  316. # tracer: irqsoff
    317. 

  317. #
    318. 

  318. irqsoff latency trace v1.1.5 on 2.6.26-rc8
    319. 

  319. --------------------------------------------------------------------
    320. 

  320.  latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    321. 

  321.     -----------------
    322. 

  322.     | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
    323. 

  323.     -----------------
    324. 

  324.  => started at: apic_timer_interrupt
    325. 

  325.  => ended at:   do_softirq
    326. 

  326. 

  327. #                _------=> CPU#
    328. 

  328. #               / _-----=> irqs-off
    329. 

  329. #              | / _----=> need-resched
    330. 

  330. #              || / _---=> hardirq/softirq
    331. 

  331. #              ||| / _--=> preempt-depth
    332. 

  332. #              |||| /
    333. 

  333. #              |||||     delay
    334. 

  334. #  cmd     pid ||||| time  |   caller
    335. 

  335. #     \   /    |||||   \   |   /
    336. 

  336.   <idle>-0     0d..1    0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
    337. 

  337.   <idle>-0     0d.s.   97us : __do_softirq (do_softirq)
    338. 

  338.   <idle>-0     0d.s1   98us : trace_hardirqs_on (do_softirq)
    339. 

  339. 

  340. 

  341. This shows that the current tracer is "irqsoff" tracing the time
    342. 

  342. for which interrupts were disabled. It gives the trace version
    343. 

  343. and the version of the kernel upon which this was executed on
    344. 

  344. (2.6.26-rc8). Then it displays the max latency in microsecs (97
    345. 

  345. us). The number of trace entries displayed and the total number
    346. 

  346. recorded (both are three: #3/3). The type of preemption that was
    347. 

  347. used (PREEMPT). VP, KP, SP, and HP are always zero and are
    348. 

  348. reserved for later use. #P is the number of online CPUS (#P:2).
    349. 

  349. 

  350. The task is the process that was running when the latency
    351. 

  351. occurred. (swapper pid: 0).
    352. 

  352. 

  353. The start and stop (the functions in which the interrupts were
    354. 

  354. disabled and enabled respectively) that caused the latencies:
    355. 

  355. 

  356.   apic_timer_interrupt is where the interrupts were disabled.
    357. 

  357.   do_softirq is where they were enabled again.
    358. 

  358. 

  359. The next lines after the header are the trace itself. The header
    360. 

  360. explains which is which.
    361. 

  361. 

  362.   cmd: The name of the process in the trace.
    363. 

  363. 

  364.   pid: The PID of that process.
    365. 

  365. 

  366.   CPU#: The CPU which the process was running on.
    367. 

  367. 

  368.   irqs-off: 'd' interrupts are disabled. '.' otherwise.
    369. 

  369. 	    Note: If the architecture does not support a way to
    370. 

  370. 		  read the irq flags variable, an 'X' will always
    371. 

  371. 		  be printed here.
    372. 

  372. 

  373.   need-resched: 'N' task need_resched is set, '.' otherwise.
    374. 

  374. 

  375.   hardirq/softirq:
    376. 

  376. 	'H' - hard irq occurred inside a softirq.
    377. 

  377. 	'h' - hard irq is running
    378. 

  378. 	's' - soft irq is running
    379. 

  379. 	'.' - normal context.
    380. 

  380. 

  381.   preempt-depth: The level of preempt_disabled
    382. 

  382. 

  383. The above is mostly meaningful for kernel developers.
    384. 

  384. 

  385.   time: When the latency-format option is enabled, the trace file
    386. 

  386. 	output includes a timestamp relative to the start of the
    387. 

  387. 	trace. This differs from the output when latency-format
    388. 

  388. 	is disabled, which includes an absolute timestamp.
    389. 

  389. 

  390.   delay: This is just to help catch your eye a bit better. And
    391. 

  391. 	 needs to be fixed to be only relative to the same CPU.
    392. 

  392. 	 The marks are determined by the difference between this
    393. 

  393. 	 current trace and the next trace.
    394. 

  394. 	  '!' - greater than preempt_mark_thresh (default 100)
    395. 

  395. 	  '+' - greater than 1 microsecond
    396. 

  396. 	  ' ' - less than or equal to 1 microsecond.
    397. 

  397. 

  398.   The rest is the same as the 'trace' file.
    399. 

  399. 

  400. 

  401. trace_options
    402. 

  402. -------------
    403. 

  403. 

  404. The trace_options file is used to control what gets printed in
    405. 

  405. the trace output. To see what is available, simply cat the file:
    406. 

  406. 

  407.   cat trace_options
    408. 

  408.   print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
    409. 

  409.   noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
    410. 

  410. 

  411. To disable one of the options, echo in the option prepended with
    412. 

  412. "no".
    413. 

  413. 

  414.   echo noprint-parent > trace_options
    415. 

  415. 

  416. To enable an option, leave off the "no".
    417. 

  417. 

  418.   echo sym-offset > trace_options
    419. 

  419. 

  420. Here are the available options:
    421. 

  421. 

  422.   print-parent - On function traces, display the calling (parent)
    423. 

  423. 		 function as well as the function being traced.
    424. 

  424. 

  425.   print-parent:
    426. 

  426.    bash-4000  [01]  1477.606694: simple_strtoul <-strict_strtoul
    427. 

  427. 

  428.   noprint-parent:
    429. 

  429.    bash-4000  [01]  1477.606694: simple_strtoul
    430. 

  430. 

  431. 

  432.   sym-offset - Display not only the function name, but also the
    433. 

  433. 	       offset in the function. For example, instead of
    434. 

  434. 	       seeing just "ktime_get", you will see
    435. 

  435. 	       "ktime_get+0xb/0x20".
    436. 

  436. 

  437.   sym-offset:
    438. 

  438.    bash-4000  [01]  1477.606694: simple_strtoul+0x6/0xa0
    439. 

  439. 

  440.   sym-addr - this will also display the function address as well
    441. 

  441. 	     as the function name.
    442. 

  442. 

  443.   sym-addr:
    444. 

  444.    bash-4000  [01]  1477.606694: simple_strtoul <c0339346>
    445. 

  445. 

  446.   verbose - This deals with the trace file when the
    447. 

  447.             latency-format option is enabled.
    448. 

  448. 

  449.     bash  4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
    450. 

  450.     (+0.000ms): simple_strtoul (strict_strtoul)
    451. 

  451. 

  452.   raw - This will display raw numbers. This option is best for
    453. 

  453. 	use with user applications that can translate the raw
    454. 

  454. 	numbers better than having it done in the kernel.
    455. 

  455. 

  456.   hex - Similar to raw, but the numbers will be in a hexadecimal
    457. 

  457. 	format.
    458. 

  458. 

  459.   bin - This will print out the formats in raw binary.
    460. 

  460. 

  461.   block - TBD (needs update)
    462. 

  462. 

  463.   stacktrace - This is one of the options that changes the trace
    464. 

  464. 	       itself. When a trace is recorded, so is the stack
    465. 

  465. 	       of functions. This allows for back traces of
    466. 

  466. 	       trace sites.
    467. 

  467. 

  468.   userstacktrace - This option changes the trace. It records a
    469. 

  469. 		   stacktrace of the current userspace thread.
    470. 

  470. 

  471.   sym-userobj - when user stacktrace are enabled, look up which
    472. 

  472. 		object the address belongs to, and print a
    473. 

  473. 		relative address. This is especially useful when
    474. 

  474. 		ASLR is on, otherwise you don't get a chance to
    475. 

  475. 		resolve the address to object/file/line after
    476. 

  476. 		the app is no longer running
    477. 

  477. 

  478. 		The lookup is performed when you read
    479. 

  479. 		trace,trace_pipe. Example:
    480. 

  480. 

  481. 		a.out-1623  [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
    482. 

  482. x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
    483. 

  483. 

  484.   sched-tree - trace all tasks that are on the runqueue, at
    485. 

  485. 	       every scheduling event. Will add overhead if
    486. 

  486. 	       there's a lot of tasks running at once.
    487. 

    488. 

  488.   latency-format - This option changes the trace. When
    489. 

  489.                    it is enabled, the trace displays
    490. 

  490.                    additional information about the
    491. 

  491.                    latencies, as described in "Latency
    492. 

  492.                    trace format".
    493. 

    494. 

  494. sched_switch
    495. 

  495. ------------
    496. 

  496. 

  497. This tracer simply records schedule switches. Here is an example
    498. 

  498. of how to use it.
    499. 

  499. 

  500.  # echo sched_switch > current_tracer
    501. 

  501.  # echo 1 > tracing_enabled
    502. 

  502.  # sleep 1
    503. 

  503.  # echo 0 > tracing_enabled
    504. 

  504.  # cat trace
    505. 

  505. 

  506. # tracer: sched_switch
    507. 

  507. #
    508. 

  508. #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
    509. 

  509. #              | |      |          |         |
    510. 

  510.             bash-3997  [01]   240.132281:   3997:120:R   +  4055:120:R
    511. 

  511.             bash-3997  [01]   240.132284:   3997:120:R ==>  4055:120:R
    512. 

  512.            sleep-4055  [01]   240.132371:   4055:120:S ==>  3997:120:R
    513. 

  513.             bash-3997  [01]   240.132454:   3997:120:R   +  4055:120:S
    514. 

  514.             bash-3997  [01]   240.132457:   3997:120:R ==>  4055:120:R
    515. 

  515.            sleep-4055  [01]   240.132460:   4055:120:D ==>  3997:120:R
    516. 

  516.             bash-3997  [01]   240.132463:   3997:120:R   +  4055:120:D
    517. 

  517.             bash-3997  [01]   240.132465:   3997:120:R ==>  4055:120:R
    518. 

  518.           <idle>-0     [00]   240.132589:      0:140:R   +     4:115:S
    519. 

  519.           <idle>-0     [00]   240.132591:      0:140:R ==>     4:115:R
    520. 

  520.      ksoftirqd/0-4     [00]   240.132595:      4:115:S ==>     0:140:R
    521. 

  521.           <idle>-0     [00]   240.132598:      0:140:R   +     4:115:S
    522. 

  522.           <idle>-0     [00]   240.132599:      0:140:R ==>     4:115:R
    523. 

  523.      ksoftirqd/0-4     [00]   240.132603:      4:115:S ==>     0:140:R
    524. 

  524.            sleep-4055  [01]   240.133058:   4055:120:S ==>  3997:120:R
    525. 

  525.  [...]
    526. 

  526. 

  527. 

  528. As we have discussed previously about this format, the header
    529. 

  529. shows the name of the trace and points to the options. The
    530. 

  530. "FUNCTION" is a misnomer since here it represents the wake ups
    531. 

  531. and context switches.
    532. 

  532. 

  533. The sched_switch file only lists the wake ups (represented with
    534. 

  534. '+') and context switches ('==>') with the previous task or
    535. 

  535. current task first followed by the next task or task waking up.
    536. 

  536. The format for both of these is PID:KERNEL-PRIO:TASK-STATE.
    537. 

  537. Remember that the KERNEL-PRIO is the inverse of the actual
    538. 

  538. priority with zero (0) being the highest priority and the nice
    539. 

  539. values starting at 100 (nice -20). Below is a quick chart to map
    540. 

  540. the kernel priority to user land priorities.
    541. 

  541. 

  542.    Kernel Space                     User Space
    543. 

  543.  ===============================================================
    544. 

  544.    0(high) to  98(low)     user RT priority 99(high) to 1(low)
    545. 

  545.                            with SCHED_RR or SCHED_FIFO
    546. 

  546.  ---------------------------------------------------------------
    547. 

  547.   99                       sched_priority is not used in scheduling
    548. 

  548.                            decisions(it must be specified as 0)
    549. 

  549.  ---------------------------------------------------------------
    550. 

  550.  100(high) to 139(low)     user nice -20(high) to 19(low)
    551. 

  551.  ---------------------------------------------------------------
    552. 

  552.  140                       idle task priority
    553. 

  553.  ---------------------------------------------------------------
    554. 

  554. 

  555. The task states are:
    556. 

  556. 

  557.  R - running : wants to run, may not actually be running
    558. 

  558.  S - sleep   : process is waiting to be woken up (handles signals)
    559. 

  559.  D - disk sleep (uninterruptible sleep) : process must be woken up
    560. 

  560. 					(ignores signals)
    561. 

  561.  T - stopped : process suspended
    562. 

  562.  t - traced  : process is being traced (with something like gdb)
    563. 

  563.  Z - zombie  : process waiting to be cleaned up
    564. 

  564.  X - unknown
    565. 

  565. 

  566. 

  567. ftrace_enabled
    568. 

  568. --------------
    569. 

  569. 

  570. The following tracers (listed below) give different output
    571. 

  571. depending on whether or not the sysctl ftrace_enabled is set. To
    572. 

  572. set ftrace_enabled, one can either use the sysctl function or
    573. 

  573. set it via the proc file system interface.
    574. 

  574. 

  575.   sysctl kernel.ftrace_enabled=1
    576. 

  576. 

  577.  or
    578. 

  578. 

  579.   echo 1 > /proc/sys/kernel/ftrace_enabled
    580. 

  580. 

  581. To disable ftrace_enabled simply replace the '1' with '0' in the
    582. 

  582. above commands.
    583. 

  583. 

  584. When ftrace_enabled is set the tracers will also record the
    585. 

  585. functions that are within the trace. The descriptions of the
    586. 

  586. tracers will also show an example with ftrace enabled.
    587. 

  587. 

  588. 

  589. irqsoff
    590. 

  590. -------
    591. 

  591. 

  592. When interrupts are disabled, the CPU can not react to any other
    593. 

  593. external event (besides NMIs and SMIs). This prevents the timer
    594. 

  594. interrupt from triggering or the mouse interrupt from letting
    595. 

  595. the kernel know of a new mouse event. The result is a latency
    596. 

  596. with the reaction time.
    597. 

  597. 

  598. The irqsoff tracer tracks the time for which interrupts are
    599. 

  599. disabled. When a new maximum latency is hit, the tracer saves
    600. 

  600. the trace leading up to that latency point so that every time a
    601. 

  601. new maximum is reached, the old saved trace is discarded and the
    602. 

  602. new trace is saved.
    603. 

  603. 

  604. To reset the maximum, echo 0 into tracing_max_latency. Here is
    605. 

  605. an example:
    606. 

  606. 

  607.  # echo irqsoff > current_tracer
    608. 

  608.  # echo latency-format > trace_options
    609. 

  609.  # echo 0 > tracing_max_latency
    610. 

  610.  # echo 1 > tracing_enabled
    611. 

  611.  # ls -ltr
    612. 

  612.  [...]
    613. 

  613.  # echo 0 > tracing_enabled
    614. 

  614.  # cat trace
    615. 

  615. # tracer: irqsoff
    616. 

  616. #
    617. 

  617. irqsoff latency trace v1.1.5 on 2.6.26
    618. 

  618. --------------------------------------------------------------------
    619. 

  619.  latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    620. 

  620.     -----------------
    621. 

  621.     | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)
    622. 

  622.     -----------------
    623. 

  623.  => started at: sys_setpgid
    624. 

  624.  => ended at:   sys_setpgid
    625. 

  625. 

  626. #                _------=> CPU#
    627. 

  627. #               / _-----=> irqs-off
    628. 

  628. #              | / _----=> need-resched
    629. 

  629. #              || / _---=> hardirq/softirq
    630. 

  630. #              ||| / _--=> preempt-depth
    631. 

  631. #              |||| /
    632. 

  632. #              |||||     delay
    633. 

  633. #  cmd     pid ||||| time  |   caller
    634. 

  634. #     \   /    |||||   \   |   /
    635. 

  635.     bash-3730  1d...    0us : _write_lock_irq (sys_setpgid)
    636. 

  636.     bash-3730  1d..1    1us+: _write_unlock_irq (sys_setpgid)
    637. 

  637.     bash-3730  1d..2   14us : trace_hardirqs_on (sys_setpgid)
    638. 

  638. 

  639. 

  640. Here we see that that we had a latency of 12 microsecs (which is
    641. 

  641. very good). The _write_lock_irq in sys_setpgid disabled
    642. 

  642. interrupts. The difference between the 12 and the displayed
    643. 

  643. timestamp 14us occurred because the clock was incremented
    644. 

  644. between the time of recording the max latency and the time of
    645. 

  645. recording the function that had that latency.
    646. 

  646. 

  647. Note the above example had ftrace_enabled not set. If we set the
    648. 

  648. ftrace_enabled, we get a much larger output:
    649. 

  649. 

  650. # tracer: irqsoff
    651. 

  651. #
    652. 

  652. irqsoff latency trace v1.1.5 on 2.6.26-rc8
    653. 

  653. --------------------------------------------------------------------
    654. 

  654.  latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    655. 

  655.     -----------------
    656. 

  656.     | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0)
    657. 

  657.     -----------------
    658. 

  658.  => started at: __alloc_pages_internal
    659. 

  659.  => ended at:   __alloc_pages_internal
    660. 

  660. 

  661. #                _------=> CPU#
    662. 

  662. #               / _-----=> irqs-off
    663. 

  663. #              | / _----=> need-resched
    664. 

  664. #              || / _---=> hardirq/softirq
    665. 

  665. #              ||| / _--=> preempt-depth
    666. 

  666. #              |||| /
    667. 

  667. #              |||||     delay
    668. 

  668. #  cmd     pid ||||| time  |   caller
    669. 

  669. #     \   /    |||||   \   |   /
    670. 

  670.       ls-4339  0...1    0us+: get_page_from_freelist (__alloc_pages_internal)
    671. 

  671.       ls-4339  0d..1    3us : rmqueue_bulk (get_page_from_freelist)
    672. 

  672.       ls-4339  0d..1    3us : _spin_lock (rmqueue_bulk)
    673. 

  673.       ls-4339  0d..1    4us : add_preempt_count (_spin_lock)
    674. 

  674.       ls-4339  0d..2    4us : __rmqueue (rmqueue_bulk)
    675. 

  675.       ls-4339  0d..2    5us : __rmqueue_smallest (__rmqueue)
    676. 

  676.       ls-4339  0d..2    5us : __mod_zone_page_state (__rmqueue_smallest)
    677. 

  677.       ls-4339  0d..2    6us : __rmqueue (rmqueue_bulk)
    678. 

  678.       ls-4339  0d..2    6us : __rmqueue_smallest (__rmqueue)
    679. 

  679.       ls-4339  0d..2    7us : __mod_zone_page_state (__rmqueue_smallest)
    680. 

  680.       ls-4339  0d..2    7us : __rmqueue (rmqueue_bulk)
    681. 

  681.       ls-4339  0d..2    8us : __rmqueue_smallest (__rmqueue)
    682. 

  682. [...]
    683. 

  683.       ls-4339  0d..2   46us : __rmqueue_smallest (__rmqueue)
    684. 

  684.       ls-4339  0d..2   47us : __mod_zone_page_state (__rmqueue_smallest)
    685. 

  685.       ls-4339  0d..2   47us : __rmqueue (rmqueue_bulk)
    686. 

  686.       ls-4339  0d..2   48us : __rmqueue_smallest (__rmqueue)
    687. 

  687.       ls-4339  0d..2   48us : __mod_zone_page_state (__rmqueue_smallest)
    688. 

  688.       ls-4339  0d..2   49us : _spin_unlock (rmqueue_bulk)
    689. 

  689.       ls-4339  0d..2   49us : sub_preempt_count (_spin_unlock)
    690. 

  690.       ls-4339  0d..1   50us : get_page_from_freelist (__alloc_pages_internal)
    691. 

  691.       ls-4339  0d..2   51us : trace_hardirqs_on (__alloc_pages_internal)
    692. 

  692. 

  693. 

  694. 

  695. Here we traced a 50 microsecond latency. But we also see all the
    696. 

  696. functions that were called during that time. Note that by
    697. 

  697. enabling function tracing, we incur an added overhead. This
    698. 

  698. overhead may extend the latency times. But nevertheless, this
    699. 

  699. trace has provided some very helpful debugging information.
    700. 

  700. 

  701. 

  702. preemptoff
    703. 

  703. ----------
    704. 

  704. 

  705. When preemption is disabled, we may be able to receive
    706. 

  706. interrupts but the task cannot be preempted and a higher
    707. 

  707. priority task must wait for preemption to be enabled again
    708. 

  708. before it can preempt a lower priority task.
    709. 

  709. 

  710. The preemptoff tracer traces the places that disable preemption.
    711. 

  711. Like the irqsoff tracer, it records the maximum latency for
    712. 

  712. which preemption was disabled. The control of preemptoff tracer
    713. 

  713. is much like the irqsoff tracer.
    714. 

  714. 

  715.  # echo preemptoff > current_tracer
    716. 

  716.  # echo latency-format > trace_options
    717. 

  717.  # echo 0 > tracing_max_latency
    718. 

  718.  # echo 1 > tracing_enabled
    719. 

  719.  # ls -ltr
    720. 

  720.  [...]
    721. 

  721.  # echo 0 > tracing_enabled
    722. 

  722.  # cat trace
    723. 

  723. # tracer: preemptoff
    724. 

  724. #
    725. 

  725. preemptoff latency trace v1.1.5 on 2.6.26-rc8
    726. 

  726. --------------------------------------------------------------------
    727. 

  727.  latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    728. 

  728.     -----------------
    729. 

  729.     | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
    730. 

  730.     -----------------
    731. 

  731.  => started at: do_IRQ
    732. 

  732.  => ended at:   __do_softirq
    733. 

  733. 

  734. #                _------=> CPU#
    735. 

  735. #               / _-----=> irqs-off
    736. 

  736. #              | / _----=> need-resched
    737. 

  737. #              || / _---=> hardirq/softirq
    738. 

  738. #              ||| / _--=> preempt-depth
    739. 

  739. #              |||| /
    740. 

  740. #              |||||     delay
    741. 

  741. #  cmd     pid ||||| time  |   caller
    742. 

  742. #     \   /    |||||   \   |   /
    743. 

  743.     sshd-4261  0d.h.    0us+: irq_enter (do_IRQ)
    744. 

  744.     sshd-4261  0d.s.   29us : _local_bh_enable (__do_softirq)
    745. 

  745.     sshd-4261  0d.s1   30us : trace_preempt_on (__do_softirq)
    746. 

  746. 

  747. 

  748. This has some more changes. Preemption was disabled when an
    749. 

  749. interrupt came in (notice the 'h'), and was enabled while doing
    750. 

  750. a softirq. (notice the 's'). But we also see that interrupts
    751. 

  751. have been disabled when entering the preempt off section and
    752. 

  752. leaving it (the 'd'). We do not know if interrupts were enabled
    753. 

  753. in the mean time.
    754. 

  754. 

  755. # tracer: preemptoff
    756. 

  756. #
    757. 

  757. preemptoff latency trace v1.1.5 on 2.6.26-rc8
    758. 

  758. --------------------------------------------------------------------
    759. 

  759.  latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    760. 

  760.     -----------------
    761. 

  761.     | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
    762. 

  762.     -----------------
    763. 

  763.  => started at: remove_wait_queue
    764. 

  764.  => ended at:   __do_softirq
    765. 

  765. 

  766. #                _------=> CPU#
    767. 

  767. #               / _-----=> irqs-off
    768. 

  768. #              | / _----=> need-resched
    769. 

  769. #              || / _---=> hardirq/softirq
    770. 

  770. #              ||| / _--=> preempt-depth
    771. 

  771. #              |||| /
    772. 

  772. #              |||||     delay
    773. 

  773. #  cmd     pid ||||| time  |   caller
    774. 

  774. #     \   /    |||||   \   |   /
    775. 

  775.     sshd-4261  0d..1    0us : _spin_lock_irqsave (remove_wait_queue)
    776. 

  776.     sshd-4261  0d..1    1us : _spin_unlock_irqrestore (remove_wait_queue)
    777. 

  777.     sshd-4261  0d..1    2us : do_IRQ (common_interrupt)
    778. 

  778.     sshd-4261  0d..1    2us : irq_enter (do_IRQ)
    779. 

  779.     sshd-4261  0d..1    2us : idle_cpu (irq_enter)
    780. 

  780.     sshd-4261  0d..1    3us : add_preempt_count (irq_enter)
    781. 

  781.     sshd-4261  0d.h1    3us : idle_cpu (irq_enter)
    782. 

  782.     sshd-4261  0d.h.    4us : handle_fasteoi_irq (do_IRQ)
    783. 

  783. [...]
    784. 

  784.     sshd-4261  0d.h.   12us : add_preempt_count (_spin_lock)
    785. 

  785.     sshd-4261  0d.h1   12us : ack_ioapic_quirk_irq (handle_fasteoi_irq)
    786. 

  786.     sshd-4261  0d.h1   13us : move_native_irq (ack_ioapic_quirk_irq)
    787. 

  787.     sshd-4261  0d.h1   13us : _spin_unlock (handle_fasteoi_irq)
    788. 

  788.     sshd-4261  0d.h1   14us : sub_preempt_count (_spin_unlock)
    789. 

  789.     sshd-4261  0d.h1   14us : irq_exit (do_IRQ)
    790. 

  790.     sshd-4261  0d.h1   15us : sub_preempt_count (irq_exit)
    791. 

  791.     sshd-4261  0d..2   15us : do_softirq (irq_exit)
    792. 

  792.     sshd-4261  0d...   15us : __do_softirq (do_softirq)
    793. 

  793.     sshd-4261  0d...   16us : __local_bh_disable (__do_softirq)
    794. 

  794.     sshd-4261  0d...   16us+: add_preempt_count (__local_bh_disable)
    795. 

  795.     sshd-4261  0d.s4   20us : add_preempt_count (__local_bh_disable)
    796. 

  796.     sshd-4261  0d.s4   21us : sub_preempt_count (local_bh_enable)
    797. 

  797.     sshd-4261  0d.s5   21us : sub_preempt_count (local_bh_enable)
    798. 

  798. [...]
    799. 

  799.     sshd-4261  0d.s6   41us : add_preempt_count (__local_bh_disable)
    800. 

  800.     sshd-4261  0d.s6   42us : sub_preempt_count (local_bh_enable)
    801. 

  801.     sshd-4261  0d.s7   42us : sub_preempt_count (local_bh_enable)
    802. 

  802.     sshd-4261  0d.s5   43us : add_preempt_count (__local_bh_disable)
    803. 

  803.     sshd-4261  0d.s5   43us : sub_preempt_count (local_bh_enable_ip)
    804. 

  804.     sshd-4261  0d.s6   44us : sub_preempt_count (local_bh_enable_ip)
    805. 

  805.     sshd-4261  0d.s5   44us : add_preempt_count (__local_bh_disable)
    806. 

  806.     sshd-4261  0d.s5   45us : sub_preempt_count (local_bh_enable)
    807. 

  807. [...]
    808. 

  808.     sshd-4261  0d.s.   63us : _local_bh_enable (__do_softirq)
    809. 

  809.     sshd-4261  0d.s1   64us : trace_preempt_on (__do_softirq)
    810. 

  810. 

  811. 

  812. The above is an example of the preemptoff trace with
    813. 

  813. ftrace_enabled set. Here we see that interrupts were disabled
    814. 

  814. the entire time. The irq_enter code lets us know that we entered
    815. 

  815. an interrupt 'h'. Before that, the functions being traced still
    816. 

  816. show that it is not in an interrupt, but we can see from the
    817. 

  817. functions themselves that this is not the case.
    818. 

  818. 

  819. Notice that __do_softirq when called does not have a
    820. 

  820. preempt_count. It may seem that we missed a preempt enabling.
    821. 

  821. What really happened is that the preempt count is held on the
    822. 

  822. thread's stack and we switched to the softirq stack (4K stacks
    823. 

  823. in effect). The code does not copy the preempt count, but
    824. 

  824. because interrupts are disabled, we do not need to worry about
    825. 

  825. it. Having a tracer like this is good for letting people know
    826. 

  826. what really happens inside the kernel.
    827. 

  827. 

  828. 

  829. preemptirqsoff
    830. 

  830. --------------
    831. 

  831. 

  832. Knowing the locations that have interrupts disabled or
    833. 

  833. preemption disabled for the longest times is helpful. But
    834. 

  834. sometimes we would like to know when either preemption and/or
    835. 

  835. interrupts are disabled.
    836. 

  836. 

  837. Consider the following code:
    838. 

  838. 

  839.     local_irq_disable();
    840. 

  840.     call_function_with_irqs_off();
    841. 

  841.     preempt_disable();
    842. 

  842.     call_function_with_irqs_and_preemption_off();
    843. 

  843.     local_irq_enable();
    844. 

  844.     call_function_with_preemption_off();
    845. 

  845.     preempt_enable();
    846. 

  846. 

  847. The irqsoff tracer will record the total length of
    848. 

  848. call_function_with_irqs_off() and
    849. 

  849. call_function_with_irqs_and_preemption_off().
    850. 

  850. 

  851. The preemptoff tracer will record the total length of
    852. 

  852. call_function_with_irqs_and_preemption_off() and
    853. 

  853. call_function_with_preemption_off().
    854. 

  854. 

  855. But neither will trace the time that interrupts and/or
    856. 

  856. preemption is disabled. This total time is the time that we can
    857. 

  857. not schedule. To record this time, use the preemptirqsoff
    858. 

  858. tracer.
    859. 

  859. 

  860. Again, using this trace is much like the irqsoff and preemptoff
    861. 

  861. tracers.
    862. 

  862. 

  863.  # echo preemptirqsoff > current_tracer
    864. 

  864.  # echo latency-format > trace_options
    865. 

  865.  # echo 0 > tracing_max_latency
    866. 

  866.  # echo 1 > tracing_enabled
    867. 

  867.  # ls -ltr
    868. 

  868.  [...]
    869. 

  869.  # echo 0 > tracing_enabled
    870. 

  870.  # cat trace
    871. 

  871. # tracer: preemptirqsoff
    872. 

  872. #
    873. 

  873. preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
    874. 

  874. --------------------------------------------------------------------
    875. 

  875.  latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    876. 

  876.     -----------------
    877. 

  877.     | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0)
    878. 

  878.     -----------------
    879. 

  879.  => started at: apic_timer_interrupt
    880. 

  880.  => ended at:   __do_softirq
    881. 

  881. 

  882. #                _------=> CPU#
    883. 

  883. #               / _-----=> irqs-off
    884. 

  884. #              | / _----=> need-resched
    885. 

  885. #              || / _---=> hardirq/softirq
    886. 

  886. #              ||| / _--=> preempt-depth
    887. 

  887. #              |||| /
    888. 

  888. #              |||||     delay
    889. 

  889. #  cmd     pid ||||| time  |   caller
    890. 

  890. #     \   /    |||||   \   |   /
    891. 

  891.       ls-4860  0d...    0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
    892. 

  892.       ls-4860  0d.s.  294us : _local_bh_enable (__do_softirq)
    893. 

  893.       ls-4860  0d.s1  294us : trace_preempt_on (__do_softirq)
    894. 

  894. 

  895. 

  896. 

  897. The trace_hardirqs_off_thunk is called from assembly on x86 when
    898. 

  898. interrupts are disabled in the assembly code. Without the
    899. 

  899. function tracing, we do not know if interrupts were enabled
    900. 

  900. within the preemption points. We do see that it started with
    901. 

  901. preemption enabled.
    902. 

  902. 

  903. Here is a trace with ftrace_enabled set:
    904. 

  904. 

  905. 

  906. # tracer: preemptirqsoff
    907. 

  907. #
    908. 

  908. preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
    909. 

  909. --------------------------------------------------------------------
    910. 

  910.  latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    911. 

  911.     -----------------
    912. 

  912.     | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
    913. 

  913.     -----------------
    914. 

  914.  => started at: write_chan
    915. 

  915.  => ended at:   __do_softirq
    916. 

  916. 

  917. #                _------=> CPU#
    918. 

  918. #               / _-----=> irqs-off
    919. 

  919. #              | / _----=> need-resched
    920. 

  920. #              || / _---=> hardirq/softirq
    921. 

  921. #              ||| / _--=> preempt-depth
    922. 

  922. #              |||| /
    923. 

  923. #              |||||     delay
    924. 

  924. #  cmd     pid ||||| time  |   caller
    925. 

  925. #     \   /    |||||   \   |   /
    926. 

  926.       ls-4473  0.N..    0us : preempt_schedule (write_chan)
    927. 

  927.       ls-4473  0dN.1    1us : _spin_lock (schedule)
    928. 

  928.       ls-4473  0dN.1    2us : add_preempt_count (_spin_lock)
    929. 

  929.       ls-4473  0d..2    2us : put_prev_task_fair (schedule)
    930. 

  930. [...]
    931. 

  931.       ls-4473  0d..2   13us : set_normalized_timespec (ktime_get_ts)
    932. 

  932.       ls-4473  0d..2   13us : __switch_to (schedule)
    933. 

  933.     sshd-4261  0d..2   14us : finish_task_switch (schedule)
    934. 

  934.     sshd-4261  0d..2   14us : _spin_unlock_irq (finish_task_switch)
    935. 

  935.     sshd-4261  0d..1   15us : add_preempt_count (_spin_lock_irqsave)
    936. 

  936.     sshd-4261  0d..2   16us : _spin_unlock_irqrestore (hrtick_set)
    937. 

  937.     sshd-4261  0d..2   16us : do_IRQ (common_interrupt)
    938. 

  938.     sshd-4261  0d..2   17us : irq_enter (do_IRQ)
    939. 

  939.     sshd-4261  0d..2   17us : idle_cpu (irq_enter)
    940. 

  940.     sshd-4261  0d..2   18us : add_preempt_count (irq_enter)
    941. 

  941.     sshd-4261  0d.h2   18us : idle_cpu (irq_enter)
    942. 

  942.     sshd-4261  0d.h.   18us : handle_fasteoi_irq (do_IRQ)
    943. 

  943.     sshd-4261  0d.h.   19us : _spin_lock (handle_fasteoi_irq)
    944. 

  944.     sshd-4261  0d.h.   19us : add_preempt_count (_spin_lock)
    945. 

  945.     sshd-4261  0d.h1   20us : _spin_unlock (handle_fasteoi_irq)
    946. 

  946.     sshd-4261  0d.h1   20us : sub_preempt_count (_spin_unlock)
    947. 

  947. [...]
    948. 

  948.     sshd-4261  0d.h1   28us : _spin_unlock (handle_fasteoi_irq)
    949. 

  949.     sshd-4261  0d.h1   29us : sub_preempt_count (_spin_unlock)
    950. 

  950.     sshd-4261  0d.h2   29us : irq_exit (do_IRQ)
    951. 

  951.     sshd-4261  0d.h2   29us : sub_preempt_count (irq_exit)
    952. 

  952.     sshd-4261  0d..3   30us : do_softirq (irq_exit)
    953. 

  953.     sshd-4261  0d...   30us : __do_softirq (do_softirq)
    954. 

  954.     sshd-4261  0d...   31us : __local_bh_disable (__do_softirq)
    955. 

  955.     sshd-4261  0d...   31us+: add_preempt_count (__local_bh_disable)
    956. 

  956.     sshd-4261  0d.s4   34us : add_preempt_count (__local_bh_disable)
    957. 

  957. [...]
    958. 

  958.     sshd-4261  0d.s3   43us : sub_preempt_count (local_bh_enable_ip)
    959. 

  959.     sshd-4261  0d.s4   44us : sub_preempt_count (local_bh_enable_ip)
    960. 

  960.     sshd-4261  0d.s3   44us : smp_apic_timer_interrupt (apic_timer_interrupt)
    961. 

  961.     sshd-4261  0d.s3   45us : irq_enter (smp_apic_timer_interrupt)
    962. 

  962.     sshd-4261  0d.s3   45us : idle_cpu (irq_enter)
    963. 

  963.     sshd-4261  0d.s3   46us : add_preempt_count (irq_enter)
    964. 

  964.     sshd-4261  0d.H3   46us : idle_cpu (irq_enter)
    965. 

  965.     sshd-4261  0d.H3   47us : hrtimer_interrupt (smp_apic_timer_interrupt)
    966. 

  966.     sshd-4261  0d.H3   47us : ktime_get (hrtimer_interrupt)
    967. 

  967. [...]
    968. 

  968.     sshd-4261  0d.H3   81us : tick_program_event (hrtimer_interrupt)
    969. 

  969.     sshd-4261  0d.H3   82us : ktime_get (tick_program_event)
    970. 

  970.     sshd-4261  0d.H3   82us : ktime_get_ts (ktime_get)
    971. 

  971.     sshd-4261  0d.H3   83us : getnstimeofday (ktime_get_ts)
    972. 

  972.     sshd-4261  0d.H3   83us : set_normalized_timespec (ktime_get_ts)
    973. 

  973.     sshd-4261  0d.H3   84us : clockevents_program_event (tick_program_event)
    974. 

  974.     sshd-4261  0d.H3   84us : lapic_next_event (clockevents_program_event)
    975. 

  975.     sshd-4261  0d.H3   85us : irq_exit (smp_apic_timer_interrupt)
    976. 

  976.     sshd-4261  0d.H3   85us : sub_preempt_count (irq_exit)
    977. 

  977.     sshd-4261  0d.s4   86us : sub_preempt_count (irq_exit)
    978. 

  978.     sshd-4261  0d.s3   86us : add_preempt_count (__local_bh_disable)
    979. 

  979. [...]
    980. 

  980.     sshd-4261  0d.s1   98us : sub_preempt_count (net_rx_action)
    981. 

  981.     sshd-4261  0d.s.   99us : add_preempt_count (_spin_lock_irq)
    982. 

  982.     sshd-4261  0d.s1   99us+: _spin_unlock_irq (run_timer_softirq)
    983. 

  983.     sshd-4261  0d.s.  104us : _local_bh_enable (__do_softirq)
    984. 

  984.     sshd-4261  0d.s.  104us : sub_preempt_count (_local_bh_enable)
    985. 

  985.     sshd-4261  0d.s.  105us : _local_bh_enable (__do_softirq)
    986. 

  986.     sshd-4261  0d.s1  105us : trace_preempt_on (__do_softirq)
    987. 

  987. 

  988. 

  989. This is a very interesting trace. It started with the preemption
    990. 

  990. of the ls task. We see that the task had the "need_resched" bit
    991. 

  991. set via the 'N' in the trace.  Interrupts were disabled before
    992. 

  992. the spin_lock at the beginning of the trace. We see that a
    993. 

  993. schedule took place to run sshd.  When the interrupts were
    994. 

  994. enabled, we took an interrupt. On return from the interrupt
    995. 

  995. handler, the softirq ran. We took another interrupt while
    996. 

  996. running the softirq as we see from the capital 'H'.
    997. 

  997. 

  998. 

  999. wakeup
    1000. 

  1000. ------
    1001. 

  1001. 

  1002. In a Real-Time environment it is very important to know the
    1003. 

  1003. wakeup time it takes for the highest priority task that is woken
    1004. 

  1004. up to the time that it executes. This is also known as "schedule
    1005. 

  1005. latency". I stress the point that this is about RT tasks. It is
    1006. 

  1006. also important to know the scheduling latency of non-RT tasks,
    1007. 

  1007. but the average schedule latency is better for non-RT tasks.
    1008. 

  1008. Tools like LatencyTop are more appropriate for such
    1009. 

  1009. measurements.
    1010. 

  1010. 

  1011. Real-Time environments are interested in the worst case latency.
    1012. 

  1012. That is the longest latency it takes for something to happen,
    1013. 

  1013. and not the average. We can have a very fast scheduler that may
    1014. 

  1014. only have a large latency once in a while, but that would not
    1015. 

  1015. work well with Real-Time tasks.  The wakeup tracer was designed
    1016. 

  1016. to record the worst case wakeups of RT tasks. Non-RT tasks are
    1017. 

  1017. not recorded because the tracer only records one worst case and
    1018. 

  1018. tracing non-RT tasks that are unpredictable will overwrite the
    1019. 

  1019. worst case latency of RT tasks.
    1020. 

  1020. 

  1021. Since this tracer only deals with RT tasks, we will run this
    1022. 

  1022. slightly differently than we did with the previous tracers.
    1023. 

  1023. Instead of performing an 'ls', we will run 'sleep 1' under
    1024. 

  1024. 'chrt' which changes the priority of the task.
    1025. 

  1025. 

  1026.  # echo wakeup > current_tracer
    1027. 

  1027.  # echo latency-format > trace_options
    1028. 

  1028.  # echo 0 > tracing_max_latency
    1029. 

  1029.  # echo 1 > tracing_enabled
    1030. 

  1030.  # chrt -f 5 sleep 1
    1031. 

  1031.  # echo 0 > tracing_enabled
    1032. 

  1032.  # cat trace
    1033. 

  1033. # tracer: wakeup
    1034. 

  1034. #
    1035. 

  1035. wakeup latency trace v1.1.5 on 2.6.26-rc8
    1036. 

  1036. --------------------------------------------------------------------
    1037. 

  1037.  latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    1038. 

  1038.     -----------------
    1039. 

  1039.     | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5)
    1040. 

  1040.     -----------------
    1041. 

  1041. 

  1042. #                _------=> CPU#
    1043. 

  1043. #               / _-----=> irqs-off
    1044. 

  1044. #              | / _----=> need-resched
    1045. 

  1045. #              || / _---=> hardirq/softirq
    1046. 

  1046. #              ||| / _--=> preempt-depth
    1047. 

  1047. #              |||| /
    1048. 

  1048. #              |||||     delay
    1049. 

  1049. #  cmd     pid ||||| time  |   caller
    1050. 

  1050. #     \   /    |||||   \   |   /
    1051. 

  1051.   <idle>-0     1d.h4    0us+: try_to_wake_up (wake_up_process)
    1052. 

  1052.   <idle>-0     1d..4    4us : schedule (cpu_idle)
    1053. 

  1053. 

  1054. 

  1055. Running this on an idle system, we see that it only took 4
    1056. 

  1056. microseconds to perform the task switch.  Note, since the trace
    1057. 

  1057. marker in the schedule is before the actual "switch", we stop
    1058. 

  1058. the tracing when the recorded task is about to schedule in. This
    1059. 

  1059. may change if we add a new marker at the end of the scheduler.
    1060. 

  1060. 

  1061. Notice that the recorded task is 'sleep' with the PID of 4901
    1062. 

  1062. and it has an rt_prio of 5. This priority is user-space priority
    1063. 

  1063. and not the internal kernel priority. The policy is 1 for
    1064. 

  1064. SCHED_FIFO and 2 for SCHED_RR.
    1065. 

  1065. 

  1066. Doing the same with chrt -r 5 and ftrace_enabled set.
    1067. 

  1067. 

  1068. # tracer: wakeup
    1069. 

  1069. #
    1070. 

  1070. wakeup latency trace v1.1.5 on 2.6.26-rc8
    1071. 

  1071. --------------------------------------------------------------------
    1072. 

  1072.  latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    1073. 

  1073.     -----------------
    1074. 

  1074.     | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5)
    1075. 

  1075.     -----------------
    1076. 

  1076. 

  1077. #                _------=> CPU#
    1078. 

  1078. #               / _-----=> irqs-off
    1079. 

  1079. #              | / _----=> need-resched
    1080. 

  1080. #              || / _---=> hardirq/softirq
    1081. 

  1081. #              ||| / _--=> preempt-depth
    1082. 

  1082. #              |||| /
    1083. 

  1083. #              |||||     delay
    1084. 

  1084. #  cmd     pid ||||| time  |   caller
    1085. 

  1085. #     \   /    |||||   \   |   /
    1086. 

  1086. ksoftirq-7     1d.H3    0us : try_to_wake_up (wake_up_process)
    1087. 

  1087. ksoftirq-7     1d.H4    1us : sub_preempt_count (marker_probe_cb)
    1088. 

  1088. ksoftirq-7     1d.H3    2us : check_preempt_wakeup (try_to_wake_up)
    1089. 

  1089. ksoftirq-7     1d.H3    3us : update_curr (check_preempt_wakeup)
    1090. 

  1090. ksoftirq-7     1d.H3    4us : calc_delta_mine (update_curr)
    1091. 

  1091. ksoftirq-7     1d.H3    5us : __resched_task (check_preempt_wakeup)
    1092. 

  1092. ksoftirq-7     1d.H3    6us : task_wake_up_rt (try_to_wake_up)
    1093. 

  1093. ksoftirq-7     1d.H3    7us : _spin_unlock_irqrestore (try_to_wake_up)
    1094. 

  1094. [...]
    1095. 

  1095. ksoftirq-7     1d.H2   17us : irq_exit (smp_apic_timer_interrupt)
    1096. 

  1096. ksoftirq-7     1d.H2   18us : sub_preempt_count (irq_exit)
    1097. 

  1097. ksoftirq-7     1d.s3   19us : sub_preempt_count (irq_exit)
    1098. 

  1098. ksoftirq-7     1..s2   20us : rcu_process_callbacks (__do_softirq)
    1099. 

  1099. [...]
    1100. 

  1100. ksoftirq-7     1..s2   26us : __rcu_process_callbacks (rcu_process_callbacks)
    1101. 

  1101. ksoftirq-7     1d.s2   27us : _local_bh_enable (__do_softirq)
    1102. 

  1102. ksoftirq-7     1d.s2   28us : sub_preempt_count (_local_bh_enable)
    1103. 

  1103. ksoftirq-7     1.N.3   29us : sub_preempt_count (ksoftirqd)
    1104. 

  1104. ksoftirq-7     1.N.2   30us : _cond_resched (ksoftirqd)
    1105. 

  1105. ksoftirq-7     1.N.2   31us : __cond_resched (_cond_resched)
    1106. 

  1106. ksoftirq-7     1.N.2   32us : add_preempt_count (__cond_resched)
    1107. 

  1107. ksoftirq-7     1.N.2   33us : schedule (__cond_resched)
    1108. 

  1108. ksoftirq-7     1.N.2   33us : add_preempt_count (schedule)
    1109. 

  1109. ksoftirq-7     1.N.3   34us : hrtick_clear (schedule)
    1110. 

  1110. ksoftirq-7     1dN.3   35us : _spin_lock (schedule)
    1111. 

  1111. ksoftirq-7     1dN.3   36us : add_preempt_count (_spin_lock)
    1112. 

  1112. ksoftirq-7     1d..4   37us : put_prev_task_fair (schedule)
    1113. 

  1113. ksoftirq-7     1d..4   38us : update_curr (put_prev_task_fair)
    1114. 

  1114. [...]
    1115. 

  1115. ksoftirq-7     1d..5   47us : _spin_trylock (tracing_record_cmdline)
    1116. 

  1116. ksoftirq-7     1d..5   48us : add_preempt_count (_spin_trylock)
    1117. 

  1117. ksoftirq-7     1d..6   49us : _spin_unlock (tracing_record_cmdline)
    1118. 

  1118. ksoftirq-7     1d..6   49us : sub_preempt_count (_spin_unlock)
    1119. 

  1119. ksoftirq-7     1d..4   50us : schedule (__cond_resched)
    1120. 

  1120. 

  1121. The interrupt went off while running ksoftirqd. This task runs
    1122. 

  1122. at SCHED_OTHER. Why did not we see the 'N' set early? This may
    1123. 

  1123. be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K
    1124. 

  1124. stacks configured, the interrupt and softirq run with their own
    1125. 

  1125. stack. Some information is held on the top of the task's stack
    1126. 

  1126. (need_resched and preempt_count are both stored there). The
    1127. 

  1127. setting of the NEED_RESCHED bit is done directly to the task's
    1128. 

  1128. stack, but the reading of the NEED_RESCHED is done by looking at
    1129. 

  1129. the current stack, which in this case is the stack for the hard
    1130. 

  1130. interrupt. This hides the fact that NEED_RESCHED has been set.
    1131. 

  1131. We do not see the 'N' until we switch back to the task's
    1132. 

  1132. assigned stack.
    1133. 

  1133. 

  1134. function
    1135. 

  1135. --------
    1136. 

  1136. 

  1137. This tracer is the function tracer. Enabling the function tracer
    1138. 

  1138. can be done from the debug file system. Make sure the
    1139. 

  1139. ftrace_enabled is set; otherwise this tracer is a nop.
    1140. 

  1140. 

  1141.  # sysctl kernel.ftrace_enabled=1
    1142. 

  1142.  # echo function > current_tracer
    1143. 

  1143.  # echo 1 > tracing_enabled
    1144. 

  1144.  # usleep 1
    1145. 

  1145.  # echo 0 > tracing_enabled
    1146. 

  1146.  # cat trace
    1147. 

  1147. # tracer: function
    1148. 

  1148. #
    1149. 

  1149. #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
    1150. 

  1150. #              | |      |          |         |
    1151. 

  1151.             bash-4003  [00]   123.638713: finish_task_switch <-schedule
    1152. 

  1152.             bash-4003  [00]   123.638714: _spin_unlock_irq <-finish_task_switch
    1153. 

  1153.             bash-4003  [00]   123.638714: sub_preempt_count <-_spin_unlock_irq
    1154. 

  1154.             bash-4003  [00]   123.638715: hrtick_set <-schedule
    1155. 

  1155.             bash-4003  [00]   123.638715: _spin_lock_irqsave <-hrtick_set
    1156. 

  1156.             bash-4003  [00]   123.638716: add_preempt_count <-_spin_lock_irqsave
    1157. 

  1157.             bash-4003  [00]   123.638716: _spin_unlock_irqrestore <-hrtick_set
    1158. 

  1158.             bash-4003  [00]   123.638717: sub_preempt_count <-_spin_unlock_irqrestore
    1159. 

  1159.             bash-4003  [00]   123.638717: hrtick_clear <-hrtick_set
    1160. 

  1160.             bash-4003  [00]   123.638718: sub_preempt_count <-schedule
    1161. 

  1161.             bash-4003  [00]   123.638718: sub_preempt_count <-preempt_schedule
    1162. 

  1162.             bash-4003  [00]   123.638719: wait_for_completion <-__stop_machine_run
    1163. 

  1163.             bash-4003  [00]   123.638719: wait_for_common <-wait_for_completion
    1164. 

  1164.             bash-4003  [00]   123.638720: _spin_lock_irq <-wait_for_common
    1165. 

  1165.             bash-4003  [00]   123.638720: add_preempt_count <-_spin_lock_irq
    1166. 

  1166. [...]
    1167. 

  1167. 

  1168. 

  1169. Note: function tracer uses ring buffers to store the above
    1170. 

  1170. entries. The newest data may overwrite the oldest data.
    1171. 

  1171. Sometimes using echo to stop the trace is not sufficient because
    1172. 

  1172. the tracing could have overwritten the data that you wanted to
    1173. 

  1173. record. For this reason, it is sometimes better to disable
    1174. 

  1174. tracing directly from a program. This allows you to stop the
    1175. 

  1175. tracing at the point that you hit the part that you are
    1176. 

  1176. interested in. To disable the tracing directly from a C program,
    1177. 

  1177. something like following code snippet can be used:
    1178. 

  1178. 

  1179. int trace_fd;
    1180. 

  1180. [...]
    1181. 

  1181. int main(int argc, char *argv[]) {
    1182. 

  1182. 	[...]
    1183. 

  1183. 	trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY);
    1184. 

  1184. 	[...]
    1185. 

  1185. 	if (condition_hit()) {
    1186. 

  1186. 		write(trace_fd, "0", 1);
    1187. 

  1187. 	}
    1188. 

  1188. 	[...]
    1189. 

  1189. }
    1190. 

  1190. 

  1191. 

  1192. Single thread tracing
    1193. 

  1193. ---------------------
    1194. 

  1194. 

  1195. By writing into set_ftrace_pid you can trace a
    1196. 

  1196. single thread. For example:
    1197. 

  1197. 

  1198. # cat set_ftrace_pid
    1199. 

  1199. no pid
    1200. 

  1200. # echo 3111 > set_ftrace_pid
    1201. 

  1201. # cat set_ftrace_pid
    1202. 

  1202. 3111
    1203. 

  1203. # echo function > current_tracer
    1204. 

  1204. # cat trace | head
    1205. 

  1205.  # tracer: function
    1206. 

  1206.  #
    1207. 

  1207.  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
    1208. 

  1208.  #              | |       |          |         |
    1209. 

  1209.      yum-updatesd-3111  [003]  1637.254676: finish_task_switch <-thread_return
    1210. 

  1210.      yum-updatesd-3111  [003]  1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
    1211. 

  1211.      yum-updatesd-3111  [003]  1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
    1212. 

  1212.      yum-updatesd-3111  [003]  1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
    1213. 

  1213.      yum-updatesd-3111  [003]  1637.254685: fget_light <-do_sys_poll
    1214. 

  1214.      yum-updatesd-3111  [003]  1637.254686: pipe_poll <-do_sys_poll
    1215. 

  1215. # echo -1 > set_ftrace_pid
    1216. 

  1216. # cat trace |head
    1217. 

  1217.  # tracer: function
    1218. 

  1218.  #
    1219. 

  1219.  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
    1220. 

  1220.  #              | |       |          |         |
    1221. 

  1221.  ##### CPU 3 buffer started ####
    1222. 

  1222.      yum-updatesd-3111  [003]  1701.957688: free_poll_entry <-poll_freewait
    1223. 

  1223.      yum-updatesd-3111  [003]  1701.957689: remove_wait_queue <-free_poll_entry
    1224. 

  1224.      yum-updatesd-3111  [003]  1701.957691: fput <-free_poll_entry
    1225. 

  1225.      yum-updatesd-3111  [003]  1701.957692: audit_syscall_exit <-sysret_audit
    1226. 

  1226.      yum-updatesd-3111  [003]  1701.957693: path_put <-audit_syscall_exit
    1227. 

  1227. 

  1228. If you want to trace a function when executing, you could use
    1229. 

  1229. something like this simple program:
    1230. 

  1230. 

  1231. #include <stdio.h>
    1232. 

  1232. #include <stdlib.h>
    1233. 

  1233. #include <sys/types.h>
    1234. 

  1234. #include <sys/stat.h>
    1235. 

  1235. #include <fcntl.h>
    1236. 

  1236. #include <unistd.h>
    1237. 

  1237. #include <string.h>
    1238. 

  1238. 

  1239. #define _STR(x) #x
    1240. 

  1240. #define STR(x) _STR(x)
    1241. 

  1241. #define MAX_PATH 256
    1242. 

  1242. 

  1243. const char *find_debugfs(void)
    1244. 

  1244. {
    1245. 

  1245.        static char debugfs[MAX_PATH+1];
    1246. 

  1246.        static int debugfs_found;
    1247. 

  1247.        char type[100];
    1248. 

  1248.        FILE *fp;
    1249. 

  1249. 

  1250.        if (debugfs_found)
    1251. 

  1251.                return debugfs;
    1252. 

  1252. 

  1253.        if ((fp = fopen("/proc/mounts","r")) == NULL) {
    1254. 

  1254.                perror("/proc/mounts");
    1255. 

  1255.                return NULL;
    1256. 

  1256.        }
    1257. 

  1257. 

  1258.        while (fscanf(fp, "%*s %"
    1259. 

  1259.                      STR(MAX_PATH)
    1260. 

  1260.                      "s %99s %*s %*d %*d\n",
    1261. 

  1261.                      debugfs, type) == 2) {
    1262. 

  1262.                if (strcmp(type, "debugfs") == 0)
    1263. 

  1263.                        break;
    1264. 

  1264.        }
    1265. 

  1265.        fclose(fp);
    1266. 

  1266. 

  1267.        if (strcmp(type, "debugfs") != 0) {
    1268. 

  1268.                fprintf(stderr, "debugfs not mounted");
    1269. 

  1269.                return NULL;
    1270. 

  1270.        }
    1271. 

  1271. 

  1272.        strcat(debugfs, "/tracing/");
    1273. 

  1273.        debugfs_found = 1;
    1274. 

  1274. 

  1275.        return debugfs;
    1276. 

  1276. }
    1277. 

  1277. 

  1278. const char *tracing_file(const char *file_name)
    1279. 

  1279. {
    1280. 

  1280.        static char trace_file[MAX_PATH+1];
    1281. 

  1281.        snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
    1282. 

  1282.        return trace_file;
    1283. 

  1283. }
    1284. 

  1284. 

  1285. int main (int argc, char **argv)
    1286. 

  1286. {
    1287. 

  1287.         if (argc < 1)
    1288. 

  1288.                 exit(-1);
    1289. 

  1289. 

  1290.         if (fork() > 0) {
    1291. 

  1291.                 int fd, ffd;
    1292. 

  1292.                 char line[64];
    1293. 

  1293.                 int s;
    1294. 

  1294. 

  1295.                 ffd = open(tracing_file("current_tracer"), O_WRONLY);
    1296. 

  1296.                 if (ffd < 0)
    1297. 

  1297.                         exit(-1);
    1298. 

  1298.                 write(ffd, "nop", 3);
    1299. 

  1299. 

  1300.                 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
    1301. 

  1301.                 s = sprintf(line, "%d\n", getpid());
    1302. 

  1302.                 write(fd, line, s);
    1303. 

  1303. 

  1304.                 write(ffd, "function", 8);
    1305. 

  1305. 

  1306.                 close(fd);
    1307. 

  1307.                 close(ffd);
    1308. 

  1308. 

  1309.                 execvp(argv[1], argv+1);
    1310. 

  1310.         }
    1311. 

  1311. 

  1312.         return 0;
    1313. 

  1313. }
    1314. 

  1314. 

  1315. 

  1316. hw-branch-tracer (x86 only)
    1317. 

  1317. ---------------------------
    1318. 

  1318. 

  1319. This tracer uses the x86 last branch tracing hardware feature to
    1320. 

  1320. collect a branch trace on all cpus with relatively low overhead.
    1321. 

  1321. 

  1322. The tracer uses a fixed-size circular buffer per cpu and only
    1323. 

  1323. traces ring 0 branches. The trace file dumps that buffer in the
    1324. 

  1324. following format:
    1325. 

  1325. 

  1326. # tracer: hw-branch-tracer
    1327. 

  1327. #
    1328. 

  1328. # CPU#        TO  <-  FROM
    1329. 

  1329.    0  scheduler_tick+0xb5/0x1bf	  <-  task_tick_idle+0x5/0x6
    1330. 

  1330.    2  run_posix_cpu_timers+0x2b/0x72a	  <-  run_posix_cpu_timers+0x25/0x72a
    1331. 

  1331.    0  scheduler_tick+0x139/0x1bf	  <-  scheduler_tick+0xed/0x1bf
    1332. 

  1332.    0  scheduler_tick+0x17c/0x1bf	  <-  scheduler_tick+0x148/0x1bf
    1333. 

  1333.    2  run_posix_cpu_timers+0x9e/0x72a	  <-  run_posix_cpu_timers+0x5e/0x72a
    1334. 

  1334.    0  scheduler_tick+0x1b6/0x1bf	  <-  scheduler_tick+0x1aa/0x1bf
    1335. 

  1335. 

  1336. 

  1337. The tracer may be used to dump the trace for the oops'ing cpu on
    1338. 

  1338. a kernel oops into the system log. To enable this,
    1339. 

  1339. ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
    1340. 

  1340. can either use the sysctl function or set it via the proc system
    1341. 

  1341. interface.
    1342. 

  1342. 

  1343.   sysctl kernel.ftrace_dump_on_oops=n
    1344. 

  1344. 

  1345. or
    1346. 

  1346. 

  1347.   echo n > /proc/sys/kernel/ftrace_dump_on_oops
    1348. 

  1348. 

  1349. If n = 1, ftrace will dump buffers of all CPUs, if n = 2 ftrace will
    1350. 

  1350. only dump the buff…
    1351.