forked from iovisor/bcc
/
funccount_example.txt
400 lines (336 loc) · 13.3 KB
/
funccount_example.txt
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
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