Very Slow Loading But Fast Storage Benchmarks

anon131 · 04-26-2020, 01:26 PM

Hello,
I've been using Debian for a few years but recently built a new system. In some programs loading is extremely slow but all my storage devices benchmark well. I have tried moving the programs in question between different storage media with no success.

Main drive is an Intel 660p 1TB SSD, CPU is Ryzen 5 3600X, motherboard is Gigabyte B450M-DS3H. Alternate storage I've tried is an Intel 520 SSD. System is running Debian 10.

The easiest way to reproduce the problem is attempting to load Kerbal Space Program. This takes ~30 minutes whereas my older laptop with a SATA SSD does this in about 30 seconds. Issue occurs in several other programs (world of warships, minecraft). I'm unsure if this is a hardware or software problem.

Code:

sudo hdparm -tT /dev/nvme0n1p2

/dev/nvme0n1p2:
 Timing cached reads:   29848 MB in  2.00 seconds = 14942.65 MB/sec
 HDIO_DRIVE_CMD(identify) failed: Inappropriate ioctl for device
 Timing buffered disk reads: 3230 MB in  3.00 seconds = 1076.07 MB/sec

fio --name=randread --rw=randread --direct=1 --ioengine=libaio --bs=4k --numjobs=1 --size=1G --runtime=600 --group_reporting --iodepth=8
randread: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=8
fio-3.12
Starting 1 process
Jobs: 1 (f=0): [f(1)][100.0%][r=203MiB/s][r=52.1k IOPS][eta 00m:00s]
randread: (groupid=0, jobs=1): err= 0: pid=6556: Sun Apr 26 13:50:19 2020
  read: IOPS=53.7k, BW=210MiB/s (220MB/s)(1024MiB/4879msec)
    slat (nsec): min=1243, max=32701, avg=2308.38, stdev=629.57
    clat (usec): min=38, max=8317, avg=145.97, stdev=89.56
     lat (usec): min=40, max=8321, avg=148.35, stdev=89.53
    clat percentiles (usec):
     |  1.00th=[   55],  5.00th=[   58], 10.00th=[   63], 20.00th=[   84],
     | 30.00th=[   94], 40.00th=[  110], 50.00th=[  129], 60.00th=[  143],
     | 70.00th=[  174], 80.00th=[  206], 90.00th=[  251], 95.00th=[  293],
     | 99.00th=[  396], 99.50th=[  437], 99.90th=[  529], 99.95th=[  594],
     | 99.99th=[ 1045]
   bw (  KiB/s): min=212960, max=218240, per=100.00%, avg=215527.11, stdev=1966.79, samples=9
   iops        : min=53240, max=54560, avg=53881.78, stdev=491.70, samples=9
  lat (usec)   : 50=0.01%, 100=35.51%, 250=54.24%, 500=10.10%, 750=0.12%
  lat (usec)   : 1000=0.02%
  lat (msec)   : 2=0.01%, 10=0.01%
  cpu          : usr=6.07%, sys=16.54%, ctx=150730, majf=0, minf=19
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.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.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=262144,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=8

Run status group 0 (all jobs):
   READ: bw=210MiB/s (220MB/s), 210MiB/s-210MiB/s (220MB/s-220MB/s), io=1024MiB (1074MB), run=4879-4879msec

Disk stats (read/write):
  nvme0n1: ios=250470/83, merge=0/66, ticks=36082/19, in_queue=64, util=97.89%

Thanks

berndbausch · 04-26-2020, 05:44 PM

strace -r shows you system calls and their timestamps. That could narrow down the problem. Run it on the system in question and on a system where you don't experience the effect.

Of course, keep in mind that strace will slow it down even more.

syg00 · 04-26-2020, 06:46 PM

Sounds similar to this. A recent kernel should fix it apparently.