funccount_example.txt

Demonstrations of funccount, the Linux eBPF/bcc version.


This program traces functions, tracepoints, or USDT probes that match a
specified pattern, and when Ctrl-C is hit prints a summary of their count
while tracing. Eg, tracing all kernel functions that begin with "vfs_":

# ./funccount 'vfs_*'
Tracing... Ctrl-C to end.
^C
FUNC                          COUNT
vfs_create                        1
vfs_rename                        1
vfs_fsync_range                   2
vfs_lock_file                    30
vfs_fstatat                     152
vfs_fstat                       154
vfs_write                       166
vfs_getattr_nosec               262
vfs_getattr                     262
vfs_open                        264
vfs_read                        470
Detaching...

The above output shows that while tracing the vfs_read() function was called 470
times, and vfs_open() 264 times, etc.

This is useful for exploring kernel code, to figure out which functions are in
use and which are not. This can narrow down an investigation to just a few
functions, whose counts are similar to the workload investigated.


Tracing all tcp functions:

# ./funccount 'tcp_*'
Tracing... Ctrl-C to end.
^C
FUNC                          COUNT
tcp_try_undo_recovery             1
tcp_twsk_destructor               1
tcp_enter_recovery                1
tcp_xmit_retransmit_queue         1
tcp_update_scoreboard             1
tcp_verify_retransmit_hint        1
tcp_tsq_handler.part.31           1
tcp_sacktag_write_queue           1
tcp_match_skb_to_sack             1
tcp_time_wait                     1
tcp_mark_head_lost                1
tcp_init_cwnd_reduction           1
tcp_sacktag_one                   1
tcp_sacktag_walk                  1
tcp_retransmit_skb                1
tcp_tasklet_func                  1
tcp_resume_early_retransmit       1
tcp_dsack_set                     1
tcp_v4_syn_recv_sock              2
tcp_ca_openreq_child              2
tcp_try_fastopen                  2
tcp_openreq_init_rwin             2
tcp_v4_init_req                   2
tcp_create_openreq_child          2
tcp_v4_send_synack                2
tcp_v4_init_sequence              2
tcp_fragment                      2
tcp_v4_conn_request               2
tcp_conn_request                  2
tcp_v4_route_req                  2
tcp_fragment_tstamp               2
tcp_try_keep_open                 2
tcp_v4_reqsk_destructor           2
tcp_may_send_now                  2
tcp_make_synack                   2
tcp_child_process                 2
tcp_check_req                     2
tcp_fastretrans_alert             2
tcp_set_keepalive                 2
tcp_finish_connect                3
tcp_connect_queue_skb             3
tcp_v4_connect                    3
tcp_init_sock                     3
tcp_v4_init_sock                  3
tcp_connect                       3
tcp_any_retrans_done.part.35        3
tcp_clear_retrans                 3
tcp_setsockopt                    4
tcp_update_metrics                5
tcp_done                          5
tcp_initialize_rcv_mss            5
tcp_sndbuf_expand                 5
tcp_fin                           5
tcp_init_xmit_timers              5
tcp_close                         5
tcp_init_congestion_control        5
tcp_init_metrics                  5
tcp_gro_complete                  5
tcp_free_fastopen_req             5
tcp_v4_destroy_sock               5
tcp_cleanup_congestion_control        5
tcp_send_fin                      5
tcp_init_buffer_space             5
tcp_init_cwnd                     5
tcp_select_initial_window         5
tcp_check_oom                     5
tcp_default_init_rwnd             5
tcp_assign_congestion_control        5
tcp_getsockopt                    6
tcp_ioctl                         6
tcp_mtup_init                     8
tcp_parse_options                 8
tcp_mss_to_mtu                    8
tcp_try_rmem_schedule             8
tcp_get_metrics                  10
tcp_try_coalesce                 10
tcp_rcv_state_process            14
tcp_sync_mss                     14
tcp_write_timer_handler          15
tcp_write_timer                  16
tcp_grow_window.isra.27          22
tcp_set_state                    23
tcp_send_ack                     37
tcp_delack_timer                 42
tcp_delack_timer_handler         42
tcp_validate_incoming            91
tcp_prequeue_process            112
tcp_v4_early_demux              117
tcp_gro_receive                 146
tcp_queue_rcv                   167
tcp_data_queue                  215
tcp_urg                         219
tcp_send_delayed_ack            257
tcp_send_mss                    275
tcp_push                        275
tcp_sendmsg                     275
tcp_event_data_recv             275
tcp_nagle_check                 279
tcp_write_xmit                  282
tcp_event_new_data_sent         282
tcp_current_mss                 284
tcp_init_tso_segs               284
tcp_wfree                       286
tcp_schedule_loss_probe         305
tcp_v4_send_check               323
tcp_transmit_skb                323
tcp_recvmsg                     323
tcp_options_write               325
tcp_rcv_space_adjust            328
tcp_check_space                 332
tcp_rcv_established             337
tcp_ack                         337
tcp_parse_aligned_timestamp.part.43      345
tcp_prequeue                    346
tcp_v4_do_rcv                   351
tcp_v4_rcv                      351
tcp_parse_md5sig_option         351
tcp_cleanup_rbuf                436
tcp_poll                        468
tcp_established_options         604
tcp_v4_md5_lookup               615
tcp_release_cb                  736
tcp_rearm_rto                   843
tcp_md5_do_lookup               968
Detaching...

The current implementation can take many seconds to detach from tracing, after
Ctrl-C has been hit.


User functions can be traced in executables or libraries, and per-process
filtering is allowed:

# ./funccount -p 1442 /home/ubuntu/contentions:*
Tracing 15 functions for "/home/ubuntu/contentions:*"... Hit Ctrl-C to end.
^C
FUNC                                           COUNT
main                                               1
_start                                             1
primes_thread                                      2
insert_result                                  87186
is_prime                                     1252772
Detaching...

If /home/ubuntu is in the $PATH, then the following command will also work:

# ./funccount -p 1442 contentions:*


Counting libc write and read calls using regular expression syntax (-r):

# ./funccount -r 'c:(write|read)$'
Tracing 2 functions for "c:(write|read)$"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
read                                        2
write                                       4
Detaching...


Kernel tracepoints are also available as targets. For example, trace common
block I/O tracepoints and see how often they are invoked:

# ./funccount t:block:*
Tracing 19 functions for "t:block:*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
block:block_rq_complete                     7
block:block_rq_issue                        7
block:block_getrq                           7
block:block_rq_insert                       7
Detaching...


Likewise, user-mode statically defined traces (USDT) can also be probed. For
example, count mutex-related events in pthreads:

# ./funccount u:pthread:*mutex* -p 1442
Tracing 7 functions for "u:pthread:*mutex*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
mutex_init                                  1
mutex_entry                            547122
mutex_acquired                         547175
mutex_release                          547185
Detaching...


An interval can be provided. Eg, printing output every 1 second for vfs calls:

# ./funccount -i 1 'vfs_*'
Tracing... Ctrl-C to end.

FUNC                          COUNT
vfs_fstatat                       1
vfs_fstat                        16
vfs_getattr_nosec                17
vfs_getattr                      17
vfs_write                        52
vfs_read                         79
vfs_open                         98

FUNC                          COUNT
vfs_fstatat                      10
vfs_fstat                        10
vfs_open                         13
vfs_getattr_nosec                20
vfs_getattr                      20
vfs_write                        28
vfs_read                         39

FUNC                          COUNT
vfs_fsync_range                   2
vfs_lock_file                    30
vfs_write                       107
vfs_fstatat                     129
vfs_fstat                       130
vfs_open                        154
vfs_getattr_nosec               222
vfs_getattr                     222
vfs_read                        384
^C
Detaching...

This can be useful for making some ad hoc tools, exposing new counts of
kernel activity that aren't visible in other metrics.

Include -T to print timestamps on output.


A maximum duration can be set. For example, to print 5 x 1 second summaries
of vfs_read() calls:

# ./funccount -i 1 -d 5 vfs_read
Tracing 1 functions for "vfs_read"... Hit Ctrl-C to end.

FUNC                                    COUNT
vfs_read                                   30

FUNC                                    COUNT
vfs_read                                   26

FUNC                                    COUNT
vfs_read                                   54

FUNC                                    COUNT
vfs_read                                   25

FUNC                                    COUNT
vfs_read                                   31
Detaching...

By leaving off the "-i 1", this will print a single 5 second summary:

# funccount.py -d 5 vfs_read
Tracing 1 functions for "vfs_read"... Hit Ctrl-C to end.

FUNC                                    COUNT
vfs_read                                  167
Detaching...

This can be useful for finding out rates: trace all functions for ten seconds
and then divide by ten for the per-second rate.


The "*" wildcard can be used multiple times. Eg, matching functions that contain
the word "readdir":

# ./funccount '*readdir*'
Tracing... Ctrl-C to end.
^C
FUNC                          COUNT
ext4_readdir                      4
Detaching...

Matching "tcp" then "send":

# ./funccount '*tcp*send*'
Tracing... Ctrl-C to end.
^C
FUNC                          COUNT
tcp_send_ack                      4
tcp_send_delayed_ack             19
tcp_send_mss                     26
tcp_sendmsg                      26
tcp_v4_send_check                30
__tcp_v4_send_check              30
Detaching...

A cpu is specified by "-c CPU", this will only trace the specified CPU. Eg,
trace how many timers setting per second of CPU 1 on a x86(Intel) server:

# funccount.py -i 1 -c 1 lapic_next_deadline
Tracing 1 functions for "lapic_next_deadline"... Hit Ctrl-C to end.

FUNC                                    COUNT
lapic_next_deadline                      3840

FUNC                                    COUNT
lapic_next_deadline                      3930

FUNC                                    COUNT
lapic_next_deadline                      4701

FUNC                                    COUNT
lapic_next_deadline                      5895

FUNC                                    COUNT
lapic_next_deadline                      5591

FUNC                                    COUNT
lapic_next_deadline                      4727

FUNC                                    COUNT
lapic_next_deadline                      5560

FUNC                                    COUNT
lapic_next_deadline                      5416
^C
FUNC                                    COUNT
lapic_next_deadline                       372
Detaching...

Full USAGE:

# ./funccount -h
usage: funccount.py [-h] [-p PID] [-i INTERVAL] [-d DURATION] [-T] [-r] [-D]
                    [-c CPU]
                    pattern

Count functions, tracepoints, and USDT probes

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.
  -D, --debug           print BPF program before starting (for debugging
                        purposes)
  -c CPU, --cpu CPU     trace this CPU only

examples:
    ./funccount 'vfs_*'             # count kernel fns starting with "vfs"
    ./funccount -r '^vfs.*'         # same as above, using regular expressions
    ./funccount -Ti 5 'vfs_*'       # output every 5 seconds, with timestamps
    ./funccount -d 10 'vfs_*'       # trace for 10 seconds only
    ./funccount -p 185 'vfs_*'      # count vfs calls for PID 181 only
    ./funccount t:sched:sched_fork  # count calls to the sched_fork tracepoint
    ./funccount -p 185 u:node:gc*   # count all GC USDT probes in node, PID 185
    ./funccount c:malloc            # count all malloc() calls in libc
    ./funccount go:os.*             # count all "os.*" calls in libgo
    ./funccount -p 185 go:os.*      # count all "os.*" calls in libgo, PID 185
    ./funccount ./test:read*        # count "read*" calls in the ./test binary
    ./funccount -c 1 'vfs_*'        # count vfs calls on CPU 1 only