workqueue: update IO counters promptly after handling IO

workqueue: update IO counters promptly after handling IO

Currently, IO submit worker threads only update parent IO counters when
the threads are idle or when the threads exit. When offload fio jobs are
assigned a restrictive CPU mask, this results in reporting and logging
problems. This patch updates parent IO counters more promptly upon
completing each IO which resolves the reporting and logging problems.

In the output below, notice the missing read data direction output in
the first, simple job and how it appropriately appears after the patch
is applied. In the second job with logging, notice the missing log
entries (unequal file sizes) in the first log and how entries are no
longer missing for the run with the patch applied.

*********************
*** WITHOUT PATCH ***
*********************
$ ./fio --name=test --io_submit_mode=offload --cpus_allowed=1 --filename=/dev/sda --size=10M
test: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
fio-3.12-19-g41dd
Starting 1 process

test: (groupid=0, jobs=1): err= 0: pid=19746: Mon Nov 26 10:37:42 2018
  lat (nsec)   : 750=13.44%, 1000=42.42%
  lat (usec)   : 2=39.88%, 4=1.56%, 10=0.23%, 20=0.20%, 50=1.02%
  lat (usec)   : 100=0.55%, 250=0.27%, 500=0.35%, 750=0.04%
  lat (msec)   : 10=0.04%
  cpu          : usr=30.30%, sys=0.00%, ctx=5126, majf=0, minf=3
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=2560,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):

Disk stats (read/write):
  sda: ios=45/0, merge=0/0, ticks=44/0, in_queue=44, util=20.51%

*********************
***** WITH PATCH ****
*********************
$ ./fio --name=test --io_submit_mode=offload --cpus_allowed=1 --filename=/dev/sda --size=10M
test: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
fio-3.12-8-gee63-dirty
Starting 1 process

test: (groupid=0, jobs=1): err= 0: pid=19754: Mon Nov 26 10:37:56 2018
  read: IOPS=77.6k, BW=303MiB/s (318MB/s)(10.0MiB/33msec)
    clat (nsec): min=588, max=5941.5k, avg=5705.48, stdev=120112.09
     lat (nsec): min=1745, max=5950.7k, avg=7302.87, stdev=120311.09
    clat percentiles (nsec):
     |  1.00th=[    628],  5.00th=[    668], 10.00th=[    700],
     | 20.00th=[    740], 30.00th=[    772], 40.00th=[    812],
     | 50.00th=[    852], 60.00th=[    908], 70.00th=[    972],
     | 80.00th=[   1064], 90.00th=[   1256], 95.00th=[   1592],
     | 99.00th=[  48896], 99.50th=[ 158720], 99.90th=[ 544768],
     | 99.95th=[ 651264], 99.99th=[5931008]
  lat (nsec)   : 750=23.28%, 1000=49.92%
  lat (usec)   : 2=22.77%, 4=1.05%, 10=0.16%, 20=0.51%, 50=1.33%
  lat (usec)   : 100=0.27%, 250=0.31%, 500=0.27%, 750=0.08%
  lat (msec)   : 10=0.04%
  cpu          : usr=6.25%, sys=25.00%, ctx=5127, majf=0, minf=3
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=2560,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: bw=303MiB/s (318MB/s), 303MiB/s-303MiB/s (318MB/s-318MB/s), io=10.0MiB (10.5MB), run=33-33msec

Disk stats (read/write):
  sda: ios=45/0, merge=0/0, ticks=36/0, in_queue=36, util=20.92%

*********************
*** WITHOUT PATCH ***
*********************
$ ./fio-canonical/fio --name=test --direct=1 --filename=/dev/fioa --numjobs=4 --log_avg_msec=1000 --write_iops_log=test --time_based --runtime=10s --rw=read --bs=4k --cpus_allowed=1,3,2,7 --io_submit_mode=offload --group_reporting
test: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
...
fio-3.12-19-g41dd
Starting 4 processes
Jobs: 4 (f=4): [R(4)][100.0%][r=385MiB/s][r=98.7k IOPS][eta 00m:00s]
test: (groupid=0, jobs=4): err= 0: pid=22661: Mon Nov 26 08:51:19 2018
  read: IOPS=134k, BW=503MiB/s (527MB/s)(5029MiB/10001msec)
    clat (nsec): min=12481, max=73112, avg=20088.92, stdev=2744.19
     lat (nsec): min=15113, max=74716, avg=23846.94, stdev=3356.56
    clat percentiles (nsec):
     |  1.00th=[14016],  5.00th=[16320], 10.00th=[17024], 20.00th=[17792],
     | 30.00th=[18304], 40.00th=[19072], 50.00th=[20096], 60.00th=[20608],
     | 70.00th=[21376], 80.00th=[21888], 90.00th=[23424], 95.00th=[24704],
     | 99.00th=[28544], 99.50th=[29824], 99.90th=[33024], 99.95th=[34560],
     | 99.99th=[43264]
   bw (  KiB/s): min=126840, max=1711256, per=32.05%, avg=165065.08, stdev=210793.01, samples=60
   iops        : min=17773, max=213907, avg=39624.97, stdev=33794.49, samples=30
  lat (usec)   : 20=48.64%, 50=51.36%, 100=0.01%
  cpu          : usr=5.38%, sys=10.06%, ctx=1795113, majf=0, minf=63
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1341011,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: bw=503MiB/s (527MB/s), 503MiB/s-503MiB/s (527MB/s-527MB/s), io=5029MiB (5274MB), run=10001-10001msec

Disk stats (read/write):
  fioa: ios=1341011/0, merge=0/0, ticks=16916/0, in_queue=18236, util=91.46%

$ ls -l test_iops.?.log
-rw-r--r-- 1 root root  55 Nov 26 08:51 test_iops.1.log
-rw-r--r-- 1 root root 162 Nov 26 08:51 test_iops.2.log
-rw-r--r-- 1 root root 162 Nov 26 08:51 test_iops.3.log
-rw-r--r-- 1 root root 162 Nov 26 08:51 test_iops.4.log

$ cat test_iops.1.log
1000, 17773, 0, 0
3000, 71404, 0, 0
9000, 213907, 0, 0

*********************
***** WITH PATCH ****
*********************
$ ./fio/fio --name=test --direct=1 --filename=/dev/fioa --numjobs=4 --log_avg_msec=1000 --write_iops_log=test --time_based --runtime=10s --rw=read --bs=4k --cpus_allowed=1,3,2,7 --io_submit_mode=offload --group_reporting
test: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
...
fio-3.12-19-g41dd-dirty
Starting 4 processes
Jobs: 4 (f=4): [R(4)][100.0%][r=528MiB/s][r=135k IOPS][eta 00m:00s]
test: (groupid=0, jobs=4): err= 0: pid=22685: Mon Nov 26 08:51:56 2018
  read: IOPS=131k, BW=514MiB/s (539MB/s)(5137MiB/10001msec)
    clat (usec): min=12, max=184, avg=20.55, stdev= 4.05
     lat (usec): min=15, max=187, avg=24.61, stdev= 4.80
    clat percentiles (nsec):
     |  1.00th=[14016],  5.00th=[16512], 10.00th=[17280], 20.00th=[17792],
     | 30.00th=[18560], 40.00th=[19072], 50.00th=[20096], 60.00th=[20608],
     | 70.00th=[21120], 80.00th=[22144], 90.00th=[24448], 95.00th=[27008],
     | 99.00th=[38144], 99.50th=[39680], 99.90th=[52480], 99.95th=[54528],
     | 99.99th=[56576]
   bw (  KiB/s): min=94640, max=145392, per=24.96%, avg=131304.57, stdev=11668.56, samples=76
   iops        : min=23691, max=36200, avg=32774.75, stdev=2963.63, samples=36
  lat (usec)   : 20=49.59%, 50=50.24%, 100=0.17%, 250=0.01%
  cpu          : usr=5.20%, sys=9.76%, ctx=1794339, majf=0, minf=63
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1315098,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: bw=514MiB/s (539MB/s), 514MiB/s-514MiB/s (539MB/s-539MB/s), io=5137MiB (5387MB), run=10001-10001msec

Disk stats (read/write):
  fioa: ios=1315098/0, merge=0/0, ticks=17156/0, in_queue=20496, util=96.36%

$ ls -l test_iops.?.log
-rw-r--r-- 1 root root 162 Nov 26 08:51 test_iops.1.log
-rw-r--r-- 1 root root 162 Nov 26 08:51 test_iops.2.log
-rw-r--r-- 1 root root 162 Nov 26 08:51 test_iops.3.log
-rw-r--r-- 1 root root 162 Nov 26 08:51 test_iops.4.log

$ cat test_iops.1.log
1000, 27173, 0, 0
2000, 27186, 0, 0
3000, 34395, 0, 0
4000, 36200, 0, 0
5000, 36047, 0, 0
6000, 36043, 0, 0
7000, 36100, 0, 0
8000, 36121, 0, 0
9000, 36124, 0, 0

Fixes: https://www.spinics.net/lists/fio/msg07628.html
Signed-off-by: Jens Axboe <axboe@kernel.dk>