<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
<p>Hi,</p>
On 2020/05/08 17:47, Ravishankar N wrote:<br>
<blockquote type="cite"
cite="mid:512f76a9-8d75-02c0-dbb0-9ad76ee44e14@redhat.com">
<br>
On 08/05/20 7:07 pm, Jaco Kroon wrote:
<br>
<blockquote type="cite">
<br>
I'm not sure "stuck" is the right word, but looking at the
"statistics heal-count" values it goes into a form of "go slow"
mode, and ends up adding more entries for heal in some cases at
a rate of about 2 every second, sometimes 4 at worst (based on
~10-15 second intervals depending on how long it takes to gather
the heal-counts).
<br>
<br>
My guess currently is that since the log entries that scroll by
relates to metadata and entry heals, these are when it's healing
files, and when it hits a folder it somehow locks something,
then iterates through the folder (very) slowly for some reason,
and whilst this is happening, directory listings are outright
unusable.
<br>
<br>
Is there lock profiling code available in glusterfs?
<br>
<br>
</blockquote>
Nope, nothing as of today as far as I know. You can have the locks
xlator log everything by setting the locks.trace option to ON
though.
<br>
</blockquote>
<p>Might be worthwhile to look at building something in. Herewith
so long my strace analysis on one of the glsuterfsds:</p>
<p>strace -p 2827 -f -T 2>&1 >/tmp/strace.txt<br>
</p>
<p>This pid represents the brick process for zoidberg:/mnt/gluster/a<br>
</p>
<p>Processed output (a b c) represents "system call c too between [<b>b</b>,
<b>b</b>+1) seconds to return during the sample period <b>a</b>
number of times". I've marked futex (used for contested mutex
cases) calls in bold. The only system calls ever to take longer
than 1.000000s were: nanosleep, futex, epoll_wait (which is hard
to say what that could be in terms of operations, or just blocking
waiting for client requests), select (same comment as epoll_wait)
and restart_syscall (which I'm betting is safe to assume is
continuations of other syscalls mentioned here).<br>
</p>
<p><tt> 5 30 nanosleep</tt><tt> <-- 5 cases of nanosleep
sleeping for 30 seconds.<br>
</tt><b><tt> 2 27 futex</tt></b><tt><br>
</tt><tt> 1 27 epoll_wait</tt><tt><br>
</tt><tt> 1 23 restart_syscall</tt><tt><br>
</tt><tt> 1 21 restart_syscall</tt><tt><br>
</tt><b><tt> 1 21 futex</tt></b><tt><br>
</tt><tt> 1 21 epoll_wait</tt><tt><br>
</tt><b><tt> 2 20 futex</tt></b><tt><br>
</tt><tt> 2 20 epoll_wait</tt><tt><br>
</tt><b><tt> 1 18 futex</tt></b><tt><br>
</tt><tt> 1 18 epoll_wait</tt><tt><br>
</tt><tt> 1 16 restart_syscall</tt><tt><br>
</tt><b><tt> 2 13 futex</tt></b><b><tt><br>
</tt></b><b><tt> 1 12 futex</tt></b><b><tt><br>
</tt></b><b><tt> 19 11 futex</tt></b><b><tt><br>
</tt></b><tt> 2 11 epoll_wait</tt><tt><br>
</tt><tt> 2 10 restart_syscall</tt><tt><br>
</tt><b><tt> 10 10 futex</tt></b><b><tt><br>
</tt></b><tt> 1 10 epoll_wait</tt><tt><br>
</tt><tt> 1 8 restart_syscall</tt><tt><br>
</tt><b><tt> 4 8 futex</tt></b><b><tt><br>
</tt></b><tt> 1 8 epoll_wait</tt><tt><br>
</tt><tt> 2 7 restart_syscall</tt><tt><br>
</tt><b><tt> 5 6 futex</tt></b><b><tt><br>
</tt></b><tt> 2 6 epoll_wait</tt><tt><br>
</tt><tt> 24 5 nanosleep</tt><tt><br>
</tt><b><tt> 2 5 futex</tt></b><b><tt><br>
</tt></b><tt> 1 4 restart_syscall</tt><tt><br>
</tt><b><tt> 9 4 futex</tt></b><b><tt><br>
</tt></b><tt> 2 4 epoll_wait</tt><tt><br>
</tt><b><tt> 19 3 futex</tt></b><b><tt><br>
</tt></b><tt> 4 3 epoll_wait</tt><tt><br>
</tt><tt> 1 2 restart_syscall</tt><tt><br>
</tt><b><tt> 69 2 futex</tt></b><b><tt><br>
</tt></b><tt> 12 2 epoll_wait</tt><tt><br>
</tt><tt> 522 1 select</tt><tt><br>
</tt><tt> 1 1 restart_syscall</tt><tt><br>
</tt><tt> 7 1 nanosleep</tt><tt><br>
</tt><b><tt> 338 1 futex</tt></b><b><tt><br>
</tt></b><tt> 43 1 epoll_wait</tt><tt><br>
</tt><tt> 19630 0 writev</tt><tt><br>
</tt><tt> 2467 0 unlink</tt><tt><br>
</tt><tt> 2 0 tls=0x7f1338009480,</tt><tt><br>
</tt><tt> 1 0 tls=0x7f1318df9480,</tt><tt><br>
</tt><tt> 32 0 statfs</tt><tt><br>
</tt><tt> 3882 0 stat</tt><tt><br>
</tt><tt> 8 0 set_robust_list</tt><tt><br>
</tt><tt> 8 0 select</tt><tt><br>
</tt><tt> 4 0 rt_sigqueueinfo</tt><tt><br>
</tt><tt> 49 0 rt_sigprocmask</tt><tt><br>
</tt><tt> 16 0 restart_syscall</tt><tt><br>
</tt><tt> 39018 0 readv</tt><tt><br>
</tt><tt> 23490 0 readlink</tt><tt><br>
</tt><tt> 62 0 pwrite64</tt><tt><br>
</tt><tt> 158 0 pread64</tt><tt><br>
</tt><tt> 836 0 openat</tt><tt><br>
</tt><tt> 87 0 mprotect</tt><tt><br>
</tt><tt> 4 0 mkdir</tt><tt><br>
</tt><tt> 8 0 madvise</tt><tt><br>
</tt><tt> 95834 0 lstat</tt><tt><br>
</tt><tt> 3068 0 lsetxattr</tt><tt><br>
</tt><tt> 37 0 lseek</tt><tt><br>
</tt><tt> 16474 0 llistxattr</tt><tt><br>
</tt><tt> 3067 0 linkat</tt><tt><br>
</tt><tt> 36345 0 lgetxattr</tt><tt><br>
</tt><tt> 4 0 getuid</tt><tt><br>
</tt><tt> 4 0 getpid</tt><tt><br>
</tt><tt> 111 0 getdents64</tt><tt><br>
</tt><tt> 399210 0 futex</tt><tt><br>
</tt><tt> 300 0 fstat</tt><tt><br>
</tt><tt> 62 0 fsetxattr</tt><tt><br>
</tt><tt> 2 0 flistxattr</tt><tt><br>
</tt><tt> 291 0 fgetxattr</tt><tt><br>
</tt><tt> 19172 0 epoll_wait</tt><tt><br>
</tt><tt> 19244 0 epoll_ctl</tt><tt><br>
</tt><tt> 843 0 close</tt><tt><br>
</tt><tt> 5 0 clone</tt><tt><br>
</tt><tt> 2 0 chown</tt><tt><br>
</tt></p>
<p>So, looking at just the futex calls:</p>
<p><tt> 2 27 futex</tt><tt><br>
</tt><tt> 1 21 futex</tt><tt><br>
</tt><tt> 2 20 futex</tt><tt><br>
</tt><tt> 1 18 futex</tt><tt><br>
</tt><tt> 2 13 futex</tt><tt><br>
</tt><tt> 1 12 futex</tt><tt><br>
</tt><tt> 19 11 futex</tt><tt><br>
</tt><tt> 10 10 futex</tt><tt><br>
</tt><tt> 4 8 futex</tt><tt><br>
</tt><tt> 5 6 futex</tt><tt><br>
</tt><tt> 2 5 futex</tt><tt><br>
</tt><tt> 9 4 futex</tt><tt><br>
</tt><tt> 19 3 futex</tt><tt><br>
</tt><tt> 69 2 futex</tt><tt><br>
</tt><tt> 338 1 futex</tt><tt><br>
</tt><tt> 399210 0 futex</tt><tt><br>
</tt></p>
<p>That still indicates that the FAR MAJORITY of mutex locks were
fast. Performance stats for the same brick (I marked that which I
find interesting/relevant in bold again):<br>
</p>
<p><tt>Brick: zoidberg:/mnt/gluster/a</tt><tt><br>
</tt><tt>-----------------------------------------</tt><tt><br>
</tt><tt>Cumulative Stats:</tt><tt><br>
</tt><tt> Block Size: 1b+
4b+ 8b+ </tt><tt><br>
</tt><tt> No. of Reads: 0
0 0 </tt><tt><br>
</tt><tt>No. of Writes: 23
10 74 </tt><tt><br>
</tt><tt> </tt><tt><br>
</tt><tt> Block Size: 16b+
32b+ 64b+ </tt><tt><br>
</tt><tt> No. of Reads: 0
248 1 </tt><tt><br>
</tt><tt>No. of Writes: 155
1340 32 </tt><tt><br>
</tt><tt> </tt><tt><br>
</tt><tt> Block Size: 128b+
256b+ 512b+ </tt><tt><br>
</tt><tt> No. of Reads: 1
27 71 </tt><tt><br>
</tt><tt>No. of Writes: 63
779 186 </tt><tt><br>
</tt><tt> </tt><tt><br>
</tt><tt> Block Size: 1024b+
2048b+ 4096b+ </tt><tt><br>
</tt><tt> No. of Reads: 19
31 43 </tt><tt><br>
</tt><tt>No. of Writes: 387
797 1490 </tt><tt><br>
</tt><tt> </tt><tt><br>
</tt><tt> Block Size: 8192b+
16384b+ 32768b+ </tt><tt><br>
</tt><tt> No. of Reads: 147
254 508 </tt><tt><br>
</tt><tt>No. of Writes: 41360
3995 34916 </tt><tt><br>
</tt><tt> </tt><tt><br>
</tt><tt> Block Size: 65536b+ 131072b+
</tt><tt><br>
</tt><tt> No. of Reads: 941 52418
</tt><tt><br>
</tt><tt>No. of Writes: 9285 18319
</tt><tt><br>
</tt><tt> %-latency Avg-latency Min-Latency Max-Latency
No. of calls Fop</tt><tt><br>
</tt><tt> --------- ----------- ----------- -----------
------------ ----</tt><tt><br>
</tt><tt> 0.00 0.00 us 0.00 us 0.00
us 627326 FORGET</tt><tt><br>
</tt><tt> 0.00 0.00 us 0.00 us 0.00
us 922811 RELEASE</tt><tt><br>
</tt><tt> 0.00 0.00 us 0.00 us 0.00
us 35290 RELEASEDIR</tt><tt><br>
</tt><tt> 0.00 10.31 us 5.72 us 14.90
us 2 IPC</tt><tt><br>
</tt><tt> 0.00 40.70 us 40.70 us 40.70
us 1 LK</tt><tt><br>
</tt><tt> 0.00 65.64 us 65.64 us 65.64
us 1 STAT</tt><tt><br>
</tt><tt> 0.00 70.26 us 70.26 us 70.26
us 1 READ</tt><tt><br>
</tt><tt> 0.00 176.04 us 176.04 us 176.04
us 1 LINK</tt><tt><br>
</tt><tt> 0.00 42.11 us 29.10 us 63.81
us 11 FINODELK</tt><tt><br>
</tt><tt> 0.00 282.23 us 192.42 us 372.03
us 2 TRUNCATE</tt><tt><br>
</tt><tt> 0.00 65.89 us 20.84 us 316.68
us 11 FLUSH</tt><tt><br>
</tt><tt> 0.00 211.73 us 25.36 us 411.40
us 4 READDIRP</tt><tt><br>
</tt><tt> 0.00 60.37 us 37.28 us 135.28
us 20 STATFS</tt><tt><br>
</tt><tt> 0.00 509.01 us 176.30 us 1213.35
us 4 UNLINK</tt><tt><br>
</tt><tt> 0.00 414.76 us 51.19 us 2698.67
us 28 OPENDIR</tt><tt><br>
</tt><tt> 0.01 349.84 us 115.94 us 1342.20
us 48 WRITE</tt><tt><br>
</tt><tt> 0.04 90.44 us 36.50 us 615.58
us 1199 READLINK</tt><tt><br>
</tt><tt> 0.06 25088.70 us 7133.79 us 59634.44
us 7 CREATE</tt><tt><br>
</tt><tt> 0.12 7024.50 us 32.80 us 57327.60
us 50 READDIR</tt><tt><br>
</tt><tt> 0.16 624.73 us 49.54 us 94746.41
us 751 OPEN</tt><tt><br>
</tt><b><tt> 0.62 167828.35 us 543.79 us 387838.03
us 11 FXATTROP</tt></b><tt><br>
</tt><tt> 0.65 430.52 us 16.83 us 485714.99
us 4526 INODELK</tt><tt><br>
</tt><tt> 0.70 618.44 us 14.05 us 178158.97
us 3401 ENTRYLK</tt><tt><br>
</tt><b><tt> 2.12 71297.23 us 16.61 us 2286254.75
us 89 GETXATTR</tt></b><tt><br>
</tt><tt> 2.59 1054.74 us 25.63 us 178938.38
us 7323 LOOKUP</tt><tt><br>
</tt><b><tt> 92.94 88173.46 us 141.60 us 519829.21
us 3149 XATTROP</tt></b><tt><br>
</tt><tt> 0.00 0.00 us 0.00 us 0.00
us 2360 UPCALL</tt><tt><br>
</tt><tt> 0.00 0.00 us 0.00 us 0.00
us 2 CI_IATT</tt><tt><br>
</tt><tt> 0.00 0.00 us 0.00 us 0.00
us 1 CI_UNLINK</tt><tt><br>
</tt><tt> 0.00 0.00 us 0.00 us 0.00
us 2358 CI_FORGET</tt><tt><br>
</tt><tt> </tt><tt><br>
</tt><tt> Duration: 163988 seconds</tt><tt><br>
</tt><tt> Data Read: 6998476545 bytes</tt><tt><br>
</tt><tt>Data Written: 5064990911 bytes</tt><tt><br>
</tt><br>
<br>
</p>
<p><br>
</p>
<blockquote type="cite"
cite="mid:512f76a9-8d75-02c0-dbb0-9ad76ee44e14@redhat.com">
<blockquote type="cite">
<br>
I saw this "issue":
<a class="moz-txt-link-freetext" href="https://github.com/gluster/glusterfs/issues/275">https://github.com/gluster/glusterfs/issues/275</a>
<br>
<br>
And there was some related PR I can't track down now which aims
to wrap pthread mutex_* calls with some other library to time
locks etc ... having looked at that code it made sense but could
trivially introduce extra latency of a few micro-seconds even in
the optimal case, and at worst could change lock behaviour (all
_lock first does _trylock then re-issues _lock) - although I
haven't fully analysed the code change. And one would need to
modify everywhere where mutex's are called, alternatively
LD_PRELOAD hacks are useful, but then obtaining code locations
where locks are initialised and used becomes much, much harder,
but it would make an analysis of whether locks are contended on
for extended periods of time (more than a few milliseconds) or
held for extended times quite trivial, and I'm guessing
backtrace() from execinfo could be helpful here to at least get
an idea of which locks are involved.
<br>
<br>
This looks like the approach used by mutrace:
<a class="moz-txt-link-freetext" href="http://0pointer.de/blog/projects/mutrace.html">http://0pointer.de/blog/projects/mutrace.html</a> so might just end
up using that. Ironically enough if the author of that project
just added a little bit more graph tracking code he could turn
it into a deadlock detection tool as well.
<br>
<br>
<blockquote type="cite">I also see from the profile info on your
first email that XATTROP fop has the highest latency. Can you
do an strace of the brick processes to see if there is any
syscall (setxattr in particular, for the XATTROP fop) that is
taking higher than usual times?
<br>
<br>
</blockquote>
I'm familiar with strace. What am I looking for? How will I
identify XATTROP fops and their associated system calls in this
trace?
<br>
</blockquote>
<br>
XATTROP is a FOP meant for the index xlator. Index serializes this
FOP and sends a setxattr to posix xlator and in the callback
performs some link/unlinks operations inside .glusterfs/indices/.
So I was wondering if the bottleneck is in the setxattr syscall
itself (which can be found in the strace -i.e. the time taken for
the syscall) or because of the serialization inside index. The
xattr keys will be trusted.afr*. like so:
<br>
<br>
[pid 517071] fsetxattr(16, "trusted.afr.dirty",
"\0\0\0\1\0\0\0\0\0\0\0", 12, 0) = 0 <0.000135>
<br>
[pid 517071]
unlink("/home/ravi/bricks/brick1/.glusterfs/indices/xattrop/6ea17fe6-9080-4054-ab98-775d37ea143b")
= 0 <0.000086>
<br>
</blockquote>
<p>Ok. So all fsetxattr calls were sub 1ms (during a time where ls
took 90s±5s).</p>
<p>unlinks varies wildly, with out of 2467 unlink calls, 1729 were
sub 1ms.</p>
<p>21 was [1,5) ms<br>
17 was [5,10) ms<br>
24 was [10,20) ms<br>
112 was [20,50) ms<br>
368 was [50,100) ms<br>
196 was [100,200) ms<br>
27 was [200,300) ms<br>
6 was >= 300 ms, with the longest clocking in at 347ms.<br>
</p>
<p>This, in my opinion, does not justify stalls on ls upwards of a
minute for listing. Currently upwards of 3 minutes and counting.<br>
</p>
<blockquote type="cite"
cite="mid:512f76a9-8d75-02c0-dbb0-9ad76ee44e14@redhat.com">
<br>
But anyway you can check if there are any syscalls(not just
setxattr) that take a long time on the drives.
<br>
</blockquote>
<p>Nothing on the drives, at least as far as I can tell. Unless
those epolls and select calls, possibly relate, and even then,
that was max 7 epoll_wait calls over 10s, the rest all lower than,
so nothing that in my opinion can justify this level of badness.<br>
</p>
<blockquote type="cite"
cite="mid:512f76a9-8d75-02c0-dbb0-9ad76ee44e14@redhat.com">
<br>
<blockquote type="cite">
<blockquote type="cite">For the slow ls from the client, an
ongoing selfheal should not affect it, since readdir, stat etc
are all read-only operations that do not take any locks that
can compete with heal, and there is no hardware bottleneck at
the brick side to process requests from what you say. Maybe a
tcp dump between the client and the server can help find if
the slowness is from the server side by looking at the request
and response times of the FOPS in the dump.
<br>
<br>
</blockquote>
Well, it does. I've samples a few hundred ls's since my email
this morning. All of them were sub 0.5s. </blockquote>
I guess you need to check when the heal does happen, *which* FOP
is slow for the `ls -l` operation. Is it readdirp? stat?
<br>
</blockquote>
<p>Ok, so I'm assuming strace -T on ls itself should be revealing.
For the moment this OK for the moment via strace (clocking in at
3.5s for the moment). There is one solitary fstat() call in the
trace (only copying relevant):</p>
<p>openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY)
= 3 <1.800382><br>
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
<0.000019><br>
getdents64(3, /* 18 entries */, 131072) = 600 <1.346974><br>
getdents64(3, /* 18 entries */, 131072) = 584 <0.000174><br>
getdents64(3, /* 18 entries */, 131072) = 584 <0.000239><br>
getdents64(3, /* 18 entries */, 131072) = 584 <0.000165><br>
getdents64(3, /* 18 entries */, 131072) = 560 <0.343684><br>
getdents64(3, /* 18 entries */, 131072) = 568 <0.000272><br>
getdents64(3, /* 18 entries */, 131072) = 592 <0.000103><br>
getdents64(3, /* 18 entries */, 131072) = 600 <0.000096><br>
getdents64(3, /* 18 entries */, 131072) = 584 <0.000166><br>
getdents64(3, /* 18 entries */, 131072) = 608 <0.000167><br>
getdents64(3, /* 1 entries */, 131072) = 40 <0.000160><br>
getdents64(3, /* 0 entries */, 131072) = 0 <0.000060><br>
close(3) = 0 <0.000011><br>
<br>
In a second trace, the long calls were:</p>
<p>openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY)
= 3 <1.501978><br>
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
<2.526342><br>
<br>
For some reason I'm unable to get really, really long ls calls
right at the moment.<br>
<br>
But in all cases it seems that the openat call takes a long time,
followed by either a long(ish) fstat or a long(ish) getdents64
system call.</p>
<p>Doing strace against another process that reliably gets tripped
up by this (blocking reliably up to a minute and a half under
current conditions) I'm also not seeing anything that makes
sense. So I'm starting to think in this case it's more like death
by a million small cuts.<br>
<br>
I will keep on digging but for now I have to switch the SHD off
... I'll be creating a separate mount point in a moment and doing
recursive find . -exec stat {} \; -exec sleep 0.01 \; to see if
that helps ...<br>
<br>
</p>
<blockquote type="cite"
cite="mid:512f76a9-8d75-02c0-dbb0-9ad76ee44e14@redhat.com">
<blockquote type="cite">The only difference is that all three SHDs
were killed. Almost without a doubt in my mind there has to be
some unforeseen interaction. We've been having a few
discussions, and a very, very long time ago, we effectively
actioned a full heal with "find /path/to/fuse-mount -exec stat
{} \;" and other times with "find /path/to/fuse-mount -print0 |
xargs -0 -n50 -P5 -- stat" - and if we recall correctly we've
seen similar there. We thought at that time it was the FUSE
process causing trouble, and it's entirely possible that that is
indeed the case, but we are wondering now whether that too not
maybe related to the heal process that was just happening due to
the stats (heal on stat). We generally run with
cluster.*-self-heal off nowadays and rather rely purely on the
SHD for performance reasons.
<br>
</blockquote>
<br>
We've had complaints of client-side heal (data/metadata/entry)
stealing too much of i/o bandwidth which is why turned the
default values to off in AFR.
<br>
</blockquote>
<p>I've never had an issue with i/o bandwidth (mbit/s) here, but the
additional latency (ms) on pretty much all filesystem access was
really bad. I suspect this again relates to use, where we're
using it as a filesystem where most folks seems to be using it as
a backing store for disk images for VMs.</p>
<p>I'm not sure how to proceed from here ... If I'm really, really
lucky, the above process should finish in a few days at best, but
it could still take weeks. What worries me greatly is that I do
have an upcoming rebalance to add another distribute triplet ...
and I'm very, very worried that this will have the same potential
impact for client performance.<br>
</p>
<p>Kind Regards,<br>
Jaco</p>
</body>
</html>