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
|
Demonstrations of funccount, the Linux ftrace version.
Tracing all kernel functions that start with "bio_" (which would be block
interface functions), and counting how many times they were executed until
Ctrl-C is hit:
# ./funccount 'bio_*'
Tracing "bio_*"... Ctrl-C to end.
^C
FUNC COUNT
bio_attempt_back_merge 26
bio_get_nr_vecs 361
bio_alloc 536
bio_alloc_bioset 536
bio_endio 536
bio_free 536
bio_fs_destructor 536
bio_init 536
bio_integrity_enabled 536
bio_put 729
bio_add_page 1004
Note that these counts are performed in-kernel context, using the ftrace
function profiler, which means this is a (relatively) low overhead technique.
Test yourself to quantify overhead.
As was demonstrated here, wildcards can be used. Individual functions can also
be specified. For example, all of the following are valid arguments:
bio_init
bio_*
*init
*bio*
A "*" within a string (eg, "bio*init") is not supported.
The full list of what can be traced is in:
/sys/kernel/debug/tracing/available_filter_functions, which can be grep'd to
check what is there. Note that grep uses regular expressions, whereas
funccount uses globbing for wildcards.
Counting all "tcp_" kernel functions, and printing a summary every one second:
# ./funccount -i 1 -t 5 'tcp_*'
Tracing "tcp_*". Top 5 only... Ctrl-C to end.
FUNC COUNT
tcp_cleanup_rbuf 386
tcp_service_net_dma 386
tcp_established_options 549
tcp_v4_md5_lookup 560
tcp_v4_md5_do_lookup 890
FUNC COUNT
tcp_service_net_dma 498
tcp_cleanup_rbuf 499
tcp_established_options 664
tcp_v4_md5_lookup 672
tcp_v4_md5_do_lookup 1071
[...]
Neat.
Tracing all "ext4*" kernel functions for 10 seconds, and printing the top 25:
# ./funccount -t 25 -d 10 'ext4*'
Tracing "ext4*" for 10 seconds. Top 25 only...
FUNC COUNT
ext4_inode_bitmap 840
ext4_meta_trans_blocks 840
ext4_ext_drop_refs 843
ext4_find_entry 845
ext4_discard_preallocations 1008
ext4_free_inodes_count 1120
ext4_group_desc_csum 1120
ext4_group_desc_csum_set 1120
ext4_getblk 1128
ext4_es_free_extent 1328
ext4_map_blocks 1471
ext4_es_lookup_extent 1751
ext4_mb_check_limits 1873
ext4_es_lru_add 2031
ext4_data_block_valid 2312
ext4_journal_check_start 3080
ext4_mark_inode_dirty 5320
ext4_get_inode_flags 5955
ext4_get_inode_loc 5955
ext4_mark_iloc_dirty 5955
ext4_reserve_inode_write 5955
ext4_inode_table 7076
ext4_get_group_desc 8476
ext4_has_inline_data 9492
ext4_inode_touch_time_cmp 38980
Ending tracing...
So ext4_inode_touch_time_cmp() was called the most frequently, at 38,980 times.
This may be normal, this may not. The purpose of this tool is to give you one
view of how one or many kernel functions are executed. Previously I had little
idea what ext4 was doing internally. Now I know the top 25 functions, and their
rate, and can begin researching them from the source code.
Use -h to print the USAGE message:
# ./funccount -h
USAGE: funccount [-hT] [-i secs] [-d secs] [-t top] funcstring
-d seconds # total duration of trace
-h # this usage message
-i seconds # interval summary
-t top # show top num entries only
-T # include timestamp (for -i)
eg,
funccount 'vfs*' # trace all funcs that match "vfs*"
funccount -d 5 'tcp*' # trace "tcp*" funcs for 5 seconds
funccount -t 10 'ext3*' # show top 10 "ext3*" funcs
funccount -i 1 'ext3*' # summary every 1 second
funccount -i 1 -d 5 'ext3*' # 5 x 1 second summaries
See the man page and example file for more info.
|
