Permalink
Cannot retrieve contributors at this time
Fetching contributors…
Cannot retrieve contributors at this time
| 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. | |
| 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... | |
| Full USAGE: | |
| # ./funccount -h | |
| usage: funccount.py [-h] [-p PID] [-i INTERVAL] [-T] [-r] [-d] 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 | |
| -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) | |
| 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 -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 |