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