blob: bf8b10172657e3b465319bba1ab8689fd0372a54 [file] [log] [blame]
Demonstrations of stackcount, the Linux eBPF/bcc version.
This program traces kernel functions and frequency counts them with their entire
kernel stack trace, summarized in-kernel for efficiency. For example, counting
stack traces that led to submit_bio(), which creates block device I/O:
# ./stackcount submit_bio
Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
^C
submit_bio
submit_bh
journal_submit_commit_record.isra.13
jbd2_journal_commit_transaction
kjournald2
kthread
ret_from_fork
mb_cache_list
1
submit_bio
__block_write_full_page.constprop.39
block_write_full_page
blkdev_writepage
__writepage
write_cache_pages
generic_writepages
do_writepages
__writeback_single_inode
writeback_sb_inodes
__writeback_inodes_wb
2
submit_bio
__block_write_full_page.constprop.39
block_write_full_page
blkdev_writepage
__writepage
write_cache_pages
generic_writepages
do_writepages
__filemap_fdatawrite_range
filemap_fdatawrite
fdatawrite_one_bdev
36
submit_bio
submit_bh
jbd2_journal_commit_transaction
kjournald2
kthread
ret_from_fork
mb_cache_list
38
submit_bio
ext4_writepages
do_writepages
__filemap_fdatawrite_range
filemap_flush
ext4_alloc_da_blocks
ext4_rename
ext4_rename2
vfs_rename
sys_rename
entry_SYSCALL_64_fastpath
79
Detaching...
The output shows unique stack traces, in order from leaf (on-CPU) to root,
followed by their occurrence count. The last stack trace in the above output
shows syscall handling, ext4_rename(), and filemap_flush(): looks like an
application issued file rename has caused back end disk I/O due to ext4
block allocation and a filemap_flush(). I'd have to browse the code to those
functions to confirm!
The order of printed stack traces is from least to most frequent. The most
frequent in this case, the ext4_rename() stack, was taken 79 times during
tracing.
It can be useful to trace the path to submit_bio to explain unusual rates of
disk IOPS. These could have in-kernel origins (eg, background scrub).
This version of stackcount truncates stacks to 10 levels deep (plus 1 for
the traced function, so 11).
As another example, here are the code paths that led to ip_output(), which
sends a packet at the IP level:
# ./stackcount ip_output
Tracing 1 functions for "ip_output"... Hit Ctrl-C to end.
^C
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
tcp_tsq_handler.part.32
tcp_tasklet_func
tasklet_action
__do_softirq
do_softirq_own_stack
do_softirq
__local_bh_enable_ip
1
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_send_ack
tcp_send_delayed_ack
__tcp_ack_snd_check
tcp_rcv_established
tcp_v4_do_rcv
tcp_v4_rcv
ip_local_deliver_finish
ip_local_deliver
1
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_send_ack
tcp_send_delayed_ack
__tcp_ack_snd_check
tcp_rcv_established
tcp_v4_do_rcv
tcp_v4_rcv
ip_local_deliver_finish
ip_local_deliver
1
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_send_ack
tcp_delack_timer_handler
tcp_delack_timer
call_timer_fn
run_timer_softirq
__do_softirq
irq_exit
xen_evtchn_do_upcall
1
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
__tcp_push_pending_frames
tcp_rcv_established
tcp_v4_do_rcv
release_sock
tcp_sendmsg
inet_sendmsg
sock_sendmsg
3
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
tcp_tsq_handler.part.32
tcp_tasklet_func
tasklet_action
__do_softirq
run_ksoftirqd
smpboot_thread_fn
kthread
3
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
__tcp_push_pending_frames
tcp_rcv_established
tcp_v4_do_rcv
tcp_v4_rcv
ip_local_deliver_finish
ip_local_deliver
ip_rcv_finish
4
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_send_ack
tcp_cleanup_rbuf
tcp_recvmsg
inet_recvmsg
sock_recvmsg
sock_read_iter
__vfs_read
vfs_read
5
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
__tcp_push_pending_frames
tcp_rcv_established
tcp_v4_do_rcv
release_sock
tcp_sendmsg
inet_sendmsg
sock_sendmsg
9
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
__tcp_push_pending_frames
tcp_push
tcp_sendmsg
inet_sendmsg
sock_sendmsg
sock_write_iter
__vfs_write
51
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
__tcp_push_pending_frames
tcp_rcv_established
tcp_v4_do_rcv
tcp_v4_rcv
ip_local_deliver_finish
ip_local_deliver
ip_rcv_finish
171
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
__tcp_push_pending_frames
tcp_rcv_established
tcp_v4_do_rcv
tcp_v4_rcv
ip_local_deliver_finish
ip_local_deliver
ip_rcv_finish
994
ip_output
ip_queue_xmit
tcp_transmit_skb
tcp_write_xmit
tcp_tsq_handler.part.32
tcp_tasklet_func
tasklet_action
__do_softirq
irq_exit
xen_evtchn_do_upcall
xen_do_hypervisor_callback
1002
Detaching...
The last two most frequent stack traces are via tcp_transmit_skb(). Note the
send last begins with ip_rcv_finish(), for a local receive, which then becomes
a transmit: likely pushing more frames when processing the newly received ones.
As may be obvious, this is a great tool for quickly understanding kernel code
flow.
A -i option can be used to set an output interval, and -T to include a
timestamp. For example:
# ./stackcount -Ti 1 submit_bio
Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
01:11:37
submit_bio
submit_bh
journal_submit_commit_record.isra.13
jbd2_journal_commit_transaction
kjournald2
kthread
ret_from_fork
mb_cache_list
1
submit_bio
ext4_writepages
do_writepages
__filemap_fdatawrite_range
filemap_flush
ext4_alloc_da_blocks
ext4_rename
ext4_rename2
vfs_rename
sys_rename
entry_SYSCALL_64_fastpath
20
submit_bio
submit_bh
jbd2_journal_commit_transaction
kjournald2
kthread
ret_from_fork
mb_cache_list
39
01:11:38
submit_bio
ext4_writepages
do_writepages
__filemap_fdatawrite_range
filemap_flush
ext4_alloc_da_blocks
ext4_rename
ext4_rename2
vfs_rename
sys_rename
entry_SYSCALL_64_fastpath
20
01:11:39
submit_bio
ext4_writepages
do_writepages
__filemap_fdatawrite_range
filemap_flush
ext4_alloc_da_blocks
ext4_rename
ext4_rename2
vfs_rename
sys_rename
entry_SYSCALL_64_fastpath
20
^C
01:11:39
submit_bio
ext4_writepages
do_writepages
__filemap_fdatawrite_range
filemap_flush
ext4_alloc_da_blocks
ext4_rename
ext4_rename2
vfs_rename
sys_rename
entry_SYSCALL_64_fastpath
20
Detaching...
The -s output prints the return instruction offset for each function (aka
symbol offset). Eg:
# ./stackcount -s tcp_sendmsg
Tracing 1 functions for "tcp_sendmsg"... Hit Ctrl-C to end.
^C
tcp_sendmsg0x1
sock_sendmsg0x38
sock_write_iter0x78
__vfs_write0xaa
vfs_write0xa9
sys_write0x46
entry_SYSCALL_64_fastpath0x16
29
Detaching...
If it wasn't clear how one function called another, knowing the instruction
offset can help you locate the lines of code from a dissassembly dump.
A wildcard can also be used. Eg, all functions beginning with "tcp_send":
# ./stackcount -s 'tcp_send*'
Tracing 14 functions for "tcp_send*"... Hit Ctrl-C to end.
^C
tcp_send_delayed_ack0x1
tcp_rcv_established0x3b1
tcp_v4_do_rcv0x130
tcp_v4_rcv0x8e0
ip_local_deliver_finish0x9f
ip_local_deliver0x51
ip_rcv_finish0x8a
ip_rcv0x29d
__netif_receive_skb_core0x637
__netif_receive_skb0x18
netif_receive_skb_internal0x23
1
tcp_send_delayed_ack0x1
tcp_rcv_established0x222
tcp_v4_do_rcv0x130
tcp_v4_rcv0x8e0
ip_local_deliver_finish0x9f
ip_local_deliver0x51
ip_rcv_finish0x8a
ip_rcv0x29d
__netif_receive_skb_core0x637
__netif_receive_skb0x18
netif_receive_skb_internal0x23
4
tcp_send_mss0x1
inet_sendmsg0x67
sock_sendmsg0x38
sock_write_iter0x78
__vfs_write0xaa
vfs_write0xa9
sys_write0x46
entry_SYSCALL_64_fastpath0x16
7
tcp_sendmsg0x1
sock_sendmsg0x38
sock_write_iter0x78
__vfs_write0xaa
vfs_write0xa9
sys_write0x46
entry_SYSCALL_64_fastpath0x16
7
Detaching...
Use -r to allow regular expressions.
USAGE message:
# ./stackcount -h
usage: stackcount [-h] [-p PID] [-i INTERVAL] [-T] [-r] [-s] [-v] pattern
Count kernel function calls and their stack traces
positional arguments:
pattern search expression for kernel functions
optional arguments:
-h, --help show this help message and exit
-p PID, --pid PID trace this PID only
-i INTERVAL, --interval INTERVAL
summary interval, seconds
-T, --timestamp include timestamp on output
-r, --regexp use regular expressions. Default is "*" wildcards
only.
-s, --offset show address offsets
-v, --verbose show raw addresses
examples:
./stackcount submit_bio # count kernel stack traces for submit_bio
./stackcount ip_output # count kernel stack traces for ip_output
./stackcount -s ip_output # show symbol offsets
./stackcount -sv ip_output # show offsets and raw addresses (verbose)
./stackcount 'tcp_send*' # count stacks for funcs matching tcp_send*
./stackcount -r '^tcp_send.*' # same as above, using regular expressions
./stackcount -Ti 5 ip_output # output every 5 seconds, with timestamps
./stackcount -p 185 ip_output # count ip_output stacks for PID 185 only