| 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 |
