Il 22-01-2020 14:02 Barak Sason Rofman ha scritto:> Hello Gionatan,
>
> Some time ago we've looked into the effect of logging in gluster on
> performance.
>
> If it's possible for you, you could try doing a performance test by
> disabling logging.
>
> In order to fully disable logging, some code needs to be modified.
>
> You can locate the method called 'skip_logging' at
'logging.c' and
> modify it so it always returns '_gf_true' (return _gf_true;).
>
> Recompiling and installing is required as well.
>
> I would be interested in knowing to what extent (if any) this had an
> affect.
>
> You can contact me if you have any doubts.
Hi Barak, thanks for you reply and sorry for the delay. As I am using
the gluster repository binary RPM, I can not immediately try to change
the source code. I think it should be possible by using SRPM, right?
That said, I collected some new stats which, to mee, seem to exclude any
logging problem; rather, it seems that a specific call (FXATTROP) take a
very long time.
Here you can find my test volume tv0 config:
[root at singularity gluster]# gluster volume status tv0 detail
Status of volume: tv0
------------------------------------------------------------------------------
Brick : Brick 172.31.255.1:/dev/shm/brick1
TCP Port : 49153
RDMA Port : 0
Online : Y
Pid : 9243
File System : tmpfs
Device : tmpfs
Mount Options : rw,seclabel,nosuid,nodev
Inode Size : N/A
Disk Space Free : 1.4GB
Total Disk Space : 3.8GB
Inode Count : 998691
Free Inodes : 998520
------------------------------------------------------------------------------
Brick : Brick 172.31.255.1:/dev/shm/brick2
TCP Port : 49154
RDMA Port : 0
Online : Y
Pid : 9263
File System : tmpfs
Device : tmpfs
Mount Options : rw,seclabel,nosuid,nodev
Inode Size : N/A
Disk Space Free : 1.4GB
Total Disk Space : 3.8GB
Inode Count : 998691
Free Inodes : 998520
As you can see, it is a very simple replica 2 volume backed by two
different /dev/shm (memory/tmpfs) directory. I am using /dev/shm to
discount any physical fsync latency. I mounted it via gluster native
client.
Runnig fio produce the following ouput:
[root at singularity tmp]# fio --name=test --filename=/mnt/fuse/test.img
--size=256M --rw=randwrite --bs=4k --fsync=1
test: (g=0): rw=randwrite, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T)
4096B-4096B, ioengine=psync, iodepth=1
fio-3.7
Starting 1 process
Jobs: 1 (f=1): [w(1)][100.0%][r=0KiB/s,w=2164KiB/s][r=0,w=541 IOPS][eta
00m:00s]2s]
test: (groupid=0, jobs=1): err= 0: pid=10612: Sat Jan 25 12:03:14 2020
write: IOPS=540, BW=2163KiB/s (2215kB/s)(256MiB/121181msec)
So, about 550 IOPs. For an all in-memory volume, it seems very slow.
Now the interesting part: first gluster client profile:
=== Interval 4 stats == Duration : 19 secs
BytesRead : 0
BytesWritten : 41852928
Block Size : 4096B+
Read Count : 0
Write Count : 10218
Fop Call Count Avg-Latency Min-Latency Max-Latency
--- ---------- ----------- ----------- -----------
WRITE 9234 26.97 us 17.27 us 153.22 us
STATFS 1 306.35 us 306.35 us 306.35 us
FSYNC 9233 1638.45 us 810.85 us 3343.30 us
SETXATTR 1 559.61 us 559.61 us 559.61 us
LOOKUP 1 445.29 us 445.29 us 445.29 us
As you can see, the client see many slow fsync. Now, server side (please
consider that client and server profile were taken at different time
point, but running the exactly same fio workload at the same
performance):
Brick: 172.31.255.1:/dev/shm/brick1
-----------------------------------
Cumulative Stats:
Block Size: 4096b+
No. of Reads: 0
No. of Writes: 102916
%-latency Avg-latency Min-Latency Max-Latency No. of calls
Fop
--------- ----------- ----------- ----------- ------------
----
0.00 0.00 us 0.00 us 0.00 us 2
RELEASE
0.00 0.00 us 0.00 us 0.00 us 3
RELEASEDIR
10.94 46.20 us 23.20 us 222.63 us 6969
FSYNC
17.35 36.66 us 15.67 us 221.59 us 13937
FINODELK
18.51 78.22 us 44.56 us 284.91 us 6968
WRITE
53.20 112.38 us 70.46 us 355.08 us 13937
FXATTROP
Duration: 246 seconds
Data Read: 0 bytes
Data Written: 421543936 bytes
Interval 1 Stats:
Block Size: 4096b+
No. of Reads: 0
No. of Writes: 3497
%-latency Avg-latency Min-Latency Max-Latency No. of calls
Fop
--------- ----------- ----------- ----------- ------------
----
11.01 46.42 us 23.20 us 222.63 us 3498
FSYNC
17.30 36.49 us 15.94 us 195.65 us 6995
FINODELK
18.42 77.70 us 44.59 us 257.26 us 3497
WRITE
53.28 112.37 us 71.49 us 355.08 us 6995
FXATTROP
Duration: 6 seconds
Data Read: 0 bytes
Data Written: 14323712 bytes
Brick: 172.31.255.1:/dev/shm/brick2
-----------------------------------
Cumulative Stats:
Block Size: 4096b+
No. of Reads: 0
No. of Writes: 102917
%-latency Avg-latency Min-Latency Max-Latency No. of calls
Fop
--------- ----------- ----------- ----------- ------------
----
0.00 0.00 us 0.00 us 0.00 us 2
RELEASE
0.00 0.00 us 0.00 us 0.00 us 3
RELEASEDIR
11.05 44.83 us 23.04 us 212.17 us 6968
FSYNC
17.39 35.28 us 15.63 us 200.36 us 13938
FINODELK
18.04 73.17 us 42.60 us 261.36 us 6969
WRITE
53.52 108.54 us 70.47 us 353.13 us 13938
FXATTROP
Duration: 246 seconds
Data Read: 0 bytes
Data Written: 421548032 bytes
Interval 1 Stats:
Block Size: 4096b+
No. of Reads: 0
No. of Writes: 3498
%-latency Avg-latency Min-Latency Max-Latency No. of calls
Fop
--------- ----------- ----------- ----------- ------------
----
11.24 46.52 us 23.38 us 212.17 us 3497
FSYNC
17.58 36.37 us 16.13 us 194.07 us 6996
FINODELK
18.07 74.77 us 42.72 us 237.45 us 3498
WRITE
53.11 109.90 us 70.87 us 353.13 us 6995
FXATTROP
Duration: 6 seconds
Data Read: 0 bytes
Data Written: 14327808 bytes
Now, the slowest operation is FXATTROP, which seems executed at a ratio
of 2x FSYNC.
So, some questions:
- as my fio 4k sync writes is running at 550 IOPs, why I see so many
FSYNC and FXATTROP?
- are my stats broken/wrong?
- are the log-disabled test still necessary?
Thanks.
--
Danti Gionatan
Supporto Tecnico
Assyoma S.r.l. - www.assyoma.it
email: g.danti at assyoma.it - info at assyoma.it
GPG public key ID: FF5F32A8