stackcount_example.txt

Demonstrations of stackcount, the Linux eBPF/bcc version.


This program traces functions and frequency counts them with their entire
stack trace, summarized in-kernel for efficiency. For example, counting
stack traces that led to the submit_bio() kernel function, which creates
block device I/O:

# ./stackcount submit_bio
Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
^C
  submit_bio
  ext4_writepages
  do_writepages
  __filemap_fdatawrite_range
  filemap_flush
  ext4_alloc_da_blocks
  ext4_release_file
  __fput
  ____fput
  task_work_run
  exit_to_usermode_loop
  syscall_return_slowpath
  entry_SYSCALL_64_fastpath
  [unknown]
  [unknown]
    tar [15069]
    5

  submit_bio
  ext4_bio_write_page
  mpage_submit_page
  mpage_map_and_submit_buffers
  ext4_writepages
  do_writepages
  __filemap_fdatawrite_range
  filemap_flush
  ext4_alloc_da_blocks
  ext4_release_file
  __fput
  ____fput
  task_work_run
  exit_to_usermode_loop
  syscall_return_slowpath
  entry_SYSCALL_64_fastpath
  [unknown]
  [unknown]
    tar [15069]
    15

  submit_bio
  ext4_readpages
  __do_page_cache_readahead
  ondemand_readahead
  page_cache_async_readahead
  generic_file_read_iter
  __vfs_read
  vfs_read
  sys_read
  entry_SYSCALL_64_fastpath
  [unknown]
    tar [15069]
    113

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, sys_read(), vfs_read(), and then "readahead" functions:
looks like an application issued file read has triggered read ahead. The
application can be seen after the stack trace, in this case, "tar [15069]"
for the "tar" command, PID 15069.

The order of printed stack traces is from least to most frequent. The most
frequent in this case, the ext4_rename() stack, was taken 113 times during
tracing.

The "[unknown]" frames are from user-level, since this simple workload is
the tar command, which apparently has been compiled without frame pointers.
It's a common compiler optimization, but it breaks frame pointer-based stack
walkers. Similar broken stacks will be seen by other profilers and debuggers
that use frame pointers. Hopefully your application preserves them so that
the user-level stack trace is visible. So how does one get frame pointers, if
your application doesn't have them to start with? For the current bcc (until
it supports other stack walkers), you need to be running a application binaries
that preserves frame pointers, eg, using gcc's -fno-omit-frame-pointer. That's
about all I'll say here: this is a big topic that is not bcc/BPF specific.

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).


Now adding the -d option to delimit kernel and user stacks:

# ./stackcount -d submit_bio
Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.
^C
  submit_bio
  submit_bh
  journal_submit_commit_record
  jbd2_journal_commit_transaction
  kjournald2
  kthread
  ret_from_fork
    --
    jbd2/xvda1-8 [405]
    1

  submit_bio
  submit_bh
  jbd2_journal_commit_transaction
  kjournald2
  kthread
  ret_from_fork
    --
    jbd2/xvda1-8 [405]
    2

  submit_bio
  ext4_writepages
  do_writepages
  __filemap_fdatawrite_range
  filemap_flush
  ext4_alloc_da_blocks
  ext4_release_file
  __fput
  ____fput
  task_work_run
  exit_to_usermode_loop
  syscall_return_slowpath
  entry_SYSCALL_64_fastpath
    --
  [unknown]
  [unknown]
    tar [15187]
    5

  submit_bio
  ext4_bio_write_page
  mpage_submit_page
  mpage_map_and_submit_buffers
  ext4_writepages
  do_writepages
  __filemap_fdatawrite_range
  filemap_flush
  ext4_alloc_da_blocks
  ext4_release_file
  __fput
  ____fput
  task_work_run
  exit_to_usermode_loop
  syscall_return_slowpath
  entry_SYSCALL_64_fastpath
    --
  [unknown]
  [unknown]
    tar [15187]
    15

  submit_bio
  ext4_readpages
  __do_page_cache_readahead
  ondemand_readahead
  page_cache_async_readahead
  generic_file_read_iter
  __vfs_read
  vfs_read
  sys_read
  entry_SYSCALL_64_fastpath
    --
  [unknown]
  [unknown]
  [unknown]
    tar [15187]
    171

Detaching...

A "--" is printed between the kernel and user stacks.


As a different example, here is the kernel function hrtimer_init_sleeper():

# ./stackcount.py -d hrtimer_init_sleeper
Tracing 1 functions for "hrtimer_init_sleeper"... Hit Ctrl-C to end.
^C
  hrtimer_init_sleeper
  do_futex
  SyS_futex
  entry_SYSCALL_64_fastpath
    --
  [unknown]
    containerd [16020]
    1

  hrtimer_init_sleeper
  do_futex
  SyS_futex
  entry_SYSCALL_64_fastpath
    --
  __pthread_cond_timedwait
  Monitor::IWait(Thread*, long)
  Monitor::wait(bool, long, bool)
  CompileQueue::get()
  CompileBroker::compiler_thread_loop()
  JavaThread::thread_main_inner()
  JavaThread::run()
  java_start(Thread*)
  start_thread
    java [4996]
    1

  hrtimer_init_sleeper
  do_futex
  SyS_futex
  entry_SYSCALL_64_fastpath
    --
  [unknown]
  [unknown]
    containerd [16020]
    1

  hrtimer_init_sleeper
  do_futex
  SyS_futex
  entry_SYSCALL_64_fastpath
    --
  __pthread_cond_timedwait
  VMThread::loop()
  VMThread::run()
  java_start(Thread*)
  start_thread
    java [4996]
    3

  hrtimer_init_sleeper
  do_futex
  SyS_futex
  entry_SYSCALL_64_fastpath
    --
  [unknown]
    dockerd [16008]
    4

  hrtimer_init_sleeper
  do_futex
  SyS_futex
  entry_SYSCALL_64_fastpath
    --
  [unknown]
  [unknown]
    dockerd [16008]
    4

  hrtimer_init_sleeper
  do_futex
  SyS_futex
  entry_SYSCALL_64_fastpath
    --
  __pthread_cond_timedwait
  Lio/netty/util/ThreadDeathWatcher$Watcher;::run
  Interpreter
  Interpreter
  call_stub
  JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*)
  JavaCalls::call_virtual(JavaValue*, KlassHandle, Symbol*, Symbol*, JavaCallArguments*, Thread*)
  JavaCalls::call_virtual(JavaValue*, Handle, KlassHandle, Symbol*, Symbol*, Thread*)
  thread_entry(JavaThread*, Thread*)
  JavaThread::thread_main_inner()
  JavaThread::run()
  java_start(Thread*)
  start_thread
    java [4996]
    4

  hrtimer_init_sleeper
  do_futex
  SyS_futex
  entry_SYSCALL_64_fastpath
    --
  __pthread_cond_timedwait
  clock_gettime
  [unknown]
    java [4996]
    79

Detaching...

I was just trying to find a more interesting example. This output includes
some Java stacks where user-level has been walked correctly (even includes a
JIT symbol translation). dockerd and containerd don't have frame pointers
(grumble), but Java does (which is running with -XX:+PreserveFramePointer).


Here's another kernel function, ip_output():

# ./stackcount.py -d 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_push_pending_frames
  tcp_push
  tcp_sendmsg
  inet_sendmsg
  sock_sendmsg
  sock_write_iter
  __vfs_write
  vfs_write
  SyS_write
  entry_SYSCALL_64_fastpath
    --
  __write_nocancel
  [unknown]
    sshd [15015]
    5

  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
  vfs_write
  SyS_write
  entry_SYSCALL_64_fastpath
    --
  __write_nocancel
  [unknown]
  [unknown]
    sshd [8234]
    5

  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
  vfs_write
  SyS_write
  entry_SYSCALL_64_fastpath
    --
  __write_nocancel
    sshd [15015]
    7

Detaching...

This time just sshd is triggering ip_output() calls.


Watch what happens if I filter on kernel stacks only (-K) for ip_output():

# ./stackcount.py -K 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_push_pending_frames
  tcp_push
  tcp_sendmsg
  inet_sendmsg
  sock_sendmsg
  sock_write_iter
  __vfs_write
  vfs_write
  SyS_write
  entry_SYSCALL_64_fastpath
    13

Detaching...

They have grouped together as a single unique stack, since the kernel part
was the same.


Here is just the user stacks, fetched during the kernel function ip_output():

# ./stackcount.py -U ip_output
Tracing 1 functions for "ip_output"... Hit Ctrl-C to end.
^C
  [unknown]
    snmpd [1645]
    1

  __write_nocancel
  [unknown]
  [unknown]
    sshd [8234]
    3

  __write_nocancel
    sshd [15015]
    4

I should really run a custom sshd with frame pointers so we can see its
stack trace...


User-space functions can also be traced if a library name is provided. For
example, to quickly identify code locations that allocate heap memory for
PID 4902 (using -p), by tracing malloc from libc ("c:malloc"):

# ./stackcount -p 4902 c:malloc
Tracing 1 functions for "malloc"... Hit Ctrl-C to end.
^C
  malloc
  rbtree_new
  main
  [unknown]
    12

  malloc
  _rbtree_node_new_internal
  _rbtree_node_insert
  rbtree_insert
  main
  [unknown]
    1189

Detaching...

Kernel stacks are absent as this didn't enter kernel code.

Note that user-space uses of stackcount can be somewhat more limited because
a lot of user-space libraries and binaries are compiled without frame-pointers
as discussed earlier (the -fomit-frame-pointer compiler default) or are used
without debuginfo.


In addition to kernel and user-space functions, kernel tracepoints and USDT
tracepoints are also supported. 

For example, to determine where threads are being created in a particular 
process, use the pthread_create USDT tracepoint:

# ./stackcount -p $(pidof parprimes) u:pthread:pthread_create
Tracing 1 functions for "u:pthread:pthread_create"... Hit Ctrl-C to end.
^C

    parprimes [11923]
  pthread_create@@GLIBC_2.2.5
  main
  __libc_start_main
  [unknown]
    7

You can use "readelf -n file" to see if it has USDT tracepoints.


Similarly, to determine where context switching is happening in the kernel, 
use the sched:sched_switch kernel tracepoint:

# ./stackcount t:sched:sched_switch
  __schedule
  schedule
  worker_thread
  kthread
  ret_from_fork
    kworker/0:2 [25482]
    1

  __schedule
  schedule
  schedule_hrtimeout_range_clock
  schedule_hrtimeout_range
  ep_poll
  SyS_epoll_wait
  entry_SYSCALL_64_fastpath
  epoll_wait
  Lsun/nio/ch/SelectorImpl;::lockAndDoSelect
  Lsun/nio/ch/SelectorImpl;::select
  Lio/netty/channel/nio/NioEventLoop;::select
  Lio/netty/channel/nio/NioEventLoop;::run
  Interpreter
  Interpreter
  call_stub
  JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*)
  JavaCalls::call_virtual(JavaValue*, KlassHandle, Symbol*, Symbol*, JavaCallArguments*, Thread*)
  JavaCalls::call_virtual(JavaValue*, Handle, KlassHandle, Symbol*, Symbol*, Thread*)
  thread_entry(JavaThread*, Thread*)
  JavaThread::thread_main_inner()
  JavaThread::run()
  java_start(Thread*)
  start_thread
    java [4996]
    1

... (omitted for brevity)

  __schedule
  schedule
  schedule_preempt_disabled
  cpu_startup_entry
  xen_play_dead
  arch_cpu_idle_dead
  cpu_startup_entry
  cpu_bringup_and_idle
    swapper/1 [0]
    289


A -i option can be used to set an output interval, and -T to include a
timestamp. For example:

# ./stackcount.py -Tdi 1 submit_bio
Tracing 1 functions for "submit_bio"... Hit Ctrl-C to end.

06:05:13

06:05:14
  submit_bio
  xfs_do_writepage
  write_cache_pages
  xfs_vm_writepages
  do_writepages
  __writeback_single_inode
  writeback_sb_inodes
  __writeback_inodes_wb
  wb_writeback
  wb_workfn
  process_one_work
  worker_thread
  kthread
  ret_from_fork
    --
    kworker/u16:1 [15686]
    1

  submit_bio
  process_one_work
  worker_thread
  kthread
  ret_from_fork
    --
    kworker/u16:0 [16007]
    1

  submit_bio
  xfs_buf_submit
  xlog_bdstrat
  xlog_sync
  xlog_state_release_iclog
  _xfs_log_force
  xfs_log_force
  xfs_fs_sync_fs
  sync_fs_one_sb
  iterate_supers
  sys_sync
  entry_SYSCALL_64_fastpath
    --
  [unknown]
    sync [16039]
    1

  submit_bio
  submit_bh
  journal_submit_commit_record
  jbd2_journal_commit_transaction
  kjournald2
  kthread
  ret_from_fork
    --
    jbd2/xvda1-8 [405]
    1

  submit_bio
  process_one_work
  worker_thread
  kthread
  ret_from_fork
    --
    kworker/0:2 [25482]
    2

  submit_bio
  ext4_writepages
  do_writepages
  __writeback_single_inode
  writeback_sb_inodes
  __writeback_inodes_wb
  wb_writeback
  wb_workfn
  process_one_work
  worker_thread
  kthread
  ret_from_fork
    --
    kworker/u16:0 [16007]
    4

  submit_bio
  xfs_vm_writepages
  do_writepages
  __writeback_single_inode
  writeback_sb_inodes
  __writeback_inodes_wb
  wb_writeback
  wb_workfn
  process_one_work
  worker_thread
  kthread
  ret_from_fork
    --
    kworker/u16:1 [15686]
    5

  submit_bio
  __block_write_full_page
  block_write_full_page
  blkdev_writepage
  __writepage
  write_cache_pages
  generic_writepages
  blkdev_writepages
  do_writepages
  __filemap_fdatawrite_range
  filemap_fdatawrite
  fdatawrite_one_bdev
  iterate_bdevs
  sys_sync
  entry_SYSCALL_64_fastpath
    --
  [unknown]
    sync [16039]
    7

  submit_bio
  submit_bh
  jbd2_journal_commit_transaction
  kjournald2
  kthread
  ret_from_fork
    --
    jbd2/xvda1-8 [405]
    8

  submit_bio
  ext4_bio_write_page
  mpage_submit_page
  mpage_map_and_submit_buffers
  ext4_writepages
  do_writepages
  __writeback_single_inode
  writeback_sb_inodes
  __writeback_inodes_wb
  wb_writeback
  wb_workfn
  process_one_work
  worker_thread
  kthread
  ret_from_fork
    --
    kworker/u16:0 [16007]
    8

  submit_bio
  __block_write_full_page
  block_write_full_page
  blkdev_writepage
  __writepage
  write_cache_pages
  generic_writepages
  blkdev_writepages
  do_writepages
  __writeback_single_inode
  writeback_sb_inodes
  __writeback_inodes_wb
  wb_writeback
  wb_workfn
  process_one_work
  worker_thread
  kthread
  ret_from_fork
    --
    kworker/u16:0 [16007]
    60


06:05:15

06:05:16

Detaching...

This only included output for the 06:05:14 interval. The other internals
did not span block device I/O.


The -s output prints the return instruction offset for each function (aka
symbol offset). Eg:

# ./stackcount.py -s tcp_sendmsg
Tracing 1 functions for "tcp_sendmsg"... Hit Ctrl-C to end.
^C
  tcp_sendmsg+0x1
  sock_sendmsg+0x38
  sock_write_iter+0x85
  __vfs_write+0xe3
  vfs_write+0xb8
  SyS_write+0x55
  entry_SYSCALL_64_fastpath+0x1e
  __write_nocancel+0x7
    sshd [15015]
    3

  tcp_sendmsg+0x1
  sock_sendmsg+0x38
  sock_write_iter+0x85
  __vfs_write+0xe3
  vfs_write+0xb8
  SyS_write+0x55
  entry_SYSCALL_64_fastpath+0x1e
  __write_nocancel+0x7
    sshd [8234]
    3

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 disassembly dump.


The -v output is verbose, and shows raw addresses:

./stackcount.py -v tcp_sendmsg
Tracing 1 functions for "tcp_sendmsg"... Hit Ctrl-C to end.
^C
  ffffffff817b05c1 tcp_sendmsg
  ffffffff8173ea48 sock_sendmsg
  ffffffff8173eae5 sock_write_iter
  ffffffff81232b33 __vfs_write
  ffffffff812331b8 vfs_write
  ffffffff81234625 SyS_write
  ffffffff818739bb entry_SYSCALL_64_fastpath
  7f120511e6e0     __write_nocancel
    sshd [8234]
    3

  ffffffff817b05c1 tcp_sendmsg
  ffffffff8173ea48 sock_sendmsg
  ffffffff8173eae5 sock_write_iter
  ffffffff81232b33 __vfs_write
  ffffffff812331b8 vfs_write
  ffffffff81234625 SyS_write
  ffffffff818739bb entry_SYSCALL_64_fastpath
  7f919c5a26e0     __write_nocancel
    sshd [15015]
    11

Detaching...


A wildcard can also be used. Eg, all functions beginning with "tcp_send",
kernel stacks only (-K) with offsets (-s):

# ./stackcount -Ks '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.


The -f option will emit folded output, which can be used as input to other
tools including flame graphs. For example, with delimiters as well:

# ./stackcount.py -df t:sched:sched_switch
^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
kworker/7:0;-;ret_from_fork;kthread;worker_thread;schedule;__schedule 1
watchdog/0;-;ret_from_fork;kthread;smpboot_thread_fn;schedule;__schedule 1
snmp-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
svscan;[unknown];-;entry_SYSCALL_64_fastpath;SyS_nanosleep;hrtimer_nanosleep;do_nanosleep;schedule;__schedule 1
python;[unknown];__select_nocancel;-;entry_SYSCALL_64_fastpath;SyS_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule;__schedule 1
kworker/2:0;-;ret_from_fork;kthread;worker_thread;schedule;__schedule 1
[...]

Flame graphs visualize stack traces. For information about them and links
to open source software, see http://www.brendangregg.com/flamegraphs.html .
This folded output can be piped directly into flamegraph.pl (the Perl version).


USAGE message:

# ./stackcount -h
usage: stackcount [-h] [-p PID] [-i INTERVAL] [-D DURATION] [-T] [-r] [-s]
                  [-P] [-K] [-U] [-v] [-d] [-f] [--debug]
                  pattern

Count events and their stack traces

positional arguments:
  pattern               search expression for events

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
  -D DURATION, --duration DURATION
                        total duration of trace, seconds
  -T, --timestamp       include timestamp on output
  -r, --regexp          use regular expressions. Default is "*" wildcards
                        only.
  -s, --offset          show address offsets
  -P, --perpid          display stacks separately for each process
  -K, --kernel-stacks-only
                        kernel stack only
  -U, --user-stacks-only
                        user stack only
  -v, --verbose         show raw addresses
  -d, --delimited       insert delimiter between kernel/user stacks
  -f, --folded          output folded format
  --debug               print BPF program before starting (for debugging
                        purposes)

examples:
    ./stackcount submit_bio         # count kernel stack traces for submit_bio
    ./stackcount -d ip_output       # include a user/kernel stack delimiter
    ./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
    ./stackcount -p 185 c:malloc    # count stacks for malloc in PID 185
    ./stackcount t:sched:sched_fork # count stacks for sched_fork tracepoint
    ./stackcount -p 185 u:node:*    # count stacks for all USDT probes in node
    ./stackcount -K t:sched:sched_switch   # kernel stacks only
    ./stackcount -U t:sched:sched_switch   # user stacks only