Bug 1676468

Summary: glusterfs-fuse client not benefiting from page cache on read after write
Product: [Red Hat Storage] Red Hat Gluster Storage Reporter: Raghavendra G <rgowdapp>
Component: fuseAssignee: Raghavendra G <rgowdapp>
Status: CLOSED ERRATA QA Contact: Nag Pavan Chilakam <nchilaka>
Severity: high Docs Contact:
Priority: unspecified    
Version: rhgs-3.4CC: amukherj, guillaume.pavese, nchilaka, pasik, rhs-bugs, storage-qa-internal
Target Milestone: ---Keywords: Performance, Rebase
Target Release: RHGS 3.5.0   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: glusterfs-6.0-1 Doc Type: Bug Fix
Doc Text:
Previously, glusterfs enabled kernel auto-invalidation, which invalidates page cache when ctime changes. This meant that whenever writes occurred before, during, and after a ctime change, the page cache was purged, and the performance of subsequent writes did not benefit from caching. Two new options are now available to improve performance. The mount option 'auto-invalidation[=on|off]' is now enabled by default, and specifies whether the kernel can automatically invalidate attribute, dentry, and page cache. To retain page cache after writes, set this to 'off', but only if files cannot be accessed by two different mount points concurrently. The volume option performance.global-cache-invalidation=[on|off] overrides the value of performance.cache-invalidation. This option is disabled by default, but when enabled purges all read caches related to gluster when a stat change is detected. Turn this option on only when a file can be accessed from different mount points and caches across these mount points are required to be coherent. If both options are turned off, data written is retained in page cache and performance of overlapping reads in the same region improves.
 Story Points: ---
Clone Of: 1664934 Environment:
Last Closed: 2019-10-30 12:20:20 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1664934    
Bug Blocks: 1629589, 1674364, 1696807    

Description Raghavendra G 2019-02-12 11:47:58 UTC 
+++ This bug was initially created as a clone of Bug #1664934 +++

Description of problem:
On a simple single brick distribute volume, I'm running tests to validate glusterfs-fuse client's use of page cache. The tests are indicating that a read following a write is reading from the brick, not from client cache. In contrast, a 2nd read gets data from the client cache.

Version-Release number of selected component (if applicable):

glusterfs-*5.2-1.el7.x86_64
kernel-3.10.0-957.el7.x86_64 (RHEL 7.6)

How reproducible:

Consistently

Steps to Reproduce:
1. use fio to create a data set that would fit easily in the page cache. My client has 128 GB RAM; I'll create a 64 GB data set:

fio --name=initialwrite --ioengine=sync --rw=write \
--direct=0 --create_on_open=1 --end_fsync=1 --bs=128k \
--directory=/mnt/glustervol/ --filename_format=f.\$jobnum.\$filenum \
--filesize=16g --size=16g --numjobs=4

2. run an fio read test that reads the data set from step 1, without invalidating the page cache:

fio --name=readtest --ioengine=sync --rw=read --invalidate=0 \
--direct=0 --bs=128k --directory=/mnt/glustervol/ \
--filename_format=f.\$jobnum.\$filenum --filesize=16g \
--size=16g --numjobs=4

Read throughput is much lower than it would be if reading from page cache:
READ: bw=573MiB/s (601MB/s), 143MiB/s-144MiB/s (150MB/s-150MB/s), io=64.0GiB (68.7GB), run=114171-114419msec

Reads are going over the 10GbE network as shown in (edited) sar output:
05:01:04 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s 
05:01:06 AM       em1 755946.26  40546.26 1116287.75   3987.24      0.00

[There is some read amplification here: application is getting lower throughput than what client is reading over the n/w. More on that later]      

3. Run the read test in step 2 again. This time read throughput is really high, indicating read from cache, rather than over the network:
READ: bw=14.8GiB/s (15.9GB/s), 3783MiB/s-4270MiB/s (3967MB/s-4477MB/s), io=64.0GiB (68.7GB), run=3837-4331msec


Expected results:

The read test in step 2 should be reading from page cache, and should be giving throughput close to what we get in step 3.

Additional Info:

gluster volume info:

Volume Name: perfvol
Type: Distribute
Volume ID: 7033539b-0331-44b1-96cf-46ddc6ee2255
Status: Started
Snapshot Count: 0
Number of Bricks: 1
Transport-type: tcp
Bricks:
Brick1: 172.16.70.128:/mnt/rhs_brick1
Options Reconfigured:
transport.address-family: inet
nfs.disable: on

--- Additional comment from Manoj Pillai on 2019-01-10 05:43:53 UTC ---

(In reply to Manoj Pillai from comment #0)
[...]
> 1. use fio to create a data set that would fit easily in the page cache. My
> client has 128 GB RAM; I'll create a 64 GB data set:
> 
> fio --name=initialwrite --ioengine=sync --rw=write \
> --direct=0 --create_on_open=1 --end_fsync=1 --bs=128k \
> --directory=/mnt/glustervol/ --filename_format=f.\$jobnum.\$filenum \
> --filesize=16g --size=16g --numjobs=4
> 

Memory usage on the client while the write test is running:

<excerpt>
# sar -r 5
Linux 3.10.0-957.el7.x86_64 (c09-h08-r630.rdu.openstack.engineering.redhat.com)         01/10/2019      _x86_64_ (56 CPU)

05:35:36 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit  kbactive   kbinact   kbdirty
05:35:41 AM 126671972   4937712      3.75         0   2974352    256704      0.18   1878020   1147776        36
05:35:46 AM 126671972   4937712      3.75         0   2974352    256704      0.18   1878020   1147776        36
05:35:51 AM 126666904   4942780      3.76         0   2974324    259900      0.19   1879948   1147772        16
05:35:56 AM 126665820   4943864      3.76         0   2974348    261300      0.19   1880304   1147776        24
05:36:01 AM 126663136   4946548      3.76         0   2974348    356356      0.25   1881500   1147772        20
05:36:06 AM 126663028   4946656      3.76         0   2974348    356356      0.25   1881540   1147772        20
05:36:11 AM 126664444   4945240      3.76         0   2974388    356356      0.25   1880648   1147788        32
05:36:16 AM 126174984   5434700      4.13         0   3449508    930284      0.66   1892912   1622536        32
05:36:21 AM 120539884  11069800      8.41         0   9076076    930284      0.66   1893784   7247852        32
05:36:26 AM 114979592  16630092     12.64         0  14620932    930284      0.66   1893796  12793472        32
05:36:31 AM 109392488  22217196     16.88         0  20192112    930284      0.66   1893796  18365764        32
05:36:36 AM 104113900  27495784     20.89         0  25457272    930284      0.66   1895152  23630336        32
05:36:41 AM  98713688  32895996     25.00         0  30842800    930284      0.66   1895156  29015400        32
05:36:46 AM  93355560  38254124     29.07         0  36190264    930688      0.66   1897548  34361664        32
05:36:51 AM  87640900  43968784     33.41         0  41885972    930688      0.66   1897556  40057860        32
05:36:56 AM  81903068  49706616     37.77         0  47626388    930688      0.66   1897004  45798848         0
05:37:01 AM  76209860  55399824     42.09         0  53303272    930688      0.66   1897004  51475716         0
05:37:06 AM  70540340  61069344     46.40         0  58956264    930688      0.66   1897004  57128836         0
05:37:11 AM  64872776  66736908     50.71         0  64609648    930688      0.66   1897000  62782624         0
05:37:16 AM  59376144  72233540     54.88         0  70096880    930688      0.66   1897368  68270084         0
05:37:21 AM  71333376  60276308     45.80         0  58169584    356740      0.25   1891388  56342848         0
05:37:26 AM 126653336   4956348      3.77         0   2974476    356740      0.25   1891392   1148348         0
05:37:31 AM 126654360   4955324      3.77         0   2974388    356740      0.25   1891380   1147784         0
05:37:36 AM 126654376   4955308      3.77         0   2974388    356740      0.25   1891380   1147784         0
05:37:41 AM 126654376   4955308      3.77         0   2974388    356740      0.25   1891380   1147784         0
</excerpt>

So as the write test progresses, kbcached steadily increases. But looks like the cached data is dropped subsequently.

--- Additional comment from Manoj Pillai on 2019-01-10 05:52:14 UTC ---

When I run the same sequence of tests on an XFS file system on the server, I get expected results: both step 2. and step 3. of comment #0 report high read throughput (15+GiB/s) indicating data is read from the page cache.

--- Additional comment from Manoj Pillai on 2019-01-10 11:01:23 UTC ---

(In reply to Manoj Pillai from comment #0)
[...]
> 
> Read throughput is much lower than it would be if reading from page cache:
> READ: bw=573MiB/s (601MB/s), 143MiB/s-144MiB/s (150MB/s-150MB/s), io=64.0GiB
> (68.7GB), run=114171-114419msec
> 
> Reads are going over the 10GbE network as shown in (edited) sar output:
> 05:01:04 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s 
> 05:01:06 AM       em1 755946.26  40546.26 1116287.75   3987.24      0.00
> 
> [There is some read amplification here: application is getting lower
> throughput than what client is reading over the n/w. More on that later]    
> 

This turned out to be primarily read-ahead related. Open a new bug for it: https://bugzilla.redhat.com/show_bug.cgi?id=1665029.

--- Additional comment from Raghavendra G on 2019-01-23 13:04:54 UTC ---

From preliminary tests I see two reasons for this:
1. inode-invalidations triggered by md-cache
2. Fuse auto invalidations

With a hacky fix removing both of the above, I can see read after write being served from kernel page-cache. I'll update the bug with more details discussing validity/limitations with the above two approaches later.

--- Additional comment from Manoj Pillai on 2019-01-24 04:43:40 UTC ---

(In reply to Raghavendra G from comment #4)
> From preliminary tests I see two reasons for this:
> 1. inode-invalidations triggered by md-cache
> 2. Fuse auto invalidations

Trying with kernel NFS, another distributed fs solution. I see that cache is retained at the end of the write test, and both read-after-write and read-after-read are served from the page cache.

In principle, if kNFS can do it, FUSE should be able to do it. I think :D.

--- Additional comment from Worker Ant on 2019-01-29 03:15:45 UTC ---

REVIEW: https://review.gluster.org/22109 (mount/fuse: expose fuse-auto-invalidation as a mount option) posted (#1) for review on master by Raghavendra G

--- Additional comment from Raghavendra G on 2019-01-30 05:41:39 UTC ---

(In reply to Manoj Pillai from comment #5)
> (In reply to Raghavendra G from comment #4)
> > From preliminary tests I see two reasons for this:
> > 1. inode-invalidations triggered by md-cache
> > 2. Fuse auto invalidations
> 
> Trying with kernel NFS, another distributed fs solution. I see that cache is
> retained at the end of the write test, and both read-after-write and
> read-after-read are served from the page cache.
> 
> In principle, if kNFS can do it, FUSE should be able to do it. I think :D.

kNFS and FUSE have different invalidation policies.

* kNFS provides close-to-open consistency. To quote from their FAQ [1]

"Linux implements close-to-open cache consistency by comparing the results of a GETATTR operation done just after the file is closed to the results of a GETATTR operation done when the file is next opened. If the results are the same, the client will assume its data cache is still valid; otherwise, the cache is purged."

For the workload used in this bz, file is not changed between close and open. Hence two values of stat fetched - at close and open - match and hence page-cache is retained.

* FUSE auto-invalidation compares times of stats cached with the values got from the underlying filesystem implementation at all codepaths where stat is fetched. This means comparision happens in lookup, (f)stat, (f)setattr etc codepaths. Since (f)stat, lookup can happen asynchronously and concurrently wrt writes, they'll end up identifying delta between two values of stats resulting in cache purge. Please note that the consistency offered by FUSE is stronger than close-to-open consistency, which means it also provides close-to-open consistency along with consistency in codepaths like lookup, fstat etc.

We have following options:

* disable auto-invalidations and use glusterfs custom designed invalidation policy. The invalidation policy can be the same as NFS close-to-open consistency or something more stronger.
* check whether the current form of auto-invalidation (though stricter) provides any added benefits to close-to-open consistency which are useful. If no, change FUSE auto-invalidation to close-to-open consistency.

[1] http://nfs.sourceforge.net/#faq_a8

--- Additional comment from Raghavendra G on 2019-01-30 05:45:23 UTC ---

Miklos,

It would be helpful if you can comment on comment #7.

regards,
Raghavendra

--- Additional comment from Raghavendra G on 2019-01-30 05:59:06 UTC ---

Note that a lease based invalidation policy would be a complete solution, but it will take some time to implement that and get it working in Glusterfs.

--- Additional comment from Worker Ant on 2019-02-02 03:08:22 UTC ---

REVIEW: https://review.gluster.org/22109 (mount/fuse: expose auto-invalidation as a mount option) merged (#13) on master by Amar Tumballi

--- Additional comment from Miklos Szeredi on 2019-02-04 09:53:18 UTC ---

The underlying problem is that auto invalidate cannot differentiate local and remote modification based on mtime alone.

What NFS apprently does is refresh attributes immediately after a write (not sure how often it does this, I guess not after each individual write).

FUSE maybe should do this if auto invalidation is enabled, but if the filesystem can do its own invalidation, possibly based on better information than c/mtime, then that seem to be a better option.

--- Additional comment from Worker Ant on 2019-02-08 12:14:58 UTC ---

REVIEW: https://review.gluster.org/22178 (mount/fuse: fix bug related to --auto-invalidation in mount script) posted (#1) for review on master by Raghavendra G

--- Additional comment from Worker Ant on 2019-02-09 18:41:54 UTC ---

REVIEW: https://review.gluster.org/22178 (mount/fuse: fix bug related to --auto-invalidation in mount script) merged (#2) on master by Raghavendra G

--- Additional comment from Worker Ant on 2019-02-11 11:16:18 UTC ---

REVIEW: https://review.gluster.org/22111 (performance/md-cache: introduce an option to control invalidation of inodes) merged (#18) on master by Raghavendra G

--- Additional comment from Worker Ant on 2019-02-12 03:46:47 UTC ---

REVIEW: https://review.gluster.org/22193 (performance/md-cache: change the op-version of \"global-cache-invalidation\") posted (#1) for review on master by Raghavendra G
Comment 4 Yaniv Kaul 2019-04-22 12:14:39 UTC 
*** Bug 1670710 has been marked as a duplicate of this bug. ***
Comment 9 Nag Pavan Chilakam 2019-10-16 13:57:16 UTC 
fyi, as expected, retested on 6.0.18 too and with performance.global-cache-invalidation off, the read is served from cache in first attempt itslef
root@rhs-gp-srv10 ~]# cd fio
[root@rhs-gp-srv10 fio]# fio --name=initialwrite --ioengine=sync --rw=write --direct=0 --create_on_open=1 --end_fsync=1 --bs=128k --directory=/mnt/glusterfs/ --filename_format=f.\$jobnum.\$filenum --filesize=4g --size=4g --numjobs=4
initialwrite: (g=0): rw=write, bs=(R) 128KiB-128KiB, (W) 128KiB-128KiB, (T) 128KiB-128KiB, ioengine=sync, iodepth=1
...
fio-3.16
Starting 4 processes
Jobs: 1 (f=1): [F(1),_(3)][100.0%][eta 00m:00s]                              
initialwrite: (groupid=0, jobs=1): err= 0: pid=9845: Wed Oct 16 19:25:01 2019
  write: IOPS=257, BW=32.1MiB/s (33.7MB/s)(4096MiB/127436msec)
    clat (usec): min=130, max=2209, avg=457.50, stdev=246.76
     lat (usec): min=132, max=2210, avg=458.97, stdev=246.75
    clat percentiles (usec):
     |  1.00th=[  147],  5.00th=[  161], 10.00th=[  184], 20.00th=[  247],
     | 30.00th=[  297], 40.00th=[  347], 50.00th=[  404], 60.00th=[  461],
     | 70.00th=[  545], 80.00th=[  644], 90.00th=[  799], 95.00th=[  947],
     | 99.00th=[ 1221], 99.50th=[ 1336], 99.90th=[ 1565], 99.95th=[ 1614],
     | 99.99th=[ 1795]
   bw (  KiB/s): min=259584, max=285636, per=100.00%, avg=277295.57, stdev=5296.38, samples=30
   iops        : min= 2028, max= 2231, avg=2166.33, stdev=41.34, samples=30
  lat (usec)   : 250=20.32%, 500=44.32%, 750=22.87%, 1000=8.83%
  lat (msec)   : 2=3.66%, 4=0.01%
  cpu          : usr=0.12%, sys=1.44%, ctx=65541, majf=0, minf=81
  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=0,32768,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1
initialwrite: (groupid=0, jobs=1): err= 0: pid=9846: Wed Oct 16 19:25:01 2019
  write: IOPS=261, BW=32.7MiB/s (34.3MB/s)(4096MiB/125346msec)
    clat (usec): min=127, max=1882.4k, avg=2018.68, stdev=45962.27
     lat (usec): min=128, max=1882.4k, avg=2020.24, stdev=45962.27
    clat percentiles (usec):
     |  1.00th=[    141],  5.00th=[    157], 10.00th=[    182],
     | 20.00th=[    245], 30.00th=[    297], 40.00th=[    347],
     | 50.00th=[    404], 60.00th=[    465], 70.00th=[    545],
     | 80.00th=[    644], 90.00th=[    799], 95.00th=[    947],
     | 99.00th=[   1287], 99.50th=[   1434], 99.90th=[ 968885],
     | 99.95th=[1434452], 99.99th=[1468007]
   bw (  KiB/s): min=  219, max=284160, per=92.18%, avg=121353.91, stdev=137172.32, samples=69
   iops        : min=    1, max= 2220, avg=947.68, stdev=1072.01, samples=69
  lat (usec)   : 250=20.82%, 500=43.53%, 750=22.82%, 1000=9.02%
  lat (msec)   : 2=3.69%, 4=0.01%, 1000=0.03%, 2000=0.09%
  cpu          : usr=0.14%, sys=1.49%, ctx=65544, majf=0, minf=79
  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=0,32768,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1
initialwrite: (groupid=0, jobs=1): err= 0: pid=9847: Wed Oct 16 19:25:01 2019
  write: IOPS=261, BW=32.7MiB/s (34.3MB/s)(4096MiB/125346msec)
    clat (usec): min=126, max=1905.7k, avg=3225.42, stdev=61331.10
     lat (usec): min=128, max=1905.7k, avg=3226.94, stdev=61331.13
    clat percentiles (usec):
     |  1.00th=[    141],  5.00th=[    157], 10.00th=[    186],
     | 20.00th=[    253], 30.00th=[    302], 40.00th=[    351],
     | 50.00th=[    408], 60.00th=[    465], 70.00th=[    545],
     | 80.00th=[    644], 90.00th=[    791], 95.00th=[    947],
     | 99.00th=[   1303], 99.50th=[   1467], 99.90th=[1417675],
     | 99.95th=[1451230], 99.99th=[1484784]
   bw (  KiB/s): min=  219, max=284160, per=64.87%, avg=85396.20, stdev=127464.08, samples=98
   iops        : min=    1, max= 2220, avg=666.66, stdev=996.14, samples=98
  lat (usec)   : 250=19.69%, 500=44.78%, 750=23.31%, 1000=8.23%
  lat (msec)   : 2=3.76%, 4=0.02%, 10=0.01%, 1000=0.02%, 2000=0.18%
  cpu          : usr=0.13%, sys=1.47%, ctx=65544, majf=0, minf=78
  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=0,32768,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1
initialwrite: (groupid=0, jobs=1): err= 0: pid=9848: Wed Oct 16 19:25:01 2019
  write: IOPS=261, BW=32.7MiB/s (34.3MB/s)(4096MiB/125318msec)
    clat (usec): min=126, max=2121, avg=457.89, stdev=253.97
     lat (usec): min=127, max=2122, avg=459.39, stdev=253.96
    clat percentiles (usec):
     |  1.00th=[  141],  5.00th=[  157], 10.00th=[  184], 20.00th=[  249],
     | 30.00th=[  297], 40.00th=[  347], 50.00th=[  404], 60.00th=[  457],
     | 70.00th=[  537], 80.00th=[  635], 90.00th=[  799], 95.00th=[  955],
     | 99.00th=[ 1303], 99.50th=[ 1450], 99.90th=[ 1696], 99.95th=[ 1762],
     | 99.99th=[ 1909]
   bw (  KiB/s): min=259840, max=284416, per=100.00%, avg=276582.00, stdev=5780.24, samples=30
   iops        : min= 2030, max= 2222, avg=2160.77, stdev=45.24, samples=30
  lat (usec)   : 250=20.18%, 500=44.94%, 750=22.62%, 1000=8.26%
  lat (msec)   : 2=4.00%, 4=0.01%
  cpu          : usr=0.13%, sys=1.46%, ctx=65544, majf=0, minf=76
  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=0,32768,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):
  WRITE: bw=129MiB/s (135MB/s), 32.1MiB/s-32.7MiB/s (33.7MB/s-34.3MB/s), io=16.0GiB (17.2GB), run=125318-127436msec
[root@rhs-gp-srv10 fio]# fio --name=readtest     --ioengine=sync --rw=read  --invalidate=0 --direct=0 --bs=128k --directory=/mnt/glusterfs/ --filename_format=f.\$jobnum.\$filenum --filesize=4g  --size=4g --numjobs=4
readtest: (g=0): rw=read, bs=(R) 128KiB-128KiB, (W) 128KiB-128KiB, (T) 128KiB-128KiB, ioengine=sync, iodepth=1
...
fio-3.16
Starting 4 processes
Jobs: 3 (f=3)
readtest: (groupid=0, jobs=1): err= 0: pid=9885: Wed Oct 16 19:25:50 2019
  read: IOPS=41.0k, BW=5126MiB/s (5375MB/s)(4096MiB/799msec)
    clat (nsec): min=17903, max=93281, avg=23856.50, stdev=7178.59
     lat (nsec): min=17944, max=95034, avg=23905.50, stdev=7182.35
    clat percentiles (nsec):
     |  1.00th=[18304],  5.00th=[18560], 10.00th=[18816], 20.00th=[18816],
     | 30.00th=[19072], 40.00th=[19328], 50.00th=[19584], 60.00th=[20096],
     | 70.00th=[25472], 80.00th=[32128], 90.00th=[36096], 95.00th=[38144],
     | 99.00th=[41216], 99.50th=[43776], 99.90th=[47872], 99.95th=[50944],
     | 99.99th=[69120]
   bw (  MiB/s): min= 4449, max= 4449, per=28.35%, avg=4449.00, stdev= 0.00, samples=1
   iops        : min=35592, max=35592, avg=35592.00, stdev= 0.00, samples=1
  lat (usec)   : 20=58.14%, 50=41.80%, 100=0.06%
  cpu          : usr=3.63%, sys=96.24%, ctx=5, majf=0, minf=65
  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=32768,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1
readtest: (groupid=0, jobs=1): err= 0: pid=9886: Wed Oct 16 19:25:50 2019
  read: IOPS=37.8k, BW=4724MiB/s (4954MB/s)(4096MiB/867msec)
    clat (usec): min=18, max=108, avg=25.95, stdev= 4.74
     lat (usec): min=18, max=110, avg=26.00, stdev= 4.74
    clat percentiles (nsec):
     |  1.00th=[20608],  5.00th=[21632], 10.00th=[22400], 20.00th=[23168],
     | 30.00th=[23680], 40.00th=[24192], 50.00th=[24448], 60.00th=[25216],
     | 70.00th=[25728], 80.00th=[26752], 90.00th=[35072], 95.00th=[38144],
     | 99.00th=[41216], 99.50th=[43776], 99.90th=[47360], 99.95th=[49408],
     | 99.99th=[72192]
   bw (  MiB/s): min= 4473, max= 4473, per=28.51%, avg=4473.50, stdev= 0.00, samples=1
   iops        : min=35788, max=35788, avg=35788.00, stdev= 0.00, samples=1
  lat (usec)   : 20=0.24%, 50=99.72%, 100=0.03%, 250=0.01%
  cpu          : usr=4.73%, sys=95.15%, ctx=4, majf=0, minf=67
  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=32768,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1
readtest: (groupid=0, jobs=1): err= 0: pid=9887: Wed Oct 16 19:25:50 2019
  read: IOPS=36.3k, BW=4541MiB/s (4762MB/s)(4096MiB/902msec)
    clat (usec): min=19, max=106, avg=27.03, stdev= 5.47
     lat (usec): min=19, max=108, avg=27.08, stdev= 5.48
    clat percentiles (nsec):
     |  1.00th=[20352],  5.00th=[21632], 10.00th=[22400], 20.00th=[22912],
     | 30.00th=[23424], 40.00th=[23936], 50.00th=[24704], 60.00th=[25472],
     | 70.00th=[27520], 80.00th=[32384], 90.00th=[36096], 95.00th=[38144],
     | 99.00th=[41728], 99.50th=[44288], 99.90th=[47872], 99.95th=[49408],
     | 99.99th=[57088]
   bw (  MiB/s): min= 4088, max= 4088, per=26.05%, avg=4088.75, stdev= 0.00, samples=1
   iops        : min=32710, max=32710, avg=32710.00, stdev= 0.00, samples=1
  lat (usec)   : 20=0.41%, 50=99.55%, 100=0.04%, 250=0.01%
  cpu          : usr=3.55%, sys=96.23%, ctx=5, majf=0, minf=66
  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=32768,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1
readtest: (groupid=0, jobs=1): err= 0: pid=9888: Wed Oct 16 19:25:50 2019
  read: IOPS=31.4k, BW=3923MiB/s (4114MB/s)(4096MiB/1044msec)
    clat (usec): min=22, max=138, avg=31.38, stdev= 3.86
     lat (usec): min=22, max=138, avg=31.43, stdev= 3.87
    clat percentiles (nsec):
     |  1.00th=[24960],  5.00th=[25728], 10.00th=[26240], 20.00th=[28032],
     | 30.00th=[29824], 40.00th=[30592], 50.00th=[31104], 60.00th=[31872],
     | 70.00th=[32640], 80.00th=[33536], 90.00th=[36608], 95.00th=[38144],
     | 99.00th=[42240], 99.50th=[44288], 99.90th=[48384], 99.95th=[49920],
     | 99.99th=[60672]
   bw (  MiB/s): min= 3676, max= 4114, per=24.82%, avg=3895.38, stdev=309.54, samples=2
   iops        : min=29412, max=32914, avg=31163.00, stdev=2476.29, samples=2
  lat (usec)   : 50=99.95%, 100=0.04%, 250=0.01%
  cpu          : usr=2.78%, sys=97.12%, ctx=3, majf=0, minf=107
  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=32768,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=15.3GiB/s (16.5GB/s), 3923MiB/s-5126MiB/s (4114MB/s-5375MB/s), io=16.0GiB (17.2GB), run=799-1044msec
[root@rhs-gp-srv10 fio]#
Comment 12 errata-xmlrpc 2019-10-30 12:20:20 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2019:3249