Description of problem: ======================= I was running a script which open's an fd and writes to a file to test eager lock. However I observed that eager lock was not effective as almost every fop was having postop and unlock being done, which is supposed to not happen when a file is opened by same fd and only one fd(eager lock feature) Also, the flush operations from vol profile looks to be too high. openfd.sh script is attached Version-Release number of selected component (if applicable): =================== 3.8.4.54.12(331 async for supporting 3.10 CNS release) [root@rhs-arch-srv1 ~]# gluster v profile cross3 info Brick: rhs-arch-srv1.lab.eng.blr.redhat.com:/gluster/brick3/cross3 ------------------------------------------------------------------ Cumulative Stats: Block Size: 16b+ No. of Reads: 0 No. of Writes: 96840 %-latency Avg-latency Min-Latency Max-Latency No. of calls Fop --------- ----------- ----------- ----------- ------------ ---- 0.00 0.00 us 0.00 us 0.00 us 1 RELEASE 0.00 0.00 us 0.00 us 0.00 us 3 RELEASEDIR 0.00 2.33 us 2.00 us 3.00 us 3 OPENDIR 0.00 64.00 us 64.00 us 64.00 us 1 FSTAT 0.00 65.00 us 65.00 us 65.00 us 1 OPEN 0.00 75.00 us 75.00 us 75.00 us 1 LK 0.00 89.00 us 89.00 us 89.00 us 1 REMOVEXATTR 0.00 144.00 us 144.00 us 144.00 us 1 TRUNCATE 0.00 61.75 us 13.00 us 143.00 us 4 GETXATTR 0.00 143.50 us 126.00 us 161.00 us 2 XATTROP 0.00 54.88 us 17.00 us 90.00 us 8 INODELK 0.00 125.57 us 30.00 us 211.00 us 7 LOOKUP 0.00 326.50 us 173.00 us 861.00 us 6 READDIR 0.03 45.15 us 17.00 us 118.00 us 347 STAT 12.04 29.81 us 11.00 us 130.00 us 193683 FLUSH 13.28 65.78 us 34.00 us 442.00 us 96840 WRITE 29.93 37.07 us 13.00 us 376.00 us 387360 FINODELK 44.71 110.73 us 64.00 us 766.00 us 193680 FXATTROP Duration: 369 seconds Data Read: 0 bytes Data Written: 1743120 bytes Interval 6 Stats: Duration: 7 seconds Data Read: 0 bytes Data Written: 0 bytes Brick: rhs-arch-srv4.lab.eng.blr.redhat.com:/gluster/brick3/cross3 ------------------------------------------------------------------ Cumulative Stats: Block Size: 16b+ No. of Reads: 0 No. of Writes: 96840 %-latency Avg-latency Min-Latency Max-Latency No. of calls Fop --------- ----------- ----------- ----------- ------------ ---- 0.00 0.00 us 0.00 us 0.00 us 1 RELEASE 0.00 0.00 us 0.00 us 0.00 us 3 RELEASEDIR 0.00 2.33 us 2.00 us 3.00 us 3 OPENDIR 0.00 106.00 us 106.00 us 106.00 us 1 LK 0.00 126.00 us 126.00 us 126.00 us 1 FSTAT 0.00 138.00 us 138.00 us 138.00 us 1 REMOVEXATTR 0.00 157.00 us 157.00 us 157.00 us 1 OPEN 0.00 182.00 us 182.00 us 182.00 us 1 TRUNCATE 0.00 70.25 us 26.00 us 119.00 us 4 GETXATTR 0.00 208.00 us 203.00 us 213.00 us 2 XATTROP 0.00 90.25 us 51.00 us 111.00 us 8 INODELK 0.00 125.00 us 25.00 us 206.00 us 7 LOOKUP 0.00 300.17 us 158.00 us 782.00 us 6 READDIR 12.12 29.04 us 11.00 us 197.00 us 193683 FLUSH 13.23 63.36 us 34.00 us 288.00 us 96840 WRITE 30.58 36.63 us 13.00 us 468.00 us 387360 FINODELK 44.06 105.56 us 64.00 us 641.00 us 193680 FXATTROP Duration: 369 seconds Data Read: 0 bytes Data Written: 1743120 bytes Interval 6 Stats: Duration: 7 seconds Data Read: 0 bytes Data Written: 0 bytes Brick: rhs-arch-srv2.lab.eng.blr.redhat.com:/gluster/brick3/cross3 ------------------------------------------------------------------ Cumulative Stats: Block Size: 16b+ No. of Reads: 0 No. of Writes: 96840 %-latency Avg-latency Min-Latency Max-Latency No. of calls Fop --------- ----------- ----------- ----------- ------------ ---- 0.00 0.00 us 0.00 us 0.00 us 1 RELEASE 0.00 0.00 us 0.00 us 0.00 us 3 RELEASEDIR 0.00 2.00 us 1.00 us 3.00 us 3 OPENDIR 0.00 60.00 us 60.00 us 60.00 us 1 OPEN 0.00 62.00 us 62.00 us 62.00 us 1 STAT 0.00 65.00 us 65.00 us 65.00 us 1 LK 0.00 68.00 us 68.00 us 68.00 us 1 REMOVEXATTR 0.00 76.00 us 76.00 us 76.00 us 1 FSTAT 0.00 148.00 us 148.00 us 148.00 us 1 TRUNCATE 0.00 44.50 us 12.00 us 88.00 us 4 GETXATTR 0.00 146.50 us 127.00 us 166.00 us 2 XATTROP 0.00 48.25 us 21.00 us 64.00 us 8 INODELK 0.00 97.71 us 21.00 us 162.00 us 7 LOOKUP 0.00 319.50 us 164.00 us 826.00 us 6 READDIR 11.27 22.48 us 11.00 us 496.00 us 193683 FLUSH 13.23 52.78 us 34.00 us 213.00 us 96840 WRITE 28.81 28.74 us 12.00 us 252.00 us 387360 FINODELK 46.68 93.10 us 63.00 us 570.00 us 193680 FXATTROP Duration: 369 seconds Data Read: 0 bytes Data Written: 1743120 bytes Interval 6 Stats: Duration: 7 seconds Data Read: 0 bytes Data Written: 0 bytes How reproducible: --------------- always Steps to Reproduce: 1.create a 1x3 volume, enable profiling, enable eager-lock 2.fuse mount volume 3.run ./openfd.sh script which is attached 4. keep monitoring profile o/p Actual results: --------------- too many flushes and inodelks happening Expected results: ------------------ if eager lock is enabled, with a single fd and non-conflicting writes, the unlocking(and hence) inodelks should be minimal flushing too should be minimal
Created attachment 1449948 [details] openfd.sh run as ./openfd.sh <filename_which_is_to_be_writtn to>
logs ie brick statedumps and fuse-client statedumps along with volume profiling at http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/nchilaka/bug.1589710/
FYI, the number of inodelk is double the number of flushes ie 2:1 in 3.8.4-54.12 whereas in older build ie 3.8.4-54.8 it is 1:1 server:3.8.4-54.12 client:3.8.4-54.12 Brick: rhs-arch-srv4.lab.eng.blr.redhat.com:/gluster/brick3/cross3 ------------------------------------------------------------------ Cumulative Stats: Block Size: 16b+ No. of Reads: 0 No. of Writes: 84977 %-latency Avg-latency Min-Latency Max-Latency No. of calls Fop --------- ----------- ----------- ----------- ------------ ---- 0.00 0.00 us 0.00 us 0.00 us 1 RELEASE 0.00 80.00 us 80.00 us 80.00 us 1 LK 0.00 111.00 us 111.00 us 111.00 us 1 TRUNCATE 0.00 134.00 us 134.00 us 134.00 us 1 OPEN 0.00 155.00 us 155.00 us 155.00 us 1 REMOVEXATTR 0.00 159.00 us 159.00 us 159.00 us 1 FSTAT 0.00 146.00 us 127.00 us 165.00 us 2 XATTROP 0.00 157.33 us 109.00 us 239.00 us 3 LOOKUP 0.00 193.38 us 18.00 us 650.00 us 8 INODELK 12.07 28.80 us 12.00 us 301.00 us 169957 FLUSH 12.98 61.92 us 35.00 us 184.00 us 84977 WRITE 30.25 36.07 us 13.00 us 222.00 us 339908 FINODELK 44.69 106.60 us 66.00 us 597.00 us 169954 FXATTROP Duration: 354 seconds Data Read: 0 bytes Data Written: 1529586 bytes Interval 8 Stats: Duration: 6 seconds Data Read: 0 bytes Data Written: 0 bytes ################################################# client:3.8.4-54.8 Brick: rhs-arch-srv2.lab.eng.blr.redhat.com:/gluster/brick3/cross3 ------------------------------------------------------------------ Cumulative Stats: Block Size: 16b+ No. of Reads: 0 No. of Writes: 83067 %-latency Avg-latency Min-Latency Max-Latency No. of calls Fop --------- ----------- ----------- ----------- ------------ ---- 0.00 0.00 us 0.00 us 0.00 us 1 RELEASE 0.00 0.00 us 0.00 us 0.00 us 3 RELEASEDIR 0.00 2.00 us 1.00 us 3.00 us 3 OPENDIR 0.00 22.00 us 22.00 us 22.00 us 1 LK 0.00 61.00 us 61.00 us 61.00 us 1 FSTAT 0.00 64.00 us 64.00 us 64.00 us 1 STAT 0.00 67.00 us 67.00 us 67.00 us 1 OPEN 0.00 88.00 us 88.00 us 88.00 us 1 TRUNCATE 0.00 135.00 us 135.00 us 135.00 us 1 REMOVEXATTR 0.00 48.00 us 34.00 us 64.00 us 4 INODELK 0.00 64.60 us 13.00 us 108.00 us 5 GETXATTR 0.00 132.33 us 129.00 us 136.00 us 3 XATTROP 0.00 87.50 us 21.00 us 141.00 us 8 LOOKUP 0.01 257.50 us 177.00 us 400.00 us 6 READDIR 11.99 16.72 us 11.00 us 135.00 us 166136 FLUSH 15.56 43.40 us 32.00 us 156.00 us 83067 WRITE 15.87 22.13 us 13.00 us 165.00 us 166134 FINODELK 56.56 78.88 us 62.00 us 362.00 us 166134 FXATTROP Duration: 333 seconds Data Read: 0 bytes Data Written: 1495206 bytes Interval 4 Stats: Duration: 6 seconds Data Read: 0 bytes Data Written: 0 bytes
fuse client dumps and profiling available at http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/nchilaka/bug.1589710/fuse-client-dumps
Reproducing the issue, and both profiling the volume and taking a fusedump, I found that the number of FLUSH fuse messages (accounted by fusedump) is identical to the number of FLUSH fops (accounted by profile data). That is, all the flushes are coming from kernel. And that's because when closing an fd such that the underlying file object still remains open via another fd (as happens with the test script), fuse issues a FLUSH. So it's just regular fuse behavior and the high number of FLUSHes is a false canary. Therefore, if there is no objection to that, I'd close this bug with NOTABUG. Nevertheless I wonder if the flushes are just noise that can be ignored from the POV of the original problem (eager lock testing) or do they effectively ruin the tests? For the part "eager lock was not effective as almost every fop was having postop and unlock being done, which is supposed to not happen when a file is opened by same fd and only one fd(eager lock feature)" I suggest to open a dedicated bug in the scope of eager locking.
Is the similar test being done on RHGS3.4 bases?
(In reply to Amar Tumballi from comment #8) > Is the similar test being done on RHGS3.4 bases? haven't done it in batch updates, due to already having this bug reported. can retry on 3.5
(In reply to nchilaka from comment #10) > (In reply to Amar Tumballi from comment #8) > > Is the similar test being done on RHGS3.4 bases? > > haven't done it in batch updates, due to already having this bug reported. > can retry on 3.5 Nag, based on Comment 7, I think this bug can be closed? The eager-lock issues were tracked and fixed in Bug 1528566
(In reply to Sahina Bose from comment #13) > (In reply to nchilaka from comment #10) > > (In reply to Amar Tumballi from comment #8) > > > Is the similar test being done on RHGS3.4 bases? > > > > haven't done it in batch updates, due to already having this bug reported. > > can retry on 3.5 > > Nag, based on Comment 7, I think this bug can be closed? > The eager-lock issues were tracked and fixed in Bug 1528566 Ok, you can go ahead and close the bug