Re: Possible SHD stalling

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi,

On 2020/05/08 17:47, Ravishankar N wrote:

On 08/05/20 7:07 pm, Jaco Kroon wrote:

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).

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.

Is there lock profiling code available in glusterfs?

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.

Might be worthwhile to look at building something in.  Herewith so long my strace analysis on one of the glsuterfsds:

strace -p 2827 -f -T 2>&1 >/tmp/strace.txt

This pid represents the brick process for zoidberg:/mnt/gluster/a

Processed output (a b c) represents "system call c too between [b, b+1) seconds to return during the sample period a 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).

      5 30 nanosleep <-- 5 cases of nanosleep sleeping for 30 seconds.
      2 27 futex
      1 27 epoll_wait
      1 23 restart_syscall
      1 21 restart_syscall
      1 21 futex
      1 21 epoll_wait
      2 20 futex
      2 20 epoll_wait
      1 18 futex
      1 18 epoll_wait
      1 16 restart_syscall
      2 13 futex
      1 12 futex
     19 11 futex
      2 11 epoll_wait
      2 10 restart_syscall
     10 10 futex
      1 10 epoll_wait
      1 8 restart_syscall
      4 8 futex
      1 8 epoll_wait
      2 7 restart_syscall
      5 6 futex
      2 6 epoll_wait
     24 5 nanosleep
      2 5 futex
      1 4 restart_syscall
      9 4 futex
      2 4 epoll_wait
     19 3 futex
      4 3 epoll_wait
      1 2 restart_syscall
     69 2 futex
     12 2 epoll_wait
    522 1 select
      1 1 restart_syscall
      7 1 nanosleep
    338 1 futex
     43 1 epoll_wait
  19630 0 writev
   2467 0 unlink
      2 0 tls=0x7f1338009480,
      1 0 tls=0x7f1318df9480,
     32 0 statfs
   3882 0 stat
      8 0 set_robust_list
      8 0 select
      4 0 rt_sigqueueinfo
     49 0 rt_sigprocmask
     16 0 restart_syscall
  39018 0 readv
  23490 0 readlink
     62 0 pwrite64
    158 0 pread64
    836 0 openat
     87 0 mprotect
      4 0 mkdir
      8 0 madvise
  95834 0 lstat
   3068 0 lsetxattr
     37 0 lseek
  16474 0 llistxattr
   3067 0 linkat
  36345 0 lgetxattr
      4 0 getuid
      4 0 getpid
    111 0 getdents64
 399210 0 futex
    300 0 fstat
     62 0 fsetxattr
      2 0 flistxattr
    291 0 fgetxattr
  19172 0 epoll_wait
  19244 0 epoll_ctl
    843 0 close
      5 0 clone
      2 0 chown

So, looking at just the futex calls:

      2 27 futex
      1 21 futex
      2 20 futex
      1 18 futex
      2 13 futex
      1 12 futex
     19 11 futex
     10 10 futex
      4 8 futex
      5 6 futex
      2 5 futex
      9 4 futex
     19 3 futex
     69 2 futex
    338 1 futex
 399210 0 futex

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):

Brick: zoidberg:/mnt/gluster/a
-----------------------------------------
Cumulative Stats:
   Block Size:                  1b+                   4b+                   8b+
 No. of Reads:                    0                     0                     0
No. of Writes:                   23                    10                    74
 
   Block Size:                 16b+                  32b+                  64b+
 No. of Reads:                    0                   248                     1
No. of Writes:                  155                  1340                    32
 
   Block Size:                128b+                 256b+                 512b+
 No. of Reads:                    1                    27                    71
No. of Writes:                   63                   779                   186
 
   Block Size:               1024b+                2048b+                4096b+
 No. of Reads:                   19                    31                    43
No. of Writes:                  387                   797                  1490
 
   Block Size:               8192b+               16384b+               32768b+
 No. of Reads:                  147                   254                   508
No. of Writes:                41360                  3995                 34916
 
   Block Size:              65536b+              131072b+
 No. of Reads:                  941                 52418
No. of Writes:                 9285                 18319
 %-latency   Avg-latency   Min-Latency   Max-Latency   No. of calls         Fop
 ---------   -----------   -----------   -----------   ------------        ----
      0.00       0.00 us       0.00 us       0.00 us         627326      FORGET
      0.00       0.00 us       0.00 us       0.00 us         922811     RELEASE
      0.00       0.00 us       0.00 us       0.00 us          35290  RELEASEDIR
      0.00      10.31 us       5.72 us      14.90 us              2         IPC
      0.00      40.70 us      40.70 us      40.70 us              1          LK
      0.00      65.64 us      65.64 us      65.64 us              1        STAT
      0.00      70.26 us      70.26 us      70.26 us              1        READ
      0.00     176.04 us     176.04 us     176.04 us              1        LINK
      0.00      42.11 us      29.10 us      63.81 us             11    FINODELK
      0.00     282.23 us     192.42 us     372.03 us              2    TRUNCATE
      0.00      65.89 us      20.84 us     316.68 us             11       FLUSH
      0.00     211.73 us      25.36 us     411.40 us              4    READDIRP
      0.00      60.37 us      37.28 us     135.28 us             20      STATFS
      0.00     509.01 us     176.30 us    1213.35 us              4      UNLINK
      0.00     414.76 us      51.19 us    2698.67 us             28     OPENDIR
      0.01     349.84 us     115.94 us    1342.20 us             48       WRITE
      0.04      90.44 us      36.50 us     615.58 us           1199    READLINK
      0.06   25088.70 us    7133.79 us   59634.44 us              7      CREATE
      0.12    7024.50 us      32.80 us   57327.60 us             50     READDIR
      0.16     624.73 us      49.54 us   94746.41 us            751        OPEN
      0.62  167828.35 us     543.79 us  387838.03 us             11    FXATTROP
      0.65     430.52 us      16.83 us  485714.99 us           4526     INODELK
      0.70     618.44 us      14.05 us  178158.97 us           3401     ENTRYLK
      2.12   71297.23 us      16.61 us 2286254.75 us             89    GETXATTR
      2.59    1054.74 us      25.63 us  178938.38 us           7323      LOOKUP
     92.94   88173.46 us     141.60 us  519829.21 us           3149     XATTROP
      0.00       0.00 us       0.00 us       0.00 us           2360      UPCALL
      0.00       0.00 us       0.00 us       0.00 us              2     CI_IATT
      0.00       0.00 us       0.00 us       0.00 us              1   CI_UNLINK
      0.00       0.00 us       0.00 us       0.00 us           2358   CI_FORGET
 
    Duration: 163988 seconds
   Data Read: 6998476545 bytes
Data Written: 5064990911 bytes




I saw this "issue": https://github.com/gluster/glusterfs/issues/275

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.

This looks like the approach used by mutrace: http://0pointer.de/blog/projects/mutrace.html 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.

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?

I'm familiar with strace.  What am I looking for?  How will I identify XATTROP fops and their associated system calls in this trace?

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:

[pid 517071] fsetxattr(16, "trusted.afr.dirty", "\0\0\0\1\0\0\0\0\0\0\0", 12, 0) = 0 <0.000135>
[pid 517071] unlink("/home/ravi/bricks/brick1/.glusterfs/indices/xattrop/6ea17fe6-9080-4054-ab98-775d37ea143b") = 0 <0.000086>

Ok.  So all fsetxattr calls were sub 1ms (during a time where ls took 90s±5s).

unlinks varies wildly, with out of 2467 unlink calls, 1729 were sub 1ms.

21 was [1,5) ms
17 was [5,10) ms
24 was [10,20) ms
112 was [20,50) ms
368 was [50,100) ms
196 was [100,200) ms
27 was [200,300) ms
6 was >= 300 ms, with the longest clocking in at 347ms.

This, in my opinion, does not justify stalls on ls upwards of a minute for listing.  Currently upwards of 3 minutes and counting.


But anyway you can check if there are any syscalls(not just setxattr) that take a long time on the drives.

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.


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.

Well, it does.  I've samples a few hundred ls's since my email this morning.  All of them were sub 0.5s.
I guess you need to check when the heal does happen, *which* FOP is slow for the `ls -l` operation. Is it readdirp? stat?

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):

openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3 <1.800382>
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000019>
getdents64(3, /* 18 entries */, 131072) = 600 <1.346974>
getdents64(3, /* 18 entries */, 131072) = 584 <0.000174>
getdents64(3, /* 18 entries */, 131072) = 584 <0.000239>
getdents64(3, /* 18 entries */, 131072) = 584 <0.000165>
getdents64(3, /* 18 entries */, 131072) = 560 <0.343684>
getdents64(3, /* 18 entries */, 131072) = 568 <0.000272>
getdents64(3, /* 18 entries */, 131072) = 592 <0.000103>
getdents64(3, /* 18 entries */, 131072) = 600 <0.000096>
getdents64(3, /* 18 entries */, 131072) = 584 <0.000166>
getdents64(3, /* 18 entries */, 131072) = 608 <0.000167>
getdents64(3, /* 1 entries */, 131072)  = 40 <0.000160>
getdents64(3, /* 0 entries */, 131072)  = 0 <0.000060>
close(3)                                = 0 <0.000011>

In a second trace, the long calls were:

openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3 <1.501978>
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <2.526342>

For some reason I'm unable to get really, really long ls calls right at the moment.

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.

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.

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 ...

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.

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.

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.

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.

Kind Regards,
Jaco

________



Community Meeting Calendar:

Schedule -
Every 2nd and 4th Tuesday at 14:30 IST / 09:00 UTC
Bridge: https://bluejeans.com/441850968

Gluster-users mailing list
Gluster-users@xxxxxxxxxxx
https://lists.gluster.org/mailman/listinfo/gluster-users

[Index of Archives]     [Gluster Development]     [Linux Filesytems Development]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Bugtraq]     [Linux OMAP]     [Linux MIPS]     [eCos]     [Asterisk Internet PBX]     [Linux API]

  Powered by Linux