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
On Feb19 16:31, William Dauchy wrote:
> I would expect at least the same performances in v4.1.x.
> What can I do to help debug this issue?
I overlooked my config in 4.1.x and find out KASAN and kmemleak were
enabled.
however I can't reach the results I had on 3.14.x without these debug
options.
see my updated results on 4.1.x:
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] [7136KB/0KB/0KB /s] [1784/0/0 iops] [eta 00m:00s]
random-read: (groupid=0, jobs=1): err= 0: pid=3519: Sat Feb 20 15:44:10 2016
read : io=131072KB, bw=7617.9KB/s, iops=1904, runt= 17206msec
clat (usec): min=281, max=2091, avg=517.56, stdev=79.68
lat (usec): min=281, max=2092, avg=517.90, stdev=79.69
clat percentiles (usec):
| 1.00th=[ 318], 5.00th=[ 402], 10.00th=[ 422], 20.00th=[ 442],
| 30.00th=[ 490], 40.00th=[ 506], 50.00th=[ 516], 60.00th=[ 524],
| 70.00th=[ 548], 80.00th=[ 580], 90.00th=[ 612], 95.00th=[ 652],
| 99.00th=[ 716], 99.50th=[ 740], 99.90th=[ 772], 99.95th=[ 1208],
| 99.99th=[ 1624]
bw (KB /s): min= 7080, max= 8128, per=100.00%, avg=7627.53, stdev=343.98
lat (usec) : 500=37.34%, 750=62.32%, 1000=0.28%
lat (msec) : 2=0.05%, 4=0.01%
cpu : usr=2.05%, sys=14.02%, ctx=65541, majf=0, minf=45
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=7617KB/s, minb=7617KB/s, maxb=7617KB/s, mint=17206msec, maxt=17206msec
summary:
3.14: 9348KB/s
4.1: 7617KB/s
--
William