aboutsummaryrefslogtreecommitdiffstats
path: root/Documentation
diff options
context:
space:
mode:
authorFrederic Weisbecker <fweisbec@gmail.com>2009-02-18 00:35:34 -0500
committerIngo Molnar <mingo@elte.hu>2009-02-19 06:33:21 -0500
commit985ec20ad531f2641ab9d5193e37891fe959fc7d (patch)
tree64a5e774ad60dbb32af4450bf4d6802d969f14b0 /Documentation
parentd1f9cbd78841f1a797c77e9117e4882f932c2ef6 (diff)
tracing/function-graph-tracer: provide documentation for the function graph tracer
Update documentation for the function graph tracer. Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: Ingo Molnar <mingo@elte.hu>
Diffstat (limited to 'Documentation')
-rw-r--r--Documentation/ftrace.txt226
1 files changed, 226 insertions, 0 deletions
diff --git a/Documentation/ftrace.txt b/Documentation/ftrace.txt
index 758fb42a1b68..055bcd2992da 100644
--- a/Documentation/ftrace.txt
+++ b/Documentation/ftrace.txt
@@ -129,6 +129,10 @@ of ftrace. Here is a list of some of the key files:
129 129
130 set_ftrace_pid: Have the function tracer only trace a single thread. 130 set_ftrace_pid: Have the function tracer only trace a single thread.
131 131
132 set_graph_function: Select the function where the trace have to start
133 with the function graph tracer (See the section
134 "dynamic ftrace" for more details).
135
132 available_filter_functions: This lists the functions that ftrace 136 available_filter_functions: This lists the functions that ftrace
133 has processed and can trace. These are the function 137 has processed and can trace. These are the function
134 names that you can pass to "set_ftrace_filter" or 138 names that you can pass to "set_ftrace_filter" or
@@ -143,6 +147,12 @@ Here is the list of current tracers that may be configured.
143 147
144 function - function tracer that uses mcount to trace all functions. 148 function - function tracer that uses mcount to trace all functions.
145 149
150 function_graph_tracer - similar to the function tracer except that the
151 function tracer probes the functions on their entry whereas the
152 function graph tracer traces on both entry and exit of the
153 functions. It then provides the ability to draw a graph of
154 function calls like a primitive C code source.
155
146 sched_switch - traces the context switches between tasks. 156 sched_switch - traces the context switches between tasks.
147 157
148 irqsoff - traces the areas that disable interrupts and saves 158 irqsoff - traces the areas that disable interrupts and saves
@@ -1226,6 +1236,163 @@ kernel module:
1226[...] 1236[...]
1227 1237
1228 1238
1239function graph tracer
1240---------------------------
1241
1242This tracer is similar to the function tracer except that it probes
1243a function on its entry and its exit.
1244This is done by setting a dynamically allocated stack of return addresses on each
1245task_struct. Then the tracer overwrites the return address of each function traced
1246to set a custom probe. Thus the original return address is stored on the stack of return
1247address in the task_struct.
1248
1249Probing on both extremities of a function leads to special features such as
1250
1251_ measure of function's time execution
1252_ having a reliable call stack to draw function calls graph
1253
1254This tracer is useful in several situations:
1255
1256_ you want to find the reason of a strange kernel behavior and need to see
1257 what happens in detail on any areas (or specific ones).
1258_ you are experiencing weird latencies but it's difficult to find its origin.
1259_ you want to find quickly which path is taken by a specific function
1260_ you just want to see what happens inside your kernel
1261
1262# tracer: function_graph
1263#
1264# CPU DURATION FUNCTION CALLS
1265# | | | | | | |
1266
1267 0) | sys_open() {
1268 0) | do_sys_open() {
1269 0) | getname() {
1270 0) | kmem_cache_alloc() {
1271 0) 1.382 us | __might_sleep();
1272 0) 2.478 us | }
1273 0) | strncpy_from_user() {
1274 0) | might_fault() {
1275 0) 1.389 us | __might_sleep();
1276 0) 2.553 us | }
1277 0) 3.807 us | }
1278 0) 7.876 us | }
1279 0) | alloc_fd() {
1280 0) 0.668 us | _spin_lock();
1281 0) 0.570 us | expand_files();
1282 0) 0.586 us | _spin_unlock();
1283
1284
1285There are several columns that can be dynamically enabled/disabled.
1286You can use every combination of options you want, depending on your needs.
1287
1288_ The cpu number on which the function executed is default enabled.
1289 It is sometimes better to only trace one cpu (see tracing_cpu_mask file)
1290 or you might sometimes see unordered function calls while cpu tracing switch.
1291
1292 hide: echo nofuncgraph-cpu > /debug/tracing/trace_options
1293 show: echo funcgraph-cpu > /debug/tracing/trace_options
1294
1295_ The duration (function's time of execution) is displayed on the closing bracket
1296 line of a function or on the same line than the current function in case of a leaf
1297 one. It is default enabled.
1298
1299 hide: echo nofuncgraph-duration > /debug/tracing/trace_options
1300 show: echo funcgraph-duration > /debug/tracing/trace_options
1301
1302_ The overhead field precedes the duration one in case of reached duration thresholds.
1303
1304 hide: echo nofuncgraph-overhead > /debug/tracing/trace_options
1305 show: echo funcgraph-overhead > /debug/tracing/trace_options
1306 depends on: funcgraph-duration
1307
1308 ie:
1309
1310 0) | up_write() {
1311 0) 0.646 us | _spin_lock_irqsave();
1312 0) 0.684 us | _spin_unlock_irqrestore();
1313 0) 3.123 us | }
1314 0) 0.548 us | fput();
1315 0) + 58.628 us | }
1316
1317 [...]
1318
1319 0) | putname() {
1320 0) | kmem_cache_free() {
1321 0) 0.518 us | __phys_addr();
1322 0) 1.757 us | }
1323 0) 2.861 us | }
1324 0) ! 115.305 us | }
1325 0) ! 116.402 us | }
1326
1327 + means that the function exceeded 10 usecs.
1328 ! means that the function exceeded 100 usecs.
1329
1330
1331_ The task/pid field displays the thread cmdline and pid which executed the function.
1332 It is default disabled.
1333
1334 hide: echo nofuncgraph-proc > /debug/tracing/trace_options
1335 show: echo funcgraph-proc > /debug/tracing/trace_options
1336
1337 ie:
1338
1339 # tracer: function_graph
1340 #
1341 # CPU TASK/PID DURATION FUNCTION CALLS
1342 # | | | | | | | | |
1343 0) sh-4802 | | d_free() {
1344 0) sh-4802 | | call_rcu() {
1345 0) sh-4802 | | __call_rcu() {
1346 0) sh-4802 | 0.616 us | rcu_process_gp_end();
1347 0) sh-4802 | 0.586 us | check_for_new_grace_period();
1348 0) sh-4802 | 2.899 us | }
1349 0) sh-4802 | 4.040 us | }
1350 0) sh-4802 | 5.151 us | }
1351 0) sh-4802 | + 49.370 us | }
1352
1353
1354_ The absolute time field is an absolute timestamp given by the clock since
1355 it started. A snapshot of this time is given on each entry/exit of functions
1356
1357 hide: echo nofuncgraph-abstime > /debug/tracing/trace_options
1358 show: echo funcgraph-abstime > /debug/tracing/trace_options
1359
1360 ie:
1361
1362 #
1363 # TIME CPU DURATION FUNCTION CALLS
1364 # | | | | | | | |
1365 360.774522 | 1) 0.541 us | }
1366 360.774522 | 1) 4.663 us | }
1367 360.774523 | 1) 0.541 us | __wake_up_bit();
1368 360.774524 | 1) 6.796 us | }
1369 360.774524 | 1) 7.952 us | }
1370 360.774525 | 1) 9.063 us | }
1371 360.774525 | 1) 0.615 us | journal_mark_dirty();
1372 360.774527 | 1) 0.578 us | __brelse();
1373 360.774528 | 1) | reiserfs_prepare_for_journal() {
1374 360.774528 | 1) | unlock_buffer() {
1375 360.774529 | 1) | wake_up_bit() {
1376 360.774529 | 1) | bit_waitqueue() {
1377 360.774530 | 1) 0.594 us | __phys_addr();
1378
1379
1380You can put some comments on specific functions by using ftrace_printk()
1381For example, if you want to put a comment inside the __might_sleep() function,
1382you just have to include <linux/ftrace.h> and call ftrace_printk() inside __might_sleep()
1383
1384ftrace_printk("I'm a comment!\n")
1385
1386will produce:
1387
1388 1) | __might_sleep() {
1389 1) | /* I'm a comment! */
1390 1) 1.449 us | }
1391
1392
1393You might find other useful features for this tracer on the "dynamic ftrace"
1394section such as tracing only specific functions or tasks.
1395
1229dynamic ftrace 1396dynamic ftrace
1230-------------- 1397--------------
1231 1398
@@ -1427,6 +1594,65 @@ Produces:
1427 1594
1428We can see that there's no more lock or preempt tracing. 1595We can see that there's no more lock or preempt tracing.
1429 1596
1597
1598* Dynamic ftrace with the function graph tracer *
1599
1600
1601Although what has been explained above concerns both the function tracer and
1602the function_graph_tracer, the following concerns only the latter.
1603
1604If you want to trace only one function and all of its childs, you just have
1605to echo its name on set_graph_function:
1606
1607echo __do_fault > set_graph_function
1608
1609will produce the following:
1610
1611 0) | __do_fault() {
1612 0) | filemap_fault() {
1613 0) | find_lock_page() {
1614 0) 0.804 us | find_get_page();
1615 0) | __might_sleep() {
1616 0) 1.329 us | }
1617 0) 3.904 us | }
1618 0) 4.979 us | }
1619 0) 0.653 us | _spin_lock();
1620 0) 0.578 us | page_add_file_rmap();
1621 0) 0.525 us | native_set_pte_at();
1622 0) 0.585 us | _spin_unlock();
1623 0) | unlock_page() {
1624 0) 0.541 us | page_waitqueue();
1625 0) 0.639 us | __wake_up_bit();
1626 0) 2.786 us | }
1627 0) + 14.237 us | }
1628 0) | __do_fault() {
1629 0) | filemap_fault() {
1630 0) | find_lock_page() {
1631 0) 0.698 us | find_get_page();
1632 0) | __might_sleep() {
1633 0) 1.412 us | }
1634 0) 3.950 us | }
1635 0) 5.098 us | }
1636 0) 0.631 us | _spin_lock();
1637 0) 0.571 us | page_add_file_rmap();
1638 0) 0.526 us | native_set_pte_at();
1639 0) 0.586 us | _spin_unlock();
1640 0) | unlock_page() {
1641 0) 0.533 us | page_waitqueue();
1642 0) 0.638 us | __wake_up_bit();
1643 0) 2.793 us | }
1644 0) + 14.012 us | }
1645
1646You can also select several functions:
1647
1648echo sys_open > set_graph_function
1649echo sys_close >> set_graph_function
1650
1651Now if you want to go back to trace all functions
1652
1653echo > set_graph_function
1654
1655
1430trace_pipe 1656trace_pipe
1431---------- 1657----------
1432 1658