| Demonstrations of funccount, the Linux eBPF/bcc version. |
| |
| |
| This program traces kernel functions that match a specified pattern, and when |
| Ctrl-C is hit prints a summary of their count while tracing. Eg, tracing all |
| functions that begin with "vfs_": |
| |
| # ./funccount 'vfs_*' |
| Tracing... Ctrl-C to end. |
| ^C |
| ADDR FUNC COUNT |
| ffffffff811efe81 vfs_create 1 |
| ffffffff811f24a1 vfs_rename 1 |
| ffffffff81215191 vfs_fsync_range 2 |
| ffffffff81231df1 vfs_lock_file 30 |
| ffffffff811e8dd1 vfs_fstatat 152 |
| ffffffff811e8d71 vfs_fstat 154 |
| ffffffff811e4381 vfs_write 166 |
| ffffffff811e8c71 vfs_getattr_nosec 262 |
| ffffffff811e8d41 vfs_getattr 262 |
| ffffffff811e3221 vfs_open 264 |
| ffffffff811e4251 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 |
| ADDR FUNC COUNT |
| ffffffff816baf51 tcp_try_undo_recovery 1 |
| ffffffff816cc431 tcp_twsk_destructor 1 |
| ffffffff816bac51 tcp_enter_recovery 1 |
| ffffffff816c6421 tcp_xmit_retransmit_queue 1 |
| ffffffff816b95a1 tcp_update_scoreboard 1 |
| ffffffff816b8921 tcp_verify_retransmit_hint 1 |
| ffffffff816c4dd1 tcp_tsq_handler.part.31 1 |
| ffffffff816bc721 tcp_sacktag_write_queue 1 |
| ffffffff816b8eb1 tcp_match_skb_to_sack 1 |
| ffffffff816cd4b1 tcp_time_wait 1 |
| ffffffff816b8c91 tcp_mark_head_lost 1 |
| ffffffff816b8a71 tcp_init_cwnd_reduction 1 |
| ffffffff816b90e1 tcp_sacktag_one 1 |
| ffffffff816ba7e1 tcp_sacktag_walk 1 |
| ffffffff816c6321 tcp_retransmit_skb 1 |
| ffffffff816c4ec1 tcp_tasklet_func 1 |
| ffffffff816bed01 tcp_resume_early_retransmit 1 |
| ffffffff816b9351 tcp_dsack_set 1 |
| ffffffff816ca181 tcp_v4_syn_recv_sock 2 |
| ffffffff816cd3d1 tcp_ca_openreq_child 2 |
| ffffffff816cfa91 tcp_try_fastopen 2 |
| ffffffff816cd221 tcp_openreq_init_rwin 2 |
| ffffffff816c8931 tcp_v4_init_req 2 |
| ffffffff816cc461 tcp_create_openreq_child 2 |
| ffffffff816cb841 tcp_v4_send_synack 2 |
| ffffffff816c8121 tcp_v4_init_sequence 2 |
| ffffffff816c2ab1 tcp_fragment 2 |
| ffffffff816c9421 tcp_v4_conn_request 2 |
| ffffffff816b99e1 tcp_conn_request 2 |
| ffffffff816c88f1 tcp_v4_route_req 2 |
| ffffffff816c1ea1 tcp_fragment_tstamp 2 |
| ffffffff816b9511 tcp_try_keep_open 2 |
| ffffffff816c8221 tcp_v4_reqsk_destructor 2 |
| ffffffff816c30e1 tcp_may_send_now 2 |
| ffffffff816c24e1 tcp_make_synack 2 |
| ffffffff816cc8f1 tcp_child_process 2 |
| ffffffff816cc9d1 tcp_check_req 2 |
| ffffffff816bbaf1 tcp_fastretrans_alert 2 |
| ffffffff816c8071 tcp_set_keepalive 2 |
| ffffffff816c0cd1 tcp_finish_connect 3 |
| ffffffff816c1e11 tcp_connect_queue_skb 3 |
| ffffffff816c9c51 tcp_v4_connect 3 |
| ffffffff816b3911 tcp_init_sock 3 |
| ffffffff816c9051 tcp_v4_init_sock 3 |
| ffffffff816c5111 tcp_connect 3 |
| ffffffff816b94e1 tcp_any_retrans_done.part.35 3 |
| ffffffff816be881 tcp_clear_retrans 3 |
| ffffffff816b6f21 tcp_setsockopt 4 |
| ffffffff816cf321 tcp_update_metrics 5 |
| ffffffff816b4ee1 tcp_done 5 |
| ffffffff816b8831 tcp_initialize_rcv_mss 5 |
| ffffffff816b8c01 tcp_sndbuf_expand 5 |
| ffffffff816bb921 tcp_fin 5 |
| ffffffff816c7151 tcp_init_xmit_timers 5 |
| ffffffff816b8301 tcp_close 5 |
| ffffffff816cdd91 tcp_init_congestion_control 5 |
| ffffffff816cf4d1 tcp_init_metrics 5 |
| ffffffff816d02b1 tcp_gro_complete 5 |
| ffffffff816b81c1 tcp_free_fastopen_req 5 |
| ffffffff816ca4e1 tcp_v4_destroy_sock 5 |
| ffffffff816cddb1 tcp_cleanup_congestion_control 5 |
| ffffffff816c67b1 tcp_send_fin 5 |
| ffffffff816bd8e1 tcp_init_buffer_space 5 |
| ffffffff816be801 tcp_init_cwnd 5 |
| ffffffff816c1c51 tcp_select_initial_window 5 |
| ffffffff816b8201 tcp_check_oom 5 |
| ffffffff816c2a81 tcp_default_init_rwnd 5 |
| ffffffff816cdc71 tcp_assign_congestion_control 5 |
| ffffffff816b54b1 tcp_getsockopt 6 |
| ffffffff816b3b21 tcp_ioctl 6 |
| ffffffff816c2fe1 tcp_mtup_init 8 |
| ffffffff816b96d1 tcp_parse_options 8 |
| ffffffff816c2f91 tcp_mss_to_mtu 8 |
| ffffffff816bd511 tcp_try_rmem_schedule 8 |
| ffffffff816cf051 tcp_get_metrics 10 |
| ffffffff816ba271 tcp_try_coalesce 10 |
| ffffffff816c0de1 tcp_rcv_state_process 14 |
| ffffffff816c2941 tcp_sync_mss 14 |
| ffffffff816c7e31 tcp_write_timer_handler 15 |
| ffffffff816c8001 tcp_write_timer 16 |
| ffffffff816bb171 tcp_grow_window.isra.27 22 |
| ffffffff816b45b1 tcp_set_state 23 |
| ffffffff816c5921 tcp_send_ack 37 |
| ffffffff816c7641 tcp_delack_timer 42 |
| ffffffff816c7471 tcp_delack_timer_handler 42 |
| ffffffff816c01f1 tcp_validate_incoming 91 |
| ffffffff816b44f1 tcp_prequeue_process 112 |
| ffffffff816cb8f1 tcp_v4_early_demux 117 |
| ffffffff816d08b1 tcp_gro_receive 146 |
| ffffffff816bb5e1 tcp_queue_rcv 167 |
| ffffffff816bdb91 tcp_data_queue 215 |
| ffffffff816ba321 tcp_urg 219 |
| ffffffff816c6c81 tcp_send_delayed_ack 257 |
| ffffffff816b3ee1 tcp_send_mss 275 |
| ffffffff816b3dc1 tcp_push 275 |
| ffffffff816b76c1 tcp_sendmsg 275 |
| ffffffff816bb2a1 tcp_event_data_recv 275 |
| ffffffff816c1d61 tcp_nagle_check 279 |
| ffffffff816c3f11 tcp_write_xmit 282 |
| ffffffff816c2341 tcp_event_new_data_sent 282 |
| ffffffff816c3061 tcp_current_mss 284 |
| ffffffff816c1db1 tcp_init_tso_segs 284 |
| ffffffff816c2871 tcp_wfree 286 |
| ffffffff816c3251 tcp_schedule_loss_probe 305 |
| ffffffff816cb821 tcp_v4_send_check 323 |
| ffffffff816c3581 tcp_transmit_skb 323 |
| ffffffff816b54e1 tcp_recvmsg 323 |
| ffffffff816c2111 tcp_options_write 325 |
| ffffffff816bda61 tcp_rcv_space_adjust 328 |
| ffffffff816bb721 tcp_check_space 332 |
| ffffffff816c04a1 tcp_rcv_established 337 |
| ffffffff816bee61 tcp_ack 337 |
| ffffffff816b9611 tcp_parse_aligned_timestamp.part.43 345 |
| ffffffff816cafc1 tcp_prequeue 346 |
| ffffffff816cab21 tcp_v4_do_rcv 351 |
| ffffffff816cba51 tcp_v4_rcv 351 |
| ffffffff816b8b91 tcp_parse_md5sig_option 351 |
| ffffffff816b3fb1 tcp_cleanup_rbuf 436 |
| ffffffff816b64a1 tcp_poll 468 |
| ffffffff816c1f01 tcp_established_options 604 |
| ffffffff816c82f1 tcp_v4_md5_lookup 615 |
| ffffffff816c4e11 tcp_release_cb 736 |
| ffffffff816bec01 tcp_rearm_rto 843 |
| ffffffff816c8261 tcp_md5_do_lookup 968 |
| Detaching... |
| |
| The current implementation can take many seconds to detach from tracing, after |
| Ctrl-C has been hit. |
| |
| |
| Counting all vfs functions for process ID 5276 only: |
| |
| # ./funccount -p 5276 'vfs_*' |
| Tracing... Ctrl-C to end. |
| ^C |
| ADDR FUNC COUNT |
| ffffffff811e8c71 vfs_getattr_nosec 7 |
| ffffffff811e8d41 vfs_getattr 7 |
| ffffffff811e8dd1 vfs_fstatat 11 |
| ffffffff811e4251 vfs_read 12 |
| ffffffff811e4381 vfs_write 16 |
| Detaching... |
| |
| This matches when that PID is on-CPU and the kernel function is called. |
| |
| |
| An interval can be provided. Eg, printing output every 1 second for vfs calls: |
| |
| # ./funccount -i 1 'vfs_*' |
| Tracing... Ctrl-C to end. |
| |
| ADDR FUNC COUNT |
| ffffffff811e8dd1 vfs_fstatat 1 |
| ffffffff811e8d71 vfs_fstat 16 |
| ffffffff811e8c71 vfs_getattr_nosec 17 |
| ffffffff811e8d41 vfs_getattr 17 |
| ffffffff811e4381 vfs_write 52 |
| ffffffff811e4251 vfs_read 79 |
| ffffffff811e3221 vfs_open 98 |
| |
| ADDR FUNC COUNT |
| ffffffff811e8dd1 vfs_fstatat 10 |
| ffffffff811e8d71 vfs_fstat 10 |
| ffffffff811e3221 vfs_open 13 |
| ffffffff811e8c71 vfs_getattr_nosec 20 |
| ffffffff811e8d41 vfs_getattr 20 |
| ffffffff811e4381 vfs_write 28 |
| ffffffff811e4251 vfs_read 39 |
| |
| ADDR FUNC COUNT |
| ffffffff81215191 vfs_fsync_range 2 |
| ffffffff81231df1 vfs_lock_file 30 |
| ffffffff811e4381 vfs_write 107 |
| ffffffff811e8dd1 vfs_fstatat 129 |
| ffffffff811e8d71 vfs_fstat 130 |
| ffffffff811e3221 vfs_open 154 |
| ffffffff811e8c71 vfs_getattr_nosec 222 |
| ffffffff811e8d41 vfs_getattr 222 |
| ffffffff811e4251 vfs_read 384 |
| ^C |
| ADDR FUNC COUNT |
| ffffffff811e4251 vfs_read 4 |
| ffffffff811e4381 vfs_write 5 |
| 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 |
| ADDR FUNC COUNT |
| ffffffff81260911 ext4_readdir 4 |
| Detaching... |
| |
| Matching "tcp" then "send": |
| |
| # ./funccount '*tcp*send*' |
| Tracing... Ctrl-C to end. |
| ^C |
| ADDR FUNC COUNT |
| ffffffff816c5921 tcp_send_ack 4 |
| ffffffff816c6c81 tcp_send_delayed_ack 19 |
| ffffffff816b3ee1 tcp_send_mss 26 |
| ffffffff816b76c1 tcp_sendmsg 26 |
| ffffffff816cb821 tcp_v4_send_check 30 |
| ffffffff816cb731 __tcp_v4_send_check 30 |
| Detaching... |
| |
| |
| Regular expressions can also be used with the -r option. Eg: |
| |
| # ./funccount -r '^vfs_[rw]' |
| Tracing... Ctrl-C to end. |
| ^C |
| ADDR FUNC COUNT |
| ffffffff811e4381 vfs_write 26 |
| ffffffff811e4251 vfs_read 42 |
| Detaching... |
| |
| |
| Full USAGE: |
| |
| # ./funccount -h |
| usage: funccount [-h] [-p PID] [-i INTERVAL] [-T] [-r] pattern |
| |
| Count kernel function calls |
| |
| 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. |
| |
| examples: |
| ./funccount 'vfs_*' # count kernel functions starting with "vfs" |
| ./funccount 'tcp_send*' # count kernel funcs starting with "tcp_send" |
| ./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 |