forked from iovisor/bcc
-
Notifications
You must be signed in to change notification settings - Fork 0
/
f2fsslower_example.txt
250 lines (234 loc) · 17.2 KB
/
f2fsslower_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
Demonstrations of f2fsslower, the Linux eBPF/bcc version.
f2fsslower shows f2fs reads, writes, opens, and fsyncs, slower than a threshold.
For example:
# ./f2fsslower
Tracing f2fs operations slower than 10 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
07:20:43 StatStore 25169 S 0 0 22.23 com.happyelements.AndroidAnimal_
07:21:21 binder:912_3 912 R 131112 0 14.66 8.bin
07:21:40 LazyTaskWriter 912 S 0 0 28.05 112_task.xml.new
07:22:01 TaskSnapshotPe 912 S 0 0 21.47 112.proto.new
07:22:11 mobile_log_d.w 1048 W 262137 40198 11.06 main_log_2022_1205_071604.curf
07:22:15 binder:912_1A 912 R 131108 0 13.92 29.bin
07:22:18 LazyTaskWriter 912 S 0 0 28.64 112_task.xml.new
07:22:21 mobile_log_d.w 1048 W 262084 41478 11.88 main_log_2022_1205_071604.curf
07:22:26 LazyTaskWriter 912 S 0 0 27.75 112_task.xml.new
07:22:37 binder:912_17 912 R 131108 0 16.16 25.bin
07:22:39 LazyTaskWriter 912 S 0 0 22.53 112_task.xml.new
07:22:43 TaskSnapshotPe 912 S 0 0 19.32 112.proto.new
07:22:47 LazyTaskWriter 912 S 0 0 25.88 112_task.xml.new
07:22:57 LazyTaskWriter 912 S 0 0 20.77 112_task.xml.new
07:22:57 LazyTaskWriter 912 S 0 0 11.00 112_task.xml.new
07:23:06 LazyTaskWriter 912 S 0 0 21.36 112_task.xml.new
07:23:53 mobile_log_d.w 1048 W 262026 3026 10.28 main_log_2022_1205_072303.curf
07:24:05 s.AndroidAnima 17273 S 0 0 20.18 tbs_download_config.xml
07:24:20 GLThread 42 17273 S 0 0 32.27 Cocos2dxPrefsFile.xml
07:24:23 GLThread 42 17273 S 0 0 19.84 Cocos2dxPrefsFile.xml
07:24:32 GLThread 42 17273 S 0 0 20.27 Cocos2dxPrefsFile.xml
07:24:43 StatStore 17273 S 0 0 20.32 com.happyelements.AndroidAnimal_
07:24:51 StatStore 18046 S 0 0 16.82 com.happyelements.AndroidAnimal_
07:25:01 s.AndroidAnima 18046 S 0 0 19.61 com.happyelements.AndroidAnimal_
07:25:06 GLThread 42 18046 S 0 0 21.33 Cocos2dxPrefsFile.xml
07:25:18 GLThread 42 18046 S 0 0 19.98 Cocos2dxPrefsFile.xml
07:25:21 GLThread 42 18046 S 0 0 20.57 log_data_19.log
07:25:34 GLThread 42 18046 S 0 0 21.82 log_data_19.log
07:26:44 GLThread 42 18046 S 0 0 28.13 Cocos2dxPrefsFile.xml
07:29:02 GLThread 42 18046 S 0 0 26.31 Cocos2dxPrefsFile.xml
07:29:07 GLThread 42 18046 S 0 0 21.80 log_data_19.log
07:29:22 android.bg 912 S 0 0 23.04 mappings.new
07:30:11 GLThread 42 18046 S 0 0 27.54 Cocos2dxPrefsFile.xml
07:31:16 GLThread 42 18046 S 0 0 22.04 Cocos2dxPrefsFile.xml
07:31:59 android.bg 912 S 0 0 40.25 appops
07:32:35 GLThread 42 18046 S 0 0 25.72 log_data_19.log
07:33:50 GLThread 42 18046 S 0 0 20.86 log_data_19.log
07:35:33 GLThread 42 18046 S 0 0 21.47 log_data_19.log
07:35:47 GLThread 42 18046 S 0 0 28.71 Cocos2dxPrefsFile.xml
07:35:53 GLThread 42 18046 S 0 0 22.43 log_data_19.log
07:36:29 StatStore 18046 S 0 0 20.47 com.happyelements.AndroidAnimal_
07:36:37 LazyTaskWriter 912 S 0 0 22.53 114_task.xml.new
07:38:02 GLThread 42 18046 S 0 0 25.43 Cocos2dxPrefsFile.xml
07:39:42 GLThread 42 18046 R 30 118172 23.11 base.apk
07:39:47 GLThread 42 18046 S 0 0 21.28 log_data_19.log
07:40:45 GLThread 42 18046 S 0 0 20.56 log_data_19.log
This shows various system tasks reading from f2fs.
This "latency" is measured from when the operation was issued from the VFS
interface to the file system, to when it completed. This spans everything:
block device I/O (disk I/O), file system CPU cycles, file system locks, run
queue latency, etc. This is a better measure of the latency suffered by
applications reading from the file system than measuring this down at the
block device interface.
Note that this only traces the common file system operations previously
listed: other file system operations (eg, inode operations including
getattr()) are not traced.
The threshold can be provided as an argument. Eg, I/O slower than 1 ms:
# ./f2fsslower 1
Tracing f2fs operations slower than 1 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
03:21:58 mobile_log_d.w 1048 W 261969 15920 2.75 main_log_2022_1208_031540.curf
03:22:03 mobile_log_d.w 1048 W 247156 22098 1.47 adsp_0_log_2022_1208_030243.curf
03:22:04 mobile_log_d.w 1048 W 262019 16176 1.56 main_log_2022_1208_031540.curf
03:22:07 mobile_log_d.w 1048 W 262122 1930 1.62 radio_log_2022_1208_031907.curf
03:22:07 mobile_log_d.w 1048 W 262114 16432 2.63 main_log_2022_1208_031540.curf
03:22:09 mobile_log_d.w 1048 W 262036 16688 2.90 main_log_2022_1208_031540.curf
03:22:11 mobile_log_d.w 1048 W 262002 16944 2.87 main_log_2022_1208_031540.curf
03:22:12 GLThread 42 18046 S 0 0 26.64 Cocos2dxPrefsFile.xml
03:22:13 mobile_log_d.w 1048 W 262138 17200 2.85 main_log_2022_1208_031540.curf
03:22:13 mobile_log_d.w 1048 W 247156 22339 1.70 adsp_0_log_2022_1208_030243.curf
03:22:15 mobile_log_d.w 1048 W 262127 17456 2.76 main_log_2022_1208_031540.curf
03:22:17 GLThread 42 18046 S 0 0 20.30 log_data_19.log
03:22:18 mobile_log_d.w 1048 W 262132 17712 3.00 main_log_2022_1208_031540.curf
03:22:20 mobile_log_d.w 1048 W 262079 17968 2.88 main_log_2022_1208_031540.curf
03:22:23 mobile_log_d.w 1048 W 262037 18224 3.06 main_log_2022_1208_031540.curf
03:22:23 mobile_log_d.w 1048 W 250068 22581 1.54 adsp_0_log_2022_1208_030243.curf
03:22:23 mobile_log_d.w 1048 W 245760 22825 1.14 adsp_0_log_2022_1208_030243.curf
03:22:24 mobile_log_d.w 1048 W 261988 18480 3.17 main_log_2022_1208_031540.curf
03:22:26 mobile_log_d.w 1048 W 262096 18736 2.81 main_log_2022_1208_031540.curf
03:22:28 mobile_log_d.w 1048 W 262056 2186 2.78 radio_log_2022_1208_031907.curf
03:22:28 mobile_log_d.w 1048 W 261992 18991 2.69 main_log_2022_1208_031540.curf
03:22:30 mobile_log_d.w 1048 W 262030 19247 2.97 main_log_2022_1208_031540.curf
03:22:31 GLThread 42 18046 S 0 0 20.65 log_data_19.log
03:22:31 mobile_log_d.w 1048 W 262098 19503 2.95 main_log_2022_1208_031540.curf
03:22:33 mobile_log_d.w 1048 W 261680 19759 2.26 main_log_2022_1208_031540.curf
03:22:33 mobile_log_d.w 1048 W 242579 23065 1.50 adsp_0_log_2022_1208_030243.curf
03:22:33 mobile_log_d.w 1048 W 245760 23302 1.16 adsp_0_log_2022_1208_030243.curf
03:22:35 mobile_log_d.w 1048 W 262030 20015 2.84 main_log_2022_1208_031540.curf
03:22:37 mobile_log_d.w 1048 W 262011 20271 2.65 main_log_2022_1208_031540.curf
03:22:38 mobile_log_d.w 1048 W 262089 20526 1.48 main_log_2022_1208_031540.curf
03:22:39 mobile_log_d.w 1048 W 262127 20782 2.90 main_log_2022_1208_031540.curf
03:22:40 mobile_log_d.w 1048 W 262081 21038 3.29 main_log_2022_1208_031540.curf
03:22:41 mobile_log_d.w 1048 W 262069 21294 2.79 main_log_2022_1208_031540.curf
03:22:42 GLThread 42 18046 S 0 0 20.37 log_data_19.log
03:22:43 mobile_log_d.w 1048 W 261791 21550 3.30 main_log_2022_1208_031540.curf
03:22:43 mobile_log_d.w 1048 W 257177 23542 1.17 adsp_0_log_2022_1208_030243.curf
03:22:43 mobile_log_d.w 1048 W 245760 23793 1.19 adsp_0_log_2022_1208_030243.curf
03:22:44 mobile_log_d.w 1048 W 262102 21806 2.27 main_log_2022_1208_031540.curf
03:22:46 mobile_log_d.w 1048 W 167051 22062 1.74 main_log_2022_1208_031540.curf
03:22:46 mobile_log_d.w 1048 W 224792 2442 2.02 radio_log_2022_1208_031907.curf
03:22:48 mobile_log_d.w 1048 W 262090 22225 3.00 main_log_2022_1208_031540.curf
03:22:50 mobile_log_d.w 1048 W 262046 22481 3.89 main_log_2022_1208_031540.curf
03:22:51 mobile_log_d.w 1048 W 262088 22737 1.35 main_log_2022_1208_031540.curf
03:22:53 mobile_log_d.w 1048 W 262100 22993 2.82 main_log_2022_1208_031540.curf
03:22:53 mobile_log_d.w 1048 W 257957 24033 1.50 adsp_0_log_2022_1208_030243.curf
This time a cksum(1) command can be seen reading various files (from /usr/bin).
A threshold of 0 will trace all operations. Warning: the output will be
verbose, as it will include all file system cache hits.
# ./f2fsslower 0
Tracing f2fs operations
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
05:56:41 f2fsslowertest 6802 O 0 0 0.01 utf_8.py
05:56:41 f2fsslowertest 6802 O 0 0 0.00 utf_8.pyc
05:56:41 f2fsslowertest 6802 R 1950 0 0.01 utf_8.pyc
05:56:41 f2fsslowertest 6802 R 0 1 0.00 utf_8.pyc
05:56:41 mobile_log_d.w 1048 W 262035 5842 2.70 main_log_2022_1208_055544.curf
05:56:42 GLThread 42 18046 R 30 45062 0.03 base.apk
05:56:42 GLThread 42 18046 R 90 45062 0.01 base.apk
05:56:44 mobile_log_d.w 1048 W 262027 6098 1.09 main_log_2022_1208_055544.curf
05:56:45 binder:1035_1 1035 R 2048 53764 0.04 base.apk
05:56:45 binder:1035_1 1035 R 2048 53766 0.01 base.apk
05:56:45 binder:1035_1 1035 R 2048 53768 0.01 base.apk
05:56:45 binder:1035_1 1035 R 2048 53770 0.01 base.apk
05:56:45 binder:1035_1 1035 R 2048 53772 0.01 base.apk
05:56:45 binder:1035_1 1035 R 2048 53774 0.00 base.apk
05:56:45 binder:1035_1 1035 R 2048 53776 0.00 base.apk
05:56:45 binder:1035_1 1035 R 2048 53778 0.00 base.apk
05:56:45 binder:1035_1 1035 R 2048 53780 0.00 base.apk
05:56:45 binder:1035_1 1035 R 2048 53782 0.00 base.apk
05:56:45 binder:1035_1 1035 R 2048 53784 0.00 base.apk
05:56:46 GLThread 42 18046 R 30 45062 0.03 base.apk
05:56:46 GLThread 42 18046 R 90 45062 0.01 base.apk
05:56:46 mobile_log_d.w 1048 W 233943 6354 2.51 main_log_2022_1208_055544.curf
05:56:46 mobile_log_d.w 1048 W 756 13956 0.32 events_log_2022_1123_004218.curf
05:56:46 mobile_log_d.w 1048 W 838 1690 0.08 sys_log_2022_1206_223338.curf
05:56:46 mobile_log_d.w 1048 W 0 4 0.02 crash_log_2022_1123_004218.curf
05:56:46 mobile_log_d.w 1048 W 223834 6553 1.39 radio_log_2022_1208_054728.curf
05:56:46 mobile_log_d.w 1048 W 258381 33557 1.51 adsp_0_log_2022_1208_054540.curf
05:56:46 mobile_log_d.w 1048 W 245760 33809 1.30 adsp_0_log_2022_1208_054540.curf
05:56:46 mobile_log_d.w 1048 O 0 0 0.01 mblog_history
05:56:46 mobile_log_d.w 1048 W 84 0 0.04 mblog_history
05:56:46 mobile_log_d.w 1048 O 0 0 0.01 mblog_history
05:56:46 mobile_log_d.w 1048 W 84 4043 0.05 mblog_history
05:56:47 binder:1035_1 1035 R 2048 53786 0.14 base.apk
05:56:47 binder:1035_1 1035 R 2048 53788 0.06 base.apk
05:56:47 binder:1035_1 1035 R 2048 53790 0.05 base.apk
05:56:47 binder:1035_1 1035 R 2048 53792 0.03 base.apk
05:56:47 binder:1035_1 1035 R 2048 53794 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53796 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53798 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53800 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53802 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53804 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53806 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53808 0.09 base.apk
05:56:47 binder:1035_1 1035 R 2048 53810 0.03 base.apk
05:56:47 binder:1035_1 1035 R 2048 53812 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53814 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53816 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53818 0.01 base.apk
05:56:47 binder:1035_1 1035 R 2048 53820 0.01 base.apk
The output now includes open operations ("O"), and writes ("W").
A -s option will print just the fields (parsable output, csv):
# ./f2fsslower -s 1
ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE
1316211823309,mobile_log_d.wr,1048,W,262131,38840382,2661,main_log_2022_1208_061729.curf
1316212810823,mobile_log_d.wr,1048,W,258559,23600773,1204,adsp_0_log_2022_1208_061547.curf
1316212872372,mobile_log_d.wr,1048,W,245760,23859332,1005,adsp_0_log_2022_1208_061547.curf
1316214082932,mobile_log_d.wr,1048,W,262057,39102513,2624,main_log_2022_1208_061729.curf
1316216669137,mobile_log_d.wr,1048,W,261982,39364570,3118,main_log_2022_1208_061729.curf
1316218993842,mobile_log_d.wr,1048,W,262089,39626552,1664,main_log_2022_1208_061729.curf
1316221426544,mobile_log_d.wr,1048,W,262051,39888641,2989,main_log_2022_1208_061729.curf
1316222951157,mobile_log_d.wr,1048,W,257177,24350852,1658,adsp_0_log_2022_1208_061547.curf
1316222954073,mobile_log_d.wr,1048,W,245760,24608029,1164,adsp_0_log_2022_1208_061547.curf
1316223791680,mobile_log_d.wr,1048,W,262069,40150692,2801,main_log_2022_1208_061729.curf
1316226044789,mobile_log_d.wr,1048,W,262035,40412761,2886,main_log_2022_1208_061729.curf
1316228166571,mobile_log_d.wr,1048,W,226979,40674796,2374,main_log_2022_1208_061729.curf
1316228181155,mobile_log_d.wr,1048,W,222758,4736186,1970,radio_log_2022_1208_061707.curf
1316230622583,mobile_log_d.wr,1048,W,262114,40901775,2776,main_log_2022_1208_061729.curf
1316233026221,mobile_log_d.wr,1048,W,257601,24853789,1257,adsp_0_log_2022_1208_061547.curf
1316233029535,mobile_log_d.wr,1048,W,245760,25111390,1561,adsp_0_log_2022_1208_061547.curf
1316233113497,mobile_log_d.wr,1048,W,261997,41163889,3589,main_log_2022_1208_061729.curf
1316235354557,mobile_log_d.wr,1048,W,262049,41425886,2787,main_log_2022_1208_061729.curf
1316238063027,mobile_log_d.wr,1048,W,262069,41687935,2696,main_log_2022_1208_061729.curf
1316242949074,mobile_log_d.wr,1048,W,262070,42212109,2973,main_log_2022_1208_061729.curf
1316243120504,mobile_log_d.wr,1048,W,257355,25357150,1507,adsp_0_log_2022_1208_061547.curf
1316243125525,mobile_log_d.wr,1048,W,245760,25614505,1946,adsp_0_log_2022_1208_061547.curf
1316245305141,mobile_log_d.wr,1048,W,262032,42474179,3083,main_log_2022_1208_061729.curf
1316247588708,mobile_log_d.wr,1048,W,262004,42736211,2967,main_log_2022_1208_061729.curf
1316249295257,mobile_log_d.wr,1048,W,262057,4958944,2578,radio_log_2022_1208_061707.curf
1316250106164,mobile_log_d.wr,1048,W,262010,42998215,2840,main_log_2022_1208_061729.curf
1316252410939,mobile_log_d.wr,1048,W,262106,43260225,2628,main_log_2022_1208_061729.curf
1316253204981,mobile_log_d.wr,1048,W,258381,25860265,1517,adsp_0_log_2022_1208_061547.curf
1316253208316,mobile_log_d.wr,1048,W,245760,26118646,1503,adsp_0_log_2022_1208_061547.curf
1316254946402,mobile_log_d.wr,1048,W,262004,43522331,2816,main_log_2022_1208_061729.curf
1316257209188,mobile_log_d.wr,1048,W,262026,43784335,4450,main_log_2022_1208_061729.curf
1316259556796,mobile_log_d.wr,1048,W,262032,44046361,2833,main_log_2022_1208_061729.curf
1316261921117,mobile_log_d.wr,1048,W,262013,44308393,1357,main_log_2022_1208_061729.curf
1316263243764,mobile_log_d.wr,1048,W,24303,6765649,1016,bsp_log_2022_1208_014047.curf
1316263251662,mobile_log_d.wr,1048,W,160077,26364406,1244,adsp_0_log_2022_1208_061547.curf
1316264438110,mobile_log_d.wr,1048,W,262131,44570406,1672,main_log_2022_1208_061729.curf
1316266865336,mobile_log_d.wr,1048,W,262067,44832537,1692,main_log_2022_1208_061729.curf
1316269146218,mobile_log_d.wr,1048,W,262023,45094604,3041,main_log_2022_1208_061729.curf
1316270305799,mobile_log_d.wr,1048,W,262111,5221001,2913,radio_log_2022_1208_061707.curf
1316271863947,mobile_log_d.wr,1048,W,262071,45356627,2915,main_log_2022_1208_061729.curf
1316273312225,mobile_log_d.wr,1048,W,255036,26770243,3875,adsp_0_log_2022_1208_061547.curf
1316273395545,mobile_log_d.wr,1048,W,245760,27025279,6162,adsp_0_log_2022_1208_061547.curf
1316273398118,mobile_log_d.wr,1048,W,245760,27271039,1846,adsp_0_log_2022_1208_061547.curf
1316274180566,mobile_log_d.wr,1048,W,262010,45618698,2867,main_log_2022_1208_061729.curf
This may be useful for visualizing with another tool, for example, for
producing a scatter plot of ENDTIME vs LATENCY, to look for time-based
patterns.
USAGE message:
# ./f2fsslower -h
usage: f2fsslower [-h] [-s] [-p PID] [min_ms]
Trace common f2fs file operations slower than a threshold
positional arguments:
min_ms minimum I/O duration to trace, in ms (default 10)
optional arguments:
-h, --help show this help message and exit
-s, --csv just print fields: comma-separated values
-p PID, --pid PID trace this PID only
examples:
./f2fsslower # trace operations slower than 10 ms (default)
./f2fsslower 1 # trace operations slower than 1 ms
./f2fsslower -s 1 # ... 1 ms, parsable output (csv)
./f2fsslower 0 # trace all operations (warning: verbose)
./f2fsslower -p 185 # trace PID 185 only