1Demonstrations of funccount, the Linux eBPF/bcc version. 2 3 4This program traces functions, tracepoints, or USDT probes that match a 5specified pattern, and when Ctrl-C is hit prints a summary of their count 6while tracing. Eg, tracing all kernel functions that begin with "vfs_": 7 8# ./funccount 'vfs_*' 9Tracing... Ctrl-C to end. 10^C 11FUNC COUNT 12vfs_create 1 13vfs_rename 1 14vfs_fsync_range 2 15vfs_lock_file 30 16vfs_fstatat 152 17vfs_fstat 154 18vfs_write 166 19vfs_getattr_nosec 262 20vfs_getattr 262 21vfs_open 264 22vfs_read 470 23Detaching... 24 25The above output shows that while tracing the vfs_read() function was called 470 26times, and vfs_open() 264 times, etc. 27 28This is useful for exploring kernel code, to figure out which functions are in 29use and which are not. This can narrow down an investigation to just a few 30functions, whose counts are similar to the workload investigated. 31 32 33Tracing all tcp functions: 34 35# ./funccount 'tcp_*' 36Tracing... Ctrl-C to end. 37^C 38FUNC COUNT 39tcp_try_undo_recovery 1 40tcp_twsk_destructor 1 41tcp_enter_recovery 1 42tcp_xmit_retransmit_queue 1 43tcp_update_scoreboard 1 44tcp_verify_retransmit_hint 1 45tcp_tsq_handler.part.31 1 46tcp_sacktag_write_queue 1 47tcp_match_skb_to_sack 1 48tcp_time_wait 1 49tcp_mark_head_lost 1 50tcp_init_cwnd_reduction 1 51tcp_sacktag_one 1 52tcp_sacktag_walk 1 53tcp_retransmit_skb 1 54tcp_tasklet_func 1 55tcp_resume_early_retransmit 1 56tcp_dsack_set 1 57tcp_v4_syn_recv_sock 2 58tcp_ca_openreq_child 2 59tcp_try_fastopen 2 60tcp_openreq_init_rwin 2 61tcp_v4_init_req 2 62tcp_create_openreq_child 2 63tcp_v4_send_synack 2 64tcp_v4_init_sequence 2 65tcp_fragment 2 66tcp_v4_conn_request 2 67tcp_conn_request 2 68tcp_v4_route_req 2 69tcp_fragment_tstamp 2 70tcp_try_keep_open 2 71tcp_v4_reqsk_destructor 2 72tcp_may_send_now 2 73tcp_make_synack 2 74tcp_child_process 2 75tcp_check_req 2 76tcp_fastretrans_alert 2 77tcp_set_keepalive 2 78tcp_finish_connect 3 79tcp_connect_queue_skb 3 80tcp_v4_connect 3 81tcp_init_sock 3 82tcp_v4_init_sock 3 83tcp_connect 3 84tcp_any_retrans_done.part.35 3 85tcp_clear_retrans 3 86tcp_setsockopt 4 87tcp_update_metrics 5 88tcp_done 5 89tcp_initialize_rcv_mss 5 90tcp_sndbuf_expand 5 91tcp_fin 5 92tcp_init_xmit_timers 5 93tcp_close 5 94tcp_init_congestion_control 5 95tcp_init_metrics 5 96tcp_gro_complete 5 97tcp_free_fastopen_req 5 98tcp_v4_destroy_sock 5 99tcp_cleanup_congestion_control 5 100tcp_send_fin 5 101tcp_init_buffer_space 5 102tcp_init_cwnd 5 103tcp_select_initial_window 5 104tcp_check_oom 5 105tcp_default_init_rwnd 5 106tcp_assign_congestion_control 5 107tcp_getsockopt 6 108tcp_ioctl 6 109tcp_mtup_init 8 110tcp_parse_options 8 111tcp_mss_to_mtu 8 112tcp_try_rmem_schedule 8 113tcp_get_metrics 10 114tcp_try_coalesce 10 115tcp_rcv_state_process 14 116tcp_sync_mss 14 117tcp_write_timer_handler 15 118tcp_write_timer 16 119tcp_grow_window.isra.27 22 120tcp_set_state 23 121tcp_send_ack 37 122tcp_delack_timer 42 123tcp_delack_timer_handler 42 124tcp_validate_incoming 91 125tcp_prequeue_process 112 126tcp_v4_early_demux 117 127tcp_gro_receive 146 128tcp_queue_rcv 167 129tcp_data_queue 215 130tcp_urg 219 131tcp_send_delayed_ack 257 132tcp_send_mss 275 133tcp_push 275 134tcp_sendmsg 275 135tcp_event_data_recv 275 136tcp_nagle_check 279 137tcp_write_xmit 282 138tcp_event_new_data_sent 282 139tcp_current_mss 284 140tcp_init_tso_segs 284 141tcp_wfree 286 142tcp_schedule_loss_probe 305 143tcp_v4_send_check 323 144tcp_transmit_skb 323 145tcp_recvmsg 323 146tcp_options_write 325 147tcp_rcv_space_adjust 328 148tcp_check_space 332 149tcp_rcv_established 337 150tcp_ack 337 151tcp_parse_aligned_timestamp.part.43 345 152tcp_prequeue 346 153tcp_v4_do_rcv 351 154tcp_v4_rcv 351 155tcp_parse_md5sig_option 351 156tcp_cleanup_rbuf 436 157tcp_poll 468 158tcp_established_options 604 159tcp_v4_md5_lookup 615 160tcp_release_cb 736 161tcp_rearm_rto 843 162tcp_md5_do_lookup 968 163Detaching... 164 165The current implementation can take many seconds to detach from tracing, after 166Ctrl-C has been hit. 167 168 169User functions can be traced in executables or libraries, and per-process 170filtering is allowed: 171 172# ./funccount -p 1442 /home/ubuntu/contentions:* 173Tracing 15 functions for "/home/ubuntu/contentions:*"... Hit Ctrl-C to end. 174^C 175FUNC COUNT 176main 1 177_start 1 178primes_thread 2 179insert_result 87186 180is_prime 1252772 181Detaching... 182 183If /home/ubuntu is in the $PATH, then the following command will also work: 184 185# ./funccount -p 1442 contentions:* 186 187 188Counting libc write and read calls using regular expression syntax (-r): 189 190# ./funccount -r 'c:(write|read)$' 191Tracing 2 functions for "c:(write|read)$"... Hit Ctrl-C to end. 192^C 193FUNC COUNT 194read 2 195write 4 196Detaching... 197 198 199Kernel tracepoints are also available as targets. For example, trace common 200block I/O tracepoints and see how often they are invoked: 201 202# ./funccount t:block:* 203Tracing 19 functions for "t:block:*"... Hit Ctrl-C to end. 204^C 205FUNC COUNT 206block:block_rq_complete 7 207block:block_rq_issue 7 208block:block_getrq 7 209block:block_rq_insert 7 210Detaching... 211 212 213Likewise, user-mode statically defined traces (USDT) can also be probed. For 214example, count mutex-related events in pthreads: 215 216# ./funccount u:pthread:*mutex* -p 1442 217Tracing 7 functions for "u:pthread:*mutex*"... Hit Ctrl-C to end. 218^C 219FUNC COUNT 220mutex_init 1 221mutex_entry 547122 222mutex_acquired 547175 223mutex_release 547185 224Detaching... 225 226 227An interval can be provided. Eg, printing output every 1 second for vfs calls: 228 229# ./funccount -i 1 'vfs_*' 230Tracing... Ctrl-C to end. 231 232FUNC COUNT 233vfs_fstatat 1 234vfs_fstat 16 235vfs_getattr_nosec 17 236vfs_getattr 17 237vfs_write 52 238vfs_read 79 239vfs_open 98 240 241FUNC COUNT 242vfs_fstatat 10 243vfs_fstat 10 244vfs_open 13 245vfs_getattr_nosec 20 246vfs_getattr 20 247vfs_write 28 248vfs_read 39 249 250FUNC COUNT 251vfs_fsync_range 2 252vfs_lock_file 30 253vfs_write 107 254vfs_fstatat 129 255vfs_fstat 130 256vfs_open 154 257vfs_getattr_nosec 222 258vfs_getattr 222 259vfs_read 384 260^C 261Detaching... 262 263This can be useful for making some ad hoc tools, exposing new counts of 264kernel activity that aren't visible in other metrics. 265 266Include -T to print timestamps on output. 267 268 269A maximum duration can be set. For example, to print 5 x 1 second summaries 270of vfs_read() calls: 271 272# ./funccount -i 1 -d 5 vfs_read 273Tracing 1 functions for "vfs_read"... Hit Ctrl-C to end. 274 275FUNC COUNT 276vfs_read 30 277 278FUNC COUNT 279vfs_read 26 280 281FUNC COUNT 282vfs_read 54 283 284FUNC COUNT 285vfs_read 25 286 287FUNC COUNT 288vfs_read 31 289Detaching... 290 291By leaving off the "-i 1", this will print a single 5 second summary: 292 293# funccount.py -d 5 vfs_read 294Tracing 1 functions for "vfs_read"... Hit Ctrl-C to end. 295 296FUNC COUNT 297vfs_read 167 298Detaching... 299 300This can be useful for finding out rates: trace all functions for ten seconds 301and then divide by ten for the per-second rate. 302 303 304The "*" wildcard can be used multiple times. Eg, matching functions that contain 305the word "readdir": 306 307# ./funccount '*readdir*' 308Tracing... Ctrl-C to end. 309^C 310FUNC COUNT 311ext4_readdir 4 312Detaching... 313 314Matching "tcp" then "send": 315 316# ./funccount '*tcp*send*' 317Tracing... Ctrl-C to end. 318^C 319FUNC COUNT 320tcp_send_ack 4 321tcp_send_delayed_ack 19 322tcp_send_mss 26 323tcp_sendmsg 26 324tcp_v4_send_check 30 325__tcp_v4_send_check 30 326Detaching... 327 328 329Full USAGE: 330 331# ./funccount -h 332usage: funccount [-h] [-p PID] [-i INTERVAL] [-d DURATION] [-T] [-r] [-D] 333 pattern 334 335Count functions, tracepoints, and USDT probes 336 337positional arguments: 338 pattern search expression for events 339 340optional arguments: 341 -h, --help show this help message and exit 342 -p PID, --pid PID trace this PID only 343 -i INTERVAL, --interval INTERVAL 344 summary interval, seconds 345 -d DURATION, --duration DURATION 346 total duration of trace, seconds 347 -T, --timestamp include timestamp on output 348 -r, --regexp use regular expressions. Default is "*" wildcards 349 only. 350 -D, --debug print BPF program before starting (for debugging 351 purposes) 352 353examples: 354 ./funccount 'vfs_*' # count kernel fns starting with "vfs" 355 ./funccount -r '^vfs.*' # same as above, using regular expressions 356 ./funccount -Ti 5 'vfs_*' # output every 5 seconds, with timestamps 357 ./funccount -d 10 'vfs_*' # trace for 10 seconds only 358 ./funccount -p 185 'vfs_*' # count vfs calls for PID 181 only 359 ./funccount t:sched:sched_fork # count calls to the sched_fork tracepoint 360 ./funccount -p 185 u:node:gc* # count all GC USDT probes in node, PID 185 361 ./funccount c:malloc # count all malloc() calls in libc 362 ./funccount go:os.* # count all "os.*" calls in libgo 363 ./funccount -p 185 go:os.* # count all "os.*" calls in libgo, PID 185 364 ./funccount ./test:read* # count "read*" calls in the ./test binary 365