[Bugs] [Bug 1427387] New: systemic testing: seeing lot of ping time outs which would lead to splitbrains
bugzilla at redhat.com
bugzilla at redhat.com
Tue Feb 28 04:31:49 UTC 2017
https://bugzilla.redhat.com/show_bug.cgi?id=1427387
Bug ID: 1427387
Summary: systemic testing: seeing lot of ping time outs which
would lead to splitbrains
Product: GlusterFS
Version: 3.10
Component: rpc
Keywords: Triaged
Severity: urgent
Assignee: bugs at gluster.org
Reporter: rgowdapp at redhat.com
CC: bugs at gluster.org, kdhananj at redhat.com,
mchangir at redhat.com, moagrawa at redhat.com,
nchilaka at redhat.com, rcyriac at redhat.com,
rgowdapp at redhat.com, rhinduja at redhat.com,
rhs-bugs at redhat.com
Depends On: 1415178, 1421938
+++ This bug was initially created as a clone of Bug #1421938 +++
+++ This bug was initially created as a clone of Bug #1415178 +++
Description of problem:
=====================
I am seeing lot of ping time outs on my systemic setup clients as below
[2017-01-20 08:07:53.591156] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-6: server
10.70.35.156:49153 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 08:07:53.595238] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-6: socket disconnected
[2017-01-20 08:32:58.781026] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-2: server
10.70.35.156:49152 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 08:32:58.818598] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-2: socket disconnected
[2017-01-20 08:35:31.801622] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-7: server
10.70.37.154:49153 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 08:35:31.802349] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-7: socket disconnected
[2017-01-20 08:39:22.835813] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-7: server
10.70.37.154:49153 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 08:39:22.841445] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-7: socket disconnected
[2017-01-20 08:52:28.949400] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-3: server
10.70.37.154:49152 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 08:52:28.950309] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-3: socket disconnected
[2017-01-20 09:11:15.090477] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-7: server
10.70.37.154:49153 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 09:11:15.091079] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-7: socket disconnected
[2017-01-20 09:15:03.122268] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-7: server
10.70.37.154:49153 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 09:15:03.125457] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-7: socket disconnected
[2017-01-20 09:17:28.141896] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-6: server
10.70.35.156:49153 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 09:17:28.146266] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-6: socket disconnected
[2017-01-20 09:36:10.260003] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-2: server
10.70.35.156:49152 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 09:36:10.329709] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-2: socket disconnected
[2017-01-20 09:39:02.283174] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-3: server
10.70.37.154:49152 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 09:39:02.283875] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-3: socket disconnected
[2017-01-20 09:42:15.311267] C
[rpc-clnt-ping.c:160:rpc_clnt_ping_timer_expired] 0-systemic-client-7: server
10.70.37.154:49153 has not responded in the last 42 seconds, disconnecting.
[2017-01-20 09:42:15.311701] W [rpc-clnt-ping.c:203:rpc_clnt_ping_cbk]
0-systemic-client-7: socket disconnected
This would eventually lead to splitbrains which is not a good place to be in
Version-Release number of selected component (if applicable):
==========
3.8.4-12
--- Additional comment from Raghavendra G on 2017-01-23 00:17:07 EST ---
I've some queries:
* what was the disk utilization during testing?
* Can you please get profile info of bricks? I need to see what operations are
being performed and their frequency.
* Is it possible to get strace of brick process when tests are being run? You
can use following cmdline:
strace -ff -T -p <pid-of-brick> -o
<path-where-you-want-the-strace-output-saved>
Following is a possible hypothesis
<hypothesis>
server not able to read ping request.
Me, Kritika and Pranith were about an issue where they had hit ping timer
expiry in replicated setups when disk usage was high. The reason for this as
Pranith pointed out was,
1. posix has some fops (like posix_xattrop, posix_fxattrop) which do syscalls
after holding a lock on inode (inode->lock).
2. During high disk usage scenarios, syscall latencies were high (sometimes >=
ping-timeout value)
3. Before being handed over to a new thread at io-threads xlator, a fop gets
executed in one of the threads that reads incoming messages from socket. This
execution path includes some translators like protocol/server, index,
quota-enforcer, marker. And these translators might access inode-ctx which
involves locking inode (inode->lock). Due to this locking latency of syscall
gets transferred to poller thread. Since poller thread is waiting on
inode->lock, it won't be able to read ping requests from network in-time
resulting in ping-timer expiry.
</hypothesis>
--- Additional comment from Raghavendra G on 2017-01-25 06:59:41 EST ---
I went through strace output and volume profile. Though volume profile shows
large max latencies for fops like xattrop/fxattrop, syscall latencies shown by
strace is not too much to cause a ping timeout. As to large xattrop/fxattrop
latency, the fops are serialized and when there too many (f)xattrops on the
same file, the last fop can have a latency which is cumulative of all the
(f)xattrops in the waiting queue before it. So, its not really an issue.
Nag also informed me that the disk utilization was not high when ping-timeout
happened. So, I doubt whether its high disk utilization that caused this
ping-timeout.
ATM, I don't have an RCA, but we can experiment with two things:
1. Increase the poller threads to 8 on bricks
2. Use fix [1]
Note that both the above two steps need to be done before starting tests.
[1] https://review.gluster.org/15046
--- Additional comment from Mohit Agrawal on 2017-01-27 03:13:56 EST ---
Hi,
Can you please confirm about reproducer steps? As per doc It seems below are
the steps
1) Run the script to create deep directory structure (5 Level) from two
different client
2) Run untar/tar linux.tar command operation 50 times in directory
Regards
Mohit Agrawal
--- Additional comment from nchilaka on 2017-01-31 01:25:22 EST ---
yes, along with that taking of statedumps at regular intervals for both clients
and servers.
--- Additional comment from Raghavendra G on 2017-01-31 23:39:39 EST ---
Nag,
Let me know once the setup becomes free. We would like to gather more
diagnostic information. Machine and login details would help us to continue
debugging the issue.
regards,
Raghavendra
--- Additional comment from Raghavendra G on 2017-02-01 07:07:40 EST ---
Another thing to verify is whether the vms running bricks and client themselves
are pausing. If they are pausing for more than ping-timeout duration, that can
be a simple cause for ping-timer-expiry.
--- Additional comment from Mohit Agrawal on 2017-02-02 00:21:13 EST ---
Hi,
I tried to reproduce the issue as step mentioned in previous comment but i did
not get success.
I have checked on the setup (server 10.70.35.20), vm is accesible but it seems
all resources(cpu,memory) are consumed and even i am not able to run any linux
command on vm.
On the client side below message are continuously coming in logs
[2017-02-02 05:26:23.661141] I [rpc-clnt.c:1965:rpc_clnt_reconfig]
0-systemic-client-4: changing port to 49153 (from 0)
[2017-02-02 05:26:23.667104] E [socket.c:2309:socket_connect_finish]
0-systemic-client-4: connection to 10.70.35.20:49153 failed (Connection
refused)
Ping timeout issue could be happen if brick process is not able to respond
within time period (42 second) and brick is not able to respond because
sufficient resources are not available on vm.
Regards
Mohit Agrawal
--- Additional comment from nchilaka on 2017-02-09 01:17:08 EST ---
i had shared the setup.
hence removing needinfo
--- Additional comment from Worker Ant on 2017-02-14 01:36:01 EST ---
REVIEW: https://review.gluster.org/16462 (storage/posix: Execute syscalls in
xattrop under different locks) posted (#4) for review on master by Krutika
Dhananjay (kdhananj at redhat.com)
--- Additional comment from Worker Ant on 2017-02-27 03:26:45 EST ---
COMMIT: https://review.gluster.org/16462 committed in master by Pranith Kumar
Karampuri (pkarampu at redhat.com)
------
commit b5c26a462caf97bfc5380c81092f5c331ccaf1ae
Author: Krutika Dhananjay <kdhananj at redhat.com>
Date: Mon Jan 23 17:40:40 2017 +0530
storage/posix: Execute syscalls in xattrop under different locks
... and not inode->lock. This is to prevent the epoll thread from
*potentially* being blocked on this lock in the worst case for
extended period elsewhere in the brick stack, while the syscalls
in xattrop are being performed under the same lock by a different
thread. This could potentially lead to ping-timeout, if the only
available epoll thread is busy waiting on the inode->lock, thereby
preventing it from picking up the ping request from the client(s).
Also removed some unused functions.
Change-Id: I2054a06701ecab11aed1c04e80ee57bbe2e52564
BUG: 1421938
Signed-off-by: Krutika Dhananjay <kdhananj at redhat.com>
Reviewed-on: https://review.gluster.org/16462
Smoke: Gluster Build System <jenkins at build.gluster.org>
NetBSD-regression: NetBSD Build System <jenkins at build.gluster.org>
Reviewed-by: Raghavendra G <rgowdapp at redhat.com>
CentOS-regression: Gluster Build System <jenkins at build.gluster.org>
--- Additional comment from Raghavendra G on 2017-02-27 23:30:44 EST ---
Moving back to POST as we've to RCA whether there are other reasons why
ping-timeout might've happened.
Referenced Bugs:
https://bugzilla.redhat.com/show_bug.cgi?id=1415178
[Bug 1415178] systemic testing: seeing lot of ping time outs which would
lead to splitbrains
https://bugzilla.redhat.com/show_bug.cgi?id=1421938
[Bug 1421938] systemic testing: seeing lot of ping time outs which would
lead to splitbrains
--
You are receiving this mail because:
You are on the CC list for the bug.
You are the assignee for the bug.
More information about the Bugs
mailing list