Description of problem:

We are investigating the performance of RHS for use with Hadoop clusters. We find performance of RHS is often poor and erratic under heavy I/O loads. Our main observation is that individual client nodes can stall for long periods of time, often as long as a minute, occasionally longer. During these stalls, write traffic from a client node stops, while other client nodes continue to write. The last straggler client may continue to stall even though there is nothing else happening in the cluster to cause it stopping. Eventually, the write traffic resumes and the test completes -- most of the time. 

This trouble report documents a case where the stall did not clear itself, and where one copy of a file appears corrupted. Avati investigated the system while it was in this state. His observations are captured in the email chain below.

We are contuing to study performance-only problem, and will open a separate bugzilla entry for that.


Test cluster and load:

- 16-node test cluster in the Phoenix lab, "Cluster G" (host[02-32]-rack07)
- RHS iso installed:  RHSS-2.1.bd-20140502.n.0-RHS-x86_64-DVD1.iso
- Each server has one brick, HW Raid6 (9+2)
- 10Gb/s ethernet, all on one pair of switches

- In this test, each node runs 16 client processes. Each process writes a 1GB file.
- The test uses POSIX calls to open, write, fsync and close files. Hadoop, the HDFS interface and Java are not involved.
- These stalls appear on writes, not reads.
- These stalls appear when writing to Gluster, but not when writing to the individual bricks.


On 08/20/2014 02:28 PM, Hank Jakiela wrote:
>
> Avati,
>
> I've been digging into these long stalls we see under heavy loads. Now the cluster is stuck in an odd state, with what looks like some data corruption. I wonder if you could take a look.
>
> The current state is this:
>
> 1. One node is unable to access one of the files that it had previously written.
>
> 2. All other nodes in the cluster can see the file correctly.
>
> 3. The sick node can see other files correctly. However, ls with a wildcard hangs on that directory.
>
> 4. The two copies of the file are on the first two bricks, but one copy is the wrong size.
>
> If you have time to poke around on the node, it's 10.1.4.8. I'll text you the root password.
>
> Thanks
> Hank
>


From : 	Anand Avati <avati>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Hank Jakiela <hjakiela>
Cc : 	Diane Feddema <dfeddema>
	
Wed, Aug 20, 2014 07:30 PM
From where was the glusterfs RPM installed? I'm trying to install
debuginfo RPM of glusterfs and is unable to find..


# debuginfo-install glusterfs-3.4.0.59rhs-1.el6rhs.x86_64
...
No debuginfo packages available to install


Here's what I could diagnose from state dumps thus far: It looks like
there are a lot of internal locks which are blocked from the client
host08-rack07 on the file wf-host08-rack07-29-000000 stored in
host02-rack07.

The locks are blocked because there is an unreleased lock on the same
file from client whose transport pointer address is 0xf2bcd0. I need the
debuginfo RPMs so that I can easily find out the client-id string stored
in the transport object, using gdb. Finding out which client the
transport object (whose pointer is 0xf2bcd0) will let me progress to the
next diagnosis step (on that node). I have a hunch it might be the
self-heal daemon client, I'll try to confirm that in other ways in the
mean time.


From : 	Anand Avati <avati>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Hank Jakiela <hjakiela>, Diane Feddema <dfeddema>, Stephen Watt <swatt>
	
Wed, Aug 20, 2014 08:23 PM
Never mind, I could inspect the client id taking hex dumps from the
calculated offset of the field in the structure (off the pointer). It
appears to be a connection from host08 process pid 27097, which at this
point does not exist. I'm assuming it is some kind of a ghost connection
which is not yet disconnected for whatever reason. Still diagnosing why
we ended up in this situation.


From : 	Anand Avati <avati>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Hank Jakiela <hjakiela>, Diane Feddema <dfeddema>, Stephen Watt <swatt>
	
Wed, Aug 20, 2014 08:25 PM
And the reason only host08 is seeing this issue is because there are
outstanding (blocked) write requests on this file held up in the
write-behind queue. These held up writes are forcing stat() on the file
to queue behind them, hence ls hangs when stating our file. On other
servers the write-behind queue on the file is empty, and stat requests
smoothly flow through. Just FYI.


On 08/20/2014 06:35 PM, Hank Jakiela wrote:
>
> Yes, this is the only node that would have been doing anything with that particular file (nb, hostname in the filename).
>
> Any idea why the writes were blocked?
>
> We're seeing a lot of cases where many operations on a particular node get held up for long periods, up to 200 seconds or more, after which things start up again. This is the first example where things didn't start up again.
>
> Hank
>


From : 	Anand Avati <avati>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Hank Jakiela <hjakiela>
Cc : 	Diane Feddema <dfeddema>, Stephen Watt <swatt>, Raghavendra Gowdappa <rgowdapp>, Krishnan Parthasarathi <kparthas>
	
Wed, Aug 20, 2014 09:44 PM

So,
Here's what appears to have happened. During heavy writes, for some
reason there was a connection freeze, and glusterfs client (which was
doing the write) seems to have detected a freeze and raised a ping
timeout, broke the connection and reconnected - all this is visible in
the logs. It appears that the "old connection" breakage hasn't
registered at the server side socket, and because of non-empty socket
buffer in the server, KEEPALIVE hasn't kicked in (which would otherwise
raise a disconnection). This is evidenced by inspecting the client-id of
the blocked lock and the acquired lock being equal.

I'm copying KP and Raghavendra who are familiar with this problem/known
behavior (to raise the priority of addressing this problem).

For now you could either just restart the volume (easiest), or attempt a
manual clear lock. If this is just a test cluster, then restarting the
volume would be the simplest.

Thanks


From : 	Krishnan Parthasarathi <kparthas>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Anand Avati <avati>
Cc : 	Hank Jakiela <hjakiela>, Diane Feddema <dfeddema>, Stephen Watt <swatt>, Raghavendra Gowdappa <rgowdapp>
	
Wed, Aug 20, 2014 11:17 PM
>
> So,
> Here's what appears to have happened. During heavy writes, for some
> reason there was a connection freeze, and glusterfs client (which was
> doing the write) seems to have detected a freeze and raised a ping
> timeout, broke the connection and reconnected - all this is visible in
> the logs. It appears that the "old connection" breakage hasn't
> registered at the server side socket, and because of non-empty socket
> buffer in the server, KEEPALIVE hasn't kicked in (which would otherwise

We must be careful before we conclude that KEEPALIVE mechanism didn't
detect 'closed' remote TCP endpoint. It is possible for the glusterfsd process
(server) to have not 'attended' to the POLLERR that will be raised, on KEEPALIVE
time-out kicking in, simply because the 'epoll thread' was busy.

> raise a disconnection). This is evidenced by inspecting the client-id of
> the blocked lock and the acquired lock being equal.
>

~KP

The brick process is otherwise healthy and responding to other requests
even now, so the epoll thread is not blocked for sure. Brick has two
server_conn_t with the same ->client_id string. One of the server_conn_t
is the frame->root->trans of the acquired lock. The other server_conn_t
is the frame->root->trans of all the blocked locks. So it is clearly the
case that a client has reconnected, but the server is still seeing two
active connections. I can't think of any other reason than keepalive not
kicking in for the server to still hold on to the first/old connection.
Thoughts?


From : 	Diane Feddema <dfeddema>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Anand Avati <avati>
Cc : 	Hank Jakiela <hjakiela>
	
Wed, Aug 20, 2014 11:47 PM
Based on recent emails it looks like you've made a lot of progress debugging the stall on writes problem.
Sounds like an interesting network issue with KEEPALIVE not detecting dead peers.  

The RHS iso installed on Cluster G is:
RHSS-2.1.bd-20140502.n.0-RHS-x86_64-DVD1.iso

This was the most current stable iso from the RHS group when we setup
the cluster.


From : 	Krishnan Parthasarathi <kparthas>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Anand Avati <avati>
Cc : 	Hank Jakiela <hjakiela>, Diane Feddema <dfeddema>, Stephen Watt <swatt>, Raghavendra Gowdappa <rgowdapp>
	
Thu, Aug 21, 2014 01:39 AM
With your observations, it does seem that keepalive timer is not kicking in.
Meanwhile, I am exploring a way to 'dump' the no. of keepalive probes have been fired,
the no. of probes that have to responded to by the remote endpoint etc, per connection
object on server, via statedump. This would allow us to assert instead of infer keepalive
behaviour.


From : 	Anand Avati <avati>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Krishnan Parthasarathi <kparthas>
Cc : 	Hank Jakiela <hjakiela>, Diane Feddema <dfeddema>, Stephen Watt <swatt>, Raghavendra Gowdappa <rgowdapp>
	
Thu, Aug 21, 2014 02:18 AM
That would be a good diagnostic. I guess the larger point is, we need to
move towards a more robust mechanism. Like a server initiated PING (only
when there are outstanding frames or locks) which is transport
independent (works over RDMA etc.)


From : 	Krishnan Parthasarathi <kparthas>
Subject : 	Re: Long gluster stalls during heavy write load
To : 	Anand Avati <avati>
Cc : 	Hank Jakiela <hjakiela>, Diane Feddema <dfeddema>, Stephen Watt <swatt>, Raghavendra Gowdappa <rgowdapp>
	
Thu, Aug 21, 2014 02:28 AM
The keepalive timer values are available in /proc/net/tcp{,6}. netstat --timers
has a more readable output. I haven't yet managed to find a per-socket interface
for fetching the current state of keepalive timers. Without such an interface it doesn't
make sense for the glusterfs server to walk through all connections on a system and filter
out connections that aren't served by it.

Yes, we need to have an heart-beating mechanism at the server-side as well.