@@ -8,6 +8,78 @@ block device I/O:
88
99# ./stackcount submit_bio
1010Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
11+ ^C
12+ submit_bio
13+ submit_bh
14+ journal_submit_commit_record.isra.13
15+ jbd2_journal_commit_transaction
16+ kjournald2
17+ kthread
18+ ret_from_fork
19+ mb_cache_list
20+ 1
21+
22+ submit_bio
23+ __block_write_full_page.constprop.39
24+ block_write_full_page
25+ blkdev_writepage
26+ __writepage
27+ write_cache_pages
28+ generic_writepages
29+ do_writepages
30+ __writeback_single_inode
31+ writeback_sb_inodes
32+ __writeback_inodes_wb
33+ 2
34+
35+ submit_bio
36+ __block_write_full_page.constprop.39
37+ block_write_full_page
38+ blkdev_writepage
39+ __writepage
40+ write_cache_pages
41+ generic_writepages
42+ do_writepages
43+ __filemap_fdatawrite_range
44+ filemap_fdatawrite
45+ fdatawrite_one_bdev
46+ 36
47+
48+ submit_bio
49+ submit_bh
50+ jbd2_journal_commit_transaction
51+ kjournald2
52+ kthread
53+ ret_from_fork
54+ mb_cache_list
55+ 38
56+
57+ submit_bio
58+ ext4_writepages
59+ do_writepages
60+ __filemap_fdatawrite_range
61+ filemap_flush
62+ ext4_alloc_da_blocks
63+ ext4_rename
64+ ext4_rename2
65+ vfs_rename
66+ sys_rename
67+ entry_SYSCALL_64_fastpath
68+ 79
69+
70+ Detaching...
71+
72+ The output shows unique stack traces, in order from leaf (on-CPU) to root,
73+ followed by their occurrence count. The last stack trace in the above output
74+ shows syscall handling, ext4_rename(), and filemap_flush(): looks like an
75+ application issued file rename has caused back end disk I/O due to ext4
76+ block allocation and a filemap_flush().
77+
78+
79+ Now adding the -P option to display stacks separately for each process:
80+
81+ # ./stackcount -P submit_bio
82+ Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
1183^C
1284 submit_bio
1385 ext4_writepages
@@ -64,15 +136,14 @@ Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
64136
65137Detaching...
66138
67- The output shows unique stack traces, in order from leaf (on-CPU) to root,
68- followed by their occurrence count. The last stack trace in the above output
69- shows syscall handling, sys_read(), vfs_read(), and then "readahead" functions:
70- looks like an application issued file read has triggered read ahead. The
71- application can be seen after the stack trace, in this case, "tar [15069]"
72- for the "tar" command, PID 15069.
139+ The last stack trace in the above output shows syscall handling, sys_read(),
140+ vfs_read(), and then "readahead" functions: looks like an application issued
141+ file read has triggered read ahead. With "-P", the application can be seen
142+ after the stack trace, in this case, "tar [15069]" for the "tar" command,
143+ PID 15069.
73144
74145The order of printed stack traces is from least to most frequent. The most
75- frequent in this case, the ext4_rename () stack, was taken 113 times during
146+ frequent in this case, the ext4_readpages () stack, was taken 113 times during
76147tracing.
77148
78149The "[unknown]" frames are from user-level, since this simple workload is
@@ -82,7 +153,7 @@ walkers. Similar broken stacks will be seen by other profilers and debuggers
82153that use frame pointers. Hopefully your application preserves them so that
83154the user-level stack trace is visible. So how does one get frame pointers, if
84155your application doesn't have them to start with? For the current bcc (until
85- it supports other stack walkers), you need to be running a application binaries
156+ it supports other stack walkers), you need to be running an application binaries
86157that preserves frame pointers, eg, using gcc's -fno-omit-frame-pointer. That's
87158about all I'll say here: this is a big topic that is not bcc/BPF specific.
88159
@@ -92,7 +163,7 @@ disk IOPS. These could have in-kernel origins (eg, background scrub).
92163
93164Now adding the -d option to delimit kernel and user stacks:
94165
95- # ./stackcount -d submit_bio
166+ # ./stackcount -P - d submit_bio
96167Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
97168^C
98169 submit_bio
@@ -181,7 +252,7 @@ A "--" is printed between the kernel and user stacks.
181252
182253As a different example, here is the kernel function hrtimer_init_sleeper():
183254
184- # ./stackcount.py -d hrtimer_init_sleeper
255+ # ./stackcount.py -P - d hrtimer_init_sleeper
185256Tracing 1 functions for "hrtimer_init_sleeper"... Hit Ctrl-C to end.
186257^C
187258 hrtimer_init_sleeper
@@ -294,7 +365,7 @@ JIT symbol translation). dockerd and containerd don't have frame pointers
294365
295366Here's another kernel function, ip_output():
296367
297- # ./stackcount.py -d ip_output
368+ # ./stackcount.py -P - d ip_output
298369Tracing 1 functions for "ip_output"... Hit Ctrl-C to end.
299370^C
300371 ip_output
@@ -391,7 +462,7 @@ was the same.
391462
392463Here is just the user stacks, fetched during the kernel function ip_output():
393464
394- # ./stackcount.py -U ip_output
465+ # ./stackcount.py -P - U ip_output
395466Tracing 1 functions for "ip_output"... Hit Ctrl-C to end.
396467^C
397468 [unknown]
@@ -416,7 +487,7 @@ User-space functions can also be traced if a library name is provided. For
416487example, to quickly identify code locations that allocate heap memory for
417488PID 4902 (using -p), by tracing malloc from libc ("c:malloc"):
418489
419- # ./stackcount -p 4902 c:malloc
490+ # ./stackcount -P - p 4902 c:malloc
420491Tracing 1 functions for "malloc"... Hit Ctrl-C to end.
421492^C
422493 malloc
@@ -444,12 +515,12 @@ without debuginfo.
444515
445516
446517In addition to kernel and user-space functions, kernel tracepoints and USDT
447- tracepoints are also supported.
518+ tracepoints are also supported.
448519
449- For example, to determine where threads are being created in a particular
520+ For example, to determine where threads are being created in a particular
450521process, use the pthread_create USDT tracepoint:
451522
452- # ./stackcount -p $(pidof parprimes) u:pthread:pthread_create
523+ # ./stackcount -P - p $(pidof parprimes) u:pthread:pthread_create
453524Tracing 1 functions for "u:pthread:pthread_create"... Hit Ctrl-C to end.
454525^C
455526
@@ -463,10 +534,10 @@ Tracing 1 functions for "u:pthread:pthread_create"... Hit Ctrl-C to end.
463534You can use "readelf -n file" to see if it has USDT tracepoints.
464535
465536
466- Similarly, to determine where context switching is happening in the kernel,
537+ Similarly, to determine where context switching is happening in the kernel,
467538use the sched:sched_switch kernel tracepoint:
468539
469- # ./stackcount t:sched:sched_switch
540+ # ./stackcount -P t:sched:sched_switch
470541 __schedule
471542 schedule
472543 worker_thread
@@ -518,7 +589,7 @@ use the sched:sched_switch kernel tracepoint:
518589A -i option can be used to set an output interval, and -T to include a
519590timestamp. For example:
520591
521- # ./stackcount.py -Tdi 1 submit_bio
592+ # ./stackcount.py -P - Tdi 1 submit_bio
522593Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
523594
52459506:05:13
@@ -705,7 +776,7 @@ did not span block device I/O.
705776The -s output prints the return instruction offset for each function (aka
706777symbol offset). Eg:
707778
708- # ./stackcount.py -s tcp_sendmsg
779+ # ./stackcount.py -P - s tcp_sendmsg
709780Tracing 1 functions for "tcp_sendmsg"... Hit Ctrl-C to end.
710781^C
711782 tcp_sendmsg+0x1
@@ -738,7 +809,7 @@ offset can help you locate the lines of code from a disassembly dump.
738809
739810The -v output is verbose, and shows raw addresses:
740811
741- ./stackcount.py -v tcp_sendmsg
812+ ./stackcount.py -P - v tcp_sendmsg
742813Tracing 1 functions for "tcp_sendmsg"... Hit Ctrl-C to end.
743814^C
744815 ffffffff817b05c1 tcp_sendmsg
@@ -825,7 +896,7 @@ Use -r to allow regular expressions.
825896The -f option will emit folded output, which can be used as input to other
826897tools including flame graphs. For example, with delimiters as well:
827898
828- # ./stackcount.py -df t:sched:sched_switch
899+ # ./stackcount.py -P - df t:sched:sched_switch
829900^Csnmp-pass;[unknown];[unknown];[unknown];[unknown];[unknown];-;entry_SYSCALL_64_fastpath;SyS_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule;__schedule 1
830901kworker/7:0;-;ret_from_fork;kthread;worker_thread;schedule;__schedule 1
831902watchdog/0;-;ret_from_fork;kthread;smpboot_thread_fn;schedule;__schedule 1
0 commit comments