Bug 919007

Summary:	After some time, transfer is slow and all writes are 4kb. Re-opening fds brings back fast transfer
Product:	[Community] GlusterFS	Reporter:	Torbjørn Thorsen <torbjorn>
Component:	core	Assignee:	Anand Avati <aavati>
Status:	CLOSED CURRENTRELEASE	QA Contact:
Severity:	unspecified	Docs Contact:
Priority:	medium
Version:	3.3.1	CC:	bfoster, chrisw, gluster-bugs, pkarampu, rgowdapp, torbjorn
Target Milestone:	---
Target Release:	---
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2014-07-11 16:16:48 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Torbjørn Thorsen 2013-03-07 11:52:41 UTC

Description of problem:
Gluster volume has 4 bricks on 2 servers, two from each server.

Volume Name: gluster0
Type: Distributed-Replicate
Number of Bricks: 2 x 2 = 4

On the client, access is via FUSE.

Starting from a fresh state, I'm seeing ~25MB/s synced transfer rate to a loop device backed by a file on Gluster.

dd if=/dev/zero of=/dev/loop1 bs=1024k count=2000 oflag=sync
2097152000 bytes (2.1 GB) copied, 81.7174 s, 25.7 MB/s

Using "volume profile" shows us that most writes are done with 32kb requests.

After some time, I've seen it mostly around 24 hours,
the transfer rate drops down to around 10% of the original rate.

dd if=/dev/zero of=/dev/loop1 bs=1024k count=2000 oflag=sync
1156579328 bytes (1.2 GB) copied, 353.585 s, 3.3 MB/s

Using "volume profile" shows us that all writes are now 4kb requests.

If we toggle any setting using "gluster volume set",
the original transfer rate is re-established.
In addition, unmapping and remapping the loop device
also brings back the original transfer rate.

This seems to work even for long-lived FD's,
for example on a running Xen instance where
the disk is a loop device backed by a file on Gluster.

Version-Release number of selected component (if applicable):
OS is Debian stable, some with kernels from backports.

Kernels are 2.6.32-46 and 3.2.35-2~bpo60+1.
Gluster is at 3.3.1-1, it's installed from Gluster Debian repo.

How reproducible:
I see it happen every night, although not always at the same time.
I'm guessing it happens after some amount of time, not dependent on walltime.

Steps to Reproduce:
1. Set up a loop device backed by a file on Gluster, test and see high xfer rates
2. Wait for some time, maybe 24 hours
3. Test xfer rate on loop device, see low transfer rates
4. Adjust some setting, or remap loop device
5. Test xfer rate on loop device, see high transfer rates

Actual results:
Transfer rates are really slow, all writes in "gluster profile" are 4kb

Expected results:
"Reasonable" transfer rates

Additional info:
There has been some discussion about this on the mailing list.
http://supercolony.gluster.org/pipermail/gluster-users/2013-February/035558.html
http://supercolony.gluster.org/pipermail/gluster-users/2013-March/035621.html

Comment 1 Torbjørn Thorsen 2013-03-07 17:39:35 UTC

I want to add that this situation seems to happen per-fd.

Newly created loop devices are always fast,
even if I have a slow and "old" loop already created.

Comment 2 Torbjørn Thorsen 2013-03-08 08:41:33 UTC

After setting the logging level to DEBUG, I found some log entries which seem to correspond with the performance degradation.

torbjorn@xen-storage01:~$ grep 'disabling wb' glusterfs.log -B 2
[2013-03-08 01:11:43.428095] D [afr-common.c:1294:afr_lookup_select_read_child] 4-gluster0-replicate-0: Source selected as 0 for /hennec.vps.trollweb.net/disk0
[2013-03-08 01:11:43.428110] D [afr-common.c:1097:afr_lookup_build_response_params] 4-gluster0-replicate-0: Building lookup response from 0
[2013-03-08 01:11:43.452718] D [write-behind.c:1392:wb_open_cbk] 4-gluster0-write-behind: disabling wb on 0x7f71249023cc
[2013-03-08 01:11:43.470332] D [write-behind.c:1349:wb_disable_all] 4-gluster0-write-behind: disabling wb on 0x7f7139c23abc because 0x7f71249023cc is O_SYNC
--
[2013-03-08 01:24:22.051955] D [afr-common.c:1294:afr_lookup_select_read_child] 4-gluster0-replicate-1: Source selected as 0 for /iotest.trollweb.net/disk0
[2013-03-08 01:24:22.051985] D [afr-common.c:1097:afr_lookup_build_response_params] 4-gluster0-replicate-1: Building lookup response from 0
[2013-03-08 01:24:22.052691] D [write-behind.c:1392:wb_open_cbk] 4-gluster0-write-behind: disabling wb on 0x7f71249023cc
--
[2013-03-08 01:26:22.112784] D [afr-common.c:1294:afr_lookup_select_read_child] 4-gluster0-replicate-1: Source selected as 1 for /tmp/bigfile
[2013-03-08 01:26:22.112798] D [afr-common.c:1097:afr_lookup_build_response_params] 4-gluster0-replicate-1: Building lookup response from 1
[2013-03-08 01:26:22.114299] D [write-behind.c:1392:wb_open_cbk] 4-gluster0-write-behind: disabling wb on 0x7f71249023cc
--
[2013-03-08 01:26:52.177231] D [afr-common.c:1294:afr_lookup_select_read_child] 4-gluster0-replicate-0: Source selected as 1 for /tmp/fila
[2013-03-08 01:26:52.177245] D [afr-common.c:1097:afr_lookup_build_response_params] 4-gluster0-replicate-0: Building lookup response from 1
[2013-03-08 01:26:52.179240] D [write-behind.c:1392:wb_open_cbk] 4-gluster0-write-behind: disabling wb on 0x7f71249023cc
--
[2013-03-08 01:27:13.734188] D [afr-common.c:1294:afr_lookup_select_read_child] 4-gluster0-replicate-1: Source selected as 1 for /tmp/loopback.img
[2013-03-08 01:27:13.734202] D [afr-common.c:1097:afr_lookup_build_response_params] 4-gluster0-replicate-1: Building lookup response from 1
[2013-03-08 01:27:13.735775] D [write-behind.c:1392:wb_open_cbk] 4-gluster0-write-behind: disabling wb on 0x7f71249023cc
[2013-03-08 01:27:13.735796] D [write-behind.c:1349:wb_disable_all] 4-gluster0-write-behind: disabling wb on 0x7f7139c23b20 because 0x7f71249023cc is O_SYNC
--
[2013-03-08 01:27:44.260709] D [afr-common.c:1294:afr_lookup_select_read_child] 4-gluster0-replicate-0: Source selected as 0 for /tmp/loopback2.img
[2013-03-08 01:27:44.260724] D [afr-common.c:1097:afr_lookup_build_response_params] 4-gluster0-replicate-0: Building lookup response from 0
[2013-03-08 01:27:44.261945] D [write-behind.c:1392:wb_open_cbk] 4-gluster0-write-behind: disabling wb on 0x7f71249023cc
--
[2013-03-08 01:28:18.834794] D [afr-common.c:1294:afr_lookup_select_read_child] 4-gluster0-replicate-0: Source selected as 1 for /tmp/loopback3.img
[2013-03-08 01:28:18.834810] D [afr-common.c:1097:afr_lookup_build_response_params] 4-gluster0-replicate-0: Building lookup response from 1
[2013-03-08 01:28:18.836625] D [write-behind.c:1392:wb_open_cbk] 4-gluster0-write-behind: disabling wb on 0x7f71249023cc
--
[2013-03-08 01:29:09.427066] D [afr-common.c:1294:afr_lookup_select_read_child] 4-gluster0-replicate-1: Source selected as 0 for /tmp/loopback4.img
[2013-03-08 01:29:09.427080] D [afr-common.c:1097:afr_lookup_build_response_params] 4-gluster0-replicate-1: Building lookup response from 0
[2013-03-08 01:29:09.427915] D [write-behind.c:1392:wb_open_cbk] 4-gluster0-write-behind: disabling wb on 0x7f71249023cc

Comment 3 Torbjørn Thorsen 2013-03-11 09:12:51 UTC

3.4.0-alpha2 has now been running for a couple of days, and I'm not experiencing the performance degradation on that version.

Comment 4 Pranith Kumar K 2014-01-03 13:11:22 UTC

Closing the bug as per comment-3