poor random read nfs client results using fio on v4.1.x

[William Dauchy <william@gandi.net>]

[-- Attachment #1: Type: text/plain, Size: 5169 bytes --]

Hello,

I have been running a few random read using a nfsv4 client.
I used the following fio file:

; random read of 128mb of data
[random-read]
rw=randread
size=128m
directory=/tmp/foo


I am using the last long term v4.1.x kernel. The results gave me very
poor performances:

random-read: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.11
Starting 1 process
Jobs: 1 (f=1): [r(1)] [100.0% done] [2780KB/0KB/0KB /s] [695/0/0 iops] [eta 00m:00s]
random-read: (groupid=0, jobs=1): err= 0: pid=3552: Fri Feb 19 15:29:43 2016
  read : io=131072KB, bw=2826.7KB/s, iops=706, runt= 46370msec
    clat (usec): min=1157, max=10807, avg=1407.98, stdev=120.44
     lat (usec): min=1157, max=10807, avg=1408.31, stdev=120.45
    clat percentiles (usec):
     |  1.00th=[ 1240],  5.00th=[ 1256], 10.00th=[ 1288], 20.00th=[ 1336],
     | 30.00th=[ 1352], 40.00th=[ 1368], 50.00th=[ 1400], 60.00th=[ 1432],
     | 70.00th=[ 1432], 80.00th=[ 1464], 90.00th=[ 1528], 95.00th=[ 1608],
     | 99.00th=[ 1720], 99.50th=[ 1784], 99.90th=[ 2256], 99.95th=[ 2512],
     | 99.99th=[ 2960]
    bw (KB  /s): min= 2496, max= 3008, per=100.00%, avg=2829.38, stdev=78.92
    lat (msec) : 2=99.83%, 4=0.17%, 20=0.01%
  cpu          : usr=0.50%, sys=12.40%, ctx=65552, majf=0, minf=68
  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    : total=r=32768/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: io=131072KB, aggrb=2826KB/s, minb=2826KB/s, maxb=2826KB/s, mint=46370msec, maxt=46370msec


So I gave a try with v4.4.x, but the results remains poor:

random-read: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.11
Starting 1 process
Jobs: 1 (f=1): [r(1)] [100.0% done] [1404KB/0KB/0KB /s] [351/0/0 iops] [eta 00m:00s]
random-read: (groupid=0, jobs=1): err= 0: pid=3649: Fri Feb 19 15:17:49 2016
  read : io=131072KB, bw=1393.2KB/s, iops=348, runt= 94026msec
    clat (usec): min=2286, max=11370, avg=2859.12, stdev=446.19
     lat (usec): min=2286, max=11370, avg=2859.53, stdev=446.17
    clat percentiles (usec):
     |  1.00th=[ 2480],  5.00th=[ 2512], 10.00th=[ 2544], 20.00th=[ 2544],
     | 30.00th=[ 2576], 40.00th=[ 2608], 50.00th=[ 2640], 60.00th=[ 2736],
     | 70.00th=[ 2928], 80.00th=[ 3216], 90.00th=[ 3568], 95.00th=[ 3760],
     | 99.00th=[ 4384], 99.50th=[ 4512], 99.90th=[ 4896], 99.95th=[ 5216],
     | 99.99th=[ 6304]
    bw (KB  /s): min= 1075, max= 1432, per=100.00%, avg=1395.07, stdev=30.20
    lat (msec) : 4=97.81%, 10=2.18%, 20=0.01%
  cpu          : usr=0.32%, sys=10.39%, ctx=65558, majf=0, minf=36
  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    : total=r=32768/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: io=131072KB, aggrb=1393KB/s, minb=1393KB/s, maxb=1393KB/s, mint=94026msec, maxt=94026msec


My previous kernel was 3.14.x, and the resuls were better:

random-read: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.11
Starting 1 process
Jobs: 1 (f=1): [r(1)] [100.0% done] [8980KB/0KB/0KB /s] [2245/0/0 iops] [eta 00m:00s]
random-read: (groupid=0, jobs=1): err= 0: pid=3655: Fri Feb 19 15:22:25 2016
  read : io=131072KB, bw=9348.1KB/s, iops=2337, runt= 14020msec
    clat (usec): min=252, max=5567, avg=420.90, stdev=85.03
     lat (usec): min=253, max=5567, avg=421.28, stdev=85.02
    clat percentiles (usec):
     |  1.00th=[  290],  5.00th=[  326], 10.00th=[  338], 20.00th=[  354],
     | 30.00th=[  362], 40.00th=[  366], 50.00th=[  398], 60.00th=[  466],
     | 70.00th=[  482], 80.00th=[  490], 90.00th=[  516], 95.00th=[  540],
     | 99.00th=[  596], 99.50th=[  620], 99.90th=[  676], 99.95th=[ 1096],
     | 99.99th=[ 1640]
    bw (KB  /s): min= 8704, max=10368, per=100.00%, avg=9352.57, stdev=579.50
    lat (usec) : 500=87.75%, 750=12.19%, 1000=0.01%
    lat (msec) : 2=0.05%, 4=0.01%, 10=0.01%
  cpu          : usr=3.28%, sys=13.75%, ctx=61908, majf=0, minf=36
  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    : total=r=32768/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: io=131072KB, aggrb=9348KB/s, minb=9348KB/s, maxb=9348KB/s, mint=14020msec, maxt=14020msec



I would expect at least the same performances in v4.1.x.
What can I do to help debug this issue?

Thanks,
-- 
William

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 181 bytes --]