On Tue, Jul 09, 2019 at 11:18:38PM +0200, Andrea Vai wrote: > On 08/07/19 09:01:35, Ming Lei wrote: > > > > > > > > > > > > > > > > > > commit f664a3cc17b7d0a2bc3b3ab96181e1029b0ec0e6 > > > > > > > > > > > > > > > > > > [...] > > > > 1) run the bcc biosnoop trace in one terminal after mounting the fs on the USB dirve > > > > 2) start the write test in another teminal > > > > 3) wait for 10 seconds, and stop the bcc trace via ctrl^ + C, then post the bcc biosnoop > > trace log > > > > Done, attached. > > Thanks, > Andrea > 5.420198000 jbd2/sdf1-8 6775 sdf W 29624320 4096 0.37 > 5.423601000 jbd2/sdf1-8 6775 sdf W 29624328 12288 3.29 > 5.424009000 jbd2/sdf1-8 6775 sdf W 29624352 4096 0.30 > 6.665732000 kworker/u8:0 6401 sdf R 10248 4096 841.64 > 6.666891000 kworker/u8:0 6401 sdf R 10256 4096 0.98 > 6.668141000 kworker/u8:0 6401 sdf R 4196352 4096 1.07 > 6.669312000 kworker/u8:0 6401 sdf R 8390656 4096 0.99 > 6.670568000 kworker/u8:0 6401 sdf R 12584960 4096 1.06 > 6.674257000 kworker/u8:0 6401 sdf R 16779264 4096 3.50 > 6.675510000 kworker/u8:0 6401 sdf R 20973568 4096 1.06 > 6.678344000 kworker/u8:0 6401 sdf R 25167872 4096 2.64 > 6.680384000 kworker/u8:0 6401 sdf R 29362176 4096 1.83 > 6.681622000 kworker/u8:0 6401 sdf R 33556480 4096 1.03 > 6.682713000 kworker/u8:0 6401 sdf R 37750784 4096 0.92 > 6.686360000 kworker/u8:0 6401 sdf R 41945088 4096 3.48 > 6.687589000 kworker/u8:0 6401 sdf R 46139392 4096 1.04 > 6.688639000 kworker/u8:0 6401 sdf R 46139424 4096 0.88 > 6.766336000 kworker/u8:0 6401 sdf W 47351808 122880 77.17 > 6.773563000 kworker/u8:0 6401 sdf W 47352048 122880 7.08 > 6.780980000 kworker/u8:0 6401 sdf W 47352288 122880 7.29 > 6.786366000 kworker/u8:0 6401 sdf W 47352528 122880 5.27 > 6.793831000 kworker/u8:0 6401 sdf W 47352768 122880 7.38 > 6.801085000 kworker/u8:0 6401 sdf W 47353008 122880 7.20 > 6.808405000 kworker/u8:0 6401 sdf W 47353248 122880 7.27 > 6.813799000 kworker/u8:0 6401 sdf W 47353488 122880 5.35 > 6.821103000 kworker/u8:0 6401 sdf W 47353728 118784 7.25 > 6.828459000 kworker/u8:0 6401 sdf W 47353960 122880 7.09 > 6.835722000 kworker/u8:0 6401 sdf W 47354200 122880 7.20 > 6.842813000 kworker/u8:0 6401 sdf W 47354440 122880 7.05 > 6.850184000 kworker/u8:0 6401 sdf W 47354680 122880 7.32 > 6.857452000 kworker/u8:0 6401 sdf W 47354920 122880 7.22 > 6.864874000 kworker/u8:0 6401 sdf W 47355160 122880 7.38 > 6.871841000 kworker/u8:0 6401 sdf W 47355400 122880 6.92 > 6.879380000 kworker/u8:0 6401 sdf W 47355640 122880 7.50 > 6.886497000 kworker/u8:0 6401 sdf W 47355880 122880 7.04 > 6.893940000 kworker/u8:0 6401 sdf W 47356120 122880 7.40 > 6.899304000 kworker/u8:0 6401 sdf W 47356360 122880 5.33 > 6.906635000 kworker/u8:0 6401 sdf W 47356600 122880 7.29 > 6.913957000 kworker/u8:0 6401 sdf W 47356840 122880 7.29 > 6.921308000 kworker/u8:0 6401 sdf W 47357080 122880 7.31 > 6.924391000 kworker/u8:0 6401 sdf W 47357320 53248 3.03 > 6.931971000 kworker/u8:0 6401 sdf W 47357424 122880 7.22 > 6.939169000 kworker/u8:0 6401 sdf W 47357664 122880 7.14 > 6.944985000 kworker/u8:0 6401 sdf W 47357904 122880 5.76 > 6.952113000 kworker/u8:0 6401 sdf W 47358144 122880 7.06 > 6.959608000 kworker/u8:0 6401 sdf W 47358384 122880 7.45 > 6.966820000 kworker/u8:0 6401 sdf W 47358624 122880 7.16 > 6.972393000 kworker/u8:0 6401 sdf W 47358864 122880 5.53 > 6.979550000 kworker/u8:0 6401 sdf W 47359104 122880 7.09 > 6.986879000 kworker/u8:0 6401 sdf W 47359344 122880 7.28 > 6.994306000 kworker/u8:0 6401 sdf W 47359584 122880 7.40 > 7.001338000 kworker/u8:0 6401 sdf W 47359824 122880 6.98 > 7.008740000 kworker/u8:0 6401 sdf W 47360064 122880 7.37 > 7.016114000 kworker/u8:0 6401 sdf W 47360304 122880 7.31 > 7.023546000 kworker/u8:0 6401 sdf W 47360544 122880 7.39 > 7.030437000 kworker/u8:0 6401 sdf W 47360784 122880 6.82 > 7.037834000 kworker/u8:0 6401 sdf W 47361024 122880 7.35 > 7.045224000 kworker/u8:0 6401 sdf W 47361264 122880 7.32 > 7.052687000 kworker/u8:0 6401 sdf W 47361504 122880 7.39 > 7.057977000 kworker/u8:0 6401 sdf W 47361744 122880 5.01 > 7.065390000 kworker/u8:0 6401 sdf W 47361984 122880 7.35 > 7.072749000 kworker/u8:0 6401 sdf W 47362224 122880 7.28 > 7.080174000 kworker/u8:0 6401 sdf W 47362464 122880 7.36 > 7.085335000 kworker/u8:0 6401 sdf W 47362704 122880 5.08 > 7.092881000 kworker/u8:0 6401 sdf W 47362944 122880 7.50 > 7.100197000 kworker/u8:0 6401 sdf W 47363184 122880 7.23 > 7.107507000 kworker/u8:0 6401 sdf W 47363424 122880 7.24 > 7.114684000 kworker/u8:0 6401 sdf W 47363664 122880 7.09 > 7.121936000 kworker/u8:0 6401 sdf W 47363904 122880 7.18 > 7.129299000 kworker/u8:0 6401 sdf W 47364144 122880 7.29 > 7.136645000 kworker/u8:0 6401 sdf W 47364384 122880 7.27 > 7.143733000 kworker/u8:0 6401 sdf W 47364624 122880 7.02 > 7.151112000 kworker/u8:0 6401 sdf W 47364864 122880 7.31 > 7.158509000 kworker/u8:0 6401 sdf W 47365104 122880 7.33 > 7.165735000 kworker/u8:0 6401 sdf W 47365344 122880 7.14 > 7.171205000 kworker/u8:0 6401 sdf W 47365584 122880 5.40 > 7.178625000 kworker/u8:0 6401 sdf W 47365824 122880 7.37 > 7.185980000 kworker/u8:0 6401 sdf W 47366064 122880 7.31 > 7.193593000 kworker/u8:0 6401 sdf W 47366304 122880 7.57 > 7.198674000 kworker/u8:0 6401 sdf W 47366544 122880 5.02 > 7.205996000 kworker/u8:0 6401 sdf W 47366784 122880 7.25 > 7.213419000 kworker/u8:0 6401 sdf W 47367024 122880 7.37 > 7.221005000 kworker/u8:0 6401 sdf W 47367264 122880 7.52 > 7.227906000 kworker/u8:0 6401 sdf W 47367504 122880 6.83 > 7.235251000 kworker/u8:0 6401 sdf W 47367744 122880 7.28 > 7.241892000 kworker/u8:0 6401 sdf W 47367984 106496 6.59 > 7.249617000 kworker/u8:0 6401 sdf W 47368192 122880 6.88 > 7.256892000 kworker/u8:0 6401 sdf W 47368432 122880 7.20 > 7.264223000 kworker/u8:0 6401 sdf W 47368672 122880 7.26 > 7.269672000 kworker/u8:0 6401 sdf W 47368912 122880 5.39 > 7.277066000 kworker/u8:0 6401 sdf W 47369152 122880 7.36 > 7.284630000 kworker/u8:0 6401 sdf W 47369392 122880 7.52 > 7.291891000 kworker/u8:0 6401 sdf W 47369632 122880 7.20 > 7.297211000 kworker/u8:0 6401 sdf W 47369872 122880 5.29 > 7.304665000 kworker/u8:0 6401 sdf W 47370112 122880 7.41 > 7.312050000 kworker/u8:0 6401 sdf W 47370352 122880 7.33 > 7.319520000 kworker/u8:0 6401 sdf W 47370592 122880 7.41 > 7.326494000 kworker/u8:0 6401 sdf W 47370832 122880 6.89 > 7.334082000 kworker/u8:0 6401 sdf W 47371072 122880 7.52 > 7.341505000 kworker/u8:0 6401 sdf W 47371312 122880 7.34 > 7.348600000 kworker/u8:0 6401 sdf W 47371552 122880 7.01 > 7.355806000 kworker/u8:0 6401 sdf W 47371792 122880 7.16 > 7.363147000 kworker/u8:0 6401 sdf W 47372032 122880 7.27 > 7.370377000 kworker/u8:0 6401 sdf W 47372272 122880 7.16 > 7.377770000 kworker/u8:0 6401 sdf W 47372512 122880 7.36 > 7.383323000 kworker/u8:0 6401 sdf W 47372752 122880 5.50 > 7.390651000 kworker/u8:0 6401 sdf W 47372992 122880 7.27 > 7.398245000 kworker/u8:0 6401 sdf W 47373232 122880 7.52 > 7.405347000 kworker/u8:0 6401 sdf W 47373472 122880 7.04 > 7.410761000 kworker/u8:0 6401 sdf W 47373712 122880 5.36 > 7.418075000 kworker/u8:0 6401 sdf W 47373952 122880 7.26 > 7.425451000 kworker/u8:0 6401 sdf W 47374192 122880 7.33 > 7.432864000 kworker/u8:0 6401 sdf W 47374432 122880 7.36 > 7.439913000 kworker/u8:0 6401 sdf W 47374672 122880 6.99 > 7.447312000 kworker/u8:0 6401 sdf W 47374912 122880 7.35 > 7.454721000 kworker/u8:0 6401 sdf W 47375152 122880 7.35 > 7.461955000 kworker/u8:0 6401 sdf W 47375392 122880 7.19 > 7.469040000 kworker/u8:0 6401 sdf W 47375632 122880 7.04 > 7.476416000 kworker/u8:0 6401 sdf W 47375872 122880 7.31 > 7.483856000 kworker/u8:0 6401 sdf W 47376112 122880 7.38 > 7.491270000 kworker/u8:0 6401 sdf W 47376352 122880 7.37 > 7.496452000 kworker/u8:0 6401 sdf W 47376592 122880 5.12 > 7.504011000 kworker/u8:0 6401 sdf W 47376832 122880 7.52 > 7.511217000 kworker/u8:0 6401 sdf W 47377072 122880 7.12 > 7.518511000 kworker/u8:0 6401 sdf W 47377312 122880 7.23 > 7.523956000 kworker/u8:0 6401 sdf W 47377552 122880 5.41 > 7.531197000 kworker/u8:0 6401 sdf W 47377792 122880 7.21 > 7.538546000 kworker/u8:0 6401 sdf W 47378032 122880 7.31 > 7.545757000 kworker/u8:0 6401 sdf W 47378272 122880 7.17 > 7.552919000 kworker/u8:0 6401 sdf W 47378512 122880 7.13 > 7.560269000 kworker/u8:0 6401 sdf W 47378752 122880 7.31 > 7.567555000 kworker/u8:0 6401 sdf W 47378992 122880 7.25 > 7.574863000 kworker/u8:0 6401 sdf W 47379232 122880 7.27 > 7.581802000 kworker/u8:0 6401 sdf W 47379472 122880 6.87 > 7.588979000 kworker/u8:0 6401 sdf W 47379712 122880 7.13 > 7.596343000 kworker/u8:0 6401 sdf W 47379952 122880 7.30 > 7.603224000 kworker/u8:0 6401 sdf W 47380192 122880 6.84 > 7.608655000 kworker/u8:0 6401 sdf W 47380432 122880 5.38 > 7.615811000 kworker/u8:0 6401 sdf W 47380672 122880 7.12 > 7.623028000 kworker/u8:0 6401 sdf W 47380912 122880 7.18 > 7.630413000 kworker/u8:0 6401 sdf W 47381152 122880 7.34 > 7.635223000 kworker/u8:0 6401 sdf W 47381392 122880 4.75 > 7.642268000 kworker/u8:0 6401 sdf W 47381632 122880 6.98 > 7.649383000 kworker/u8:0 6401 sdf W 47381872 122880 7.04 > 7.656619000 kworker/u8:0 6401 sdf W 47382112 122880 7.19 > 7.661918000 kworker/u8:0 6401 sdf W 47382352 122880 5.25 > 8.268039000 kworker/u8:0 6401 sdf W 47382592 122880 606.07 > 8.280414000 kworker/u8:0 6401 sdf W 47382832 122880 12.30 > 8.286503000 kworker/u8:0 6401 sdf W 47383072 122880 6.02 > 8.293627000 kworker/u8:0 6401 sdf W 47383312 122880 7.07 > 8.300777000 kworker/u8:0 6401 sdf W 47383552 122880 7.08 > 8.307733000 kworker/u8:0 6401 sdf W 47383792 122880 6.89 > 8.315212000 kworker/u8:0 6401 sdf W 47384032 122880 7.43 > 8.320697000 kworker/u8:0 6401 sdf W 47384272 122880 5.41 > 8.323335000 kworker/u8:0 6401 sdf W 47384512 32768 2.58 > 8.331116000 kworker/u8:0 6401 sdf W 47384576 122880 6.58 > 8.338586000 kworker/u8:0 6401 sdf W 47384816 122880 7.40 > 8.346113000 kworker/u8:0 6401 sdf W 47385056 122880 7.46 > 8.351558000 kworker/u8:0 6401 sdf W 47385296 122880 5.37 > 8.359030000 kworker/u8:0 6401 sdf W 47385536 122880 7.43 > 8.366425000 kworker/u8:0 6401 sdf W 47385776 122880 7.34 > 8.373712000 kworker/u8:0 6401 sdf W 47386016 122880 7.22 > 8.940689000 cp 6828 sdf W 47400960 122880 566.92 > 9.614647000 kworker/u8:0 6401 sdf W 47386256 122880 673.87 > 10.179120000 cp 6828 sdf W 47401200 122880 564.38 5 of 165 IO requests(1 4096 READ and 4 120K WRITE) take more than 500ms, and most of others only needs <10ms. That is the reason why the performance drops, and it is highly related with your USB pen drive. biosnoop collects the trace data in blk_mq_start_request() and blk_account_io_completion(), both happens during dispatching request to LLD & device. >From my understanding, scsi-mq should only change the timing, or maybe some setting is changed(still very unlikely), you may follow Alan's suggestion to collect usbmon on 'bad' & 'good' kernel, and check if the setting is changed. If the initialization setting is same, maybe you can try US_FL_GO_SLOW quirk. Thanks, Ming
