Gitiles
Code Review Sign In
gerrit-public.fairphone.software / platform / external / bcc / refs/tags/rel/13/fp3/6.A.018.0 / . / tools / klockstat_example.txt
blob: eff6276d6c58427e892208d95caa8b7e14d28e99 [file] [log] [blame]
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]1Demonstrations of klockstat, the Linux eBPF/bcc version.
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]2
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]3klockstat traces kernel mutex lock events and display locks statistics
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]4
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]5# klockstat.py
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]6Tracing lock events... Hit Ctrl-C to end.
7^C
8 Caller Avg Spin Count Max spin Total spin
9 psi_avgs_work+0x2e 3675 5 5468 18379
10 flush_to_ldisc+0x22 2833 2 4210 5667
11 n_tty_write+0x30c 3914 1 3914 3914
12 isig+0x5d 2390 1 2390 2390
13 tty_buffer_flush+0x2a 1604 1 1604 1604
14 commit_echoes+0x22 1400 1 1400 1400
15 n_tty_receive_buf_common+0x3b9 1399 1 1399 1399
16
17 Caller Avg Hold Count Max hold Total hold
18 flush_to_ldisc+0x22 42558 2 76135 85116
19 psi_avgs_work+0x2e 14821 5 20446 74106
20 n_tty_receive_buf_common+0x3b9 12300 1 12300 12300
21 n_tty_write+0x30c 10712 1 10712 10712
22 isig+0x5d 3362 1 3362 3362
23 tty_buffer_flush+0x2a 3078 1 3078 3078
24 commit_echoes+0x22 3017 1 3017 3017
25
26
27Every caller to using kernel's mutex is displayed on every line.
28
29First portion of lines show the lock acquiring data, showing the
30amount of time it took to acquired given lock.
31
32 'Caller' - symbol acquiring the mutex
33 'Average Spin' - average time to acquire the mutex
34 'Count' - number of times mutex was acquired
35 'Max spin' - maximum time to acquire the mutex
36 'Total spin' - total time spent in acquiring the mutex
37
38Second portion of lines show the lock holding data, showing the
39amount of time it took to hold given lock.
40
41 'Caller' - symbol holding the mutex
42 'Average Hold' - average time mutex was held
43 'Count' - number of times mutex was held
44 'Max hold' - maximum time mutex was held
45 'Total hold' - total time spent in holding the mutex
46
47This works by tracing mutex_lock/unlock kprobes, updating the
48lock stats in maps and processing them in the python part.
49
50
51An -i option can be used to display stats in interval (5 seconds in example below):
52
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]53# klockstat.py -i 5
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]54Tracing lock events... Hit Ctrl-C to end.
55
56 Caller Avg Spin Count Max spin Total spin
57 psi_avgs_work+0x2e 3822 15 5650 57338
58 flush_to_ldisc+0x22 4630 1 4630 4630
59 work_fn+0x4f 4185 1 4185 4185
60
61 Caller Avg Hold Count Max hold Total hold
62 psi_avgs_work+0x2e 12155 15 15739 182329
63 flush_to_ldisc+0x22 13809 1 13809 13809
64 work_fn+0x4f 5274 1 5274 5274
65
66 Caller Avg Spin Count Max spin Total spin
67 psi_avgs_work+0x2e 3715 17 4374 63163
68
69 Caller Avg Hold Count Max hold Total hold
70 psi_avgs_work+0x2e 13141 17 19510 223399
71^C
72
73
74A -p option can be used to trace only selected process:
75
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]76# klockstat.py -p 883
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]77Tracing lock events... Hit Ctrl-C to end.
78^C
79 Caller Avg Spin Count Max spin Total spin
80 pipe_wait+0xa9 625 412686 16930 258277958
81 pipe_read+0x3f 420 413425 16872 174017649
82 pipe_write+0x35 471 413425 16765 194792253
83
84 Caller Avg Hold Count Max hold Total hold
85 pipe_read+0x3f 473 413425 20063 195773647
86 pipe_wait+0xa9 604 412686 16972 249598153
87 pipe_write+0x35 481 413425 16944 199008064
88
89
90A -c option can be used to display only callers with specific substring:
91
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]92# klockstat.py -c pipe_
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]93Tracing lock events... Hit Ctrl-C to end.
94^C
95 Caller Avg Spin Count Max spin Total spin
96 pipe_read+0x3f 422 469554 18665 198354705
97 pipe_wait+0xa9 679 469536 17196 319017069
98 pipe_write+0x35 469 469554 17057 220338525
99
100 Caller Avg Hold Count Max hold Total hold
101 pipe_write+0x35 638 469554 17330 299857180
102 pipe_wait+0xa9 779 469535 16912 366047392
103 pipe_read+0x3f 575 469554 13251 270005394
104
105
106An -n option can be used to display only specific number of callers:
107
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]108# klockstat.py -n 3
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]109Tracing lock events... Hit Ctrl-C to end.
110^C
111 Caller Avg Spin Count Max spin Total spin
112 pipe_read+0x3f 420 334120 16964 140632284
113 pipe_wait+0xa9 688 334116 16876 229957062
114 pipe_write+0x35 463 334120 16791 154981747
115
116 Caller Avg Hold Count Max hold Total hold
117 flush_to_ldisc+0x22 27754 3 63270 83264
118 pipe_read+0x3f 571 334120 17123 190976463
119 pipe_wait+0xa9 759 334115 17068 253747213
120
121
122An -s option can be used to display number of callers backtrace entries:
123
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]124# klockstat.py -n 1 -s 3
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]125Tracing lock events... Hit Ctrl-C to end.
126^C
127 Caller Avg Spin Count Max spin Total spin
128 pipe_wait+0xa9 685 811947 17376 556542328
129 pipe_wait+0xa9
130 pipe_read+0x206
131
132 Caller Avg Hold Count Max hold Total hold
133 flush_to_ldisc+0x22 28145 3 63872 84437
134 flush_to_ldisc+0x22
135 process_one_work+0x1b0
136
137
138Output can be sorted by using -S <fields> option on various
139fields, the acq_total will force the acquired table to be
140sorted on 'Total spin' column:
141
Yonghong Song71f9c2a2019-12-04 19:45:27 -0800[diff] [blame]142# klockstat.py -S acq_total
Jiri Olsaac00ac52019-11-15 12:45:59 +0100[diff] [blame]143Tracing lock events... Hit Ctrl-C to end.
144^C
145 Caller Avg Spin Count Max spin Total spin
146 pipe_wait+0xa9 691 269343 17190 186263983
147 pipe_write+0x35 464 269351 11730 125205417
148 pipe_read+0x3f 422 269351 17107 113724697
149 psi_avgs_work+0x2e 2499 11 4454 27494
150 flush_to_ldisc+0x22 3111 3 5096 9334
151 n_tty_write+0x30c 2764 1 2764 2764
152 isig+0x5d 1287 1 1287 1287
153 tty_buffer_flush+0x2a 961 1 961 961
154 commit_echoes+0x22 892 1 892 892
155 n_tty_receive_buf_common+0x3b9 868 1 868 868
156
157 Caller Avg Hold Count Max hold Total hold
158 pipe_wait+0xa9 788 269343 17128 212496240
159 pipe_write+0x35 637 269351 17209 171596811
160 pipe_read+0x3f 585 269351 11834 157606323
161 psi_avgs_work+0x2e 8726 11 19177 95996
162 flush_to_ldisc+0x22 22158 3 43731 66474
163 n_tty_write+0x30c 9770 1 9770 9770
164 n_tty_receive_buf_common+0x3b9 6830 1 6830 6830
165 isig+0x5d 3114 1 3114 3114
166 tty_buffer_flush+0x2a 2032 1 2032 2032
167 commit_echoes+0x22 1616 1 1616 1616