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