Bug 1378424

Summary:	[RHEL-6] Account and container server makes excessive and redundant stat() calls
Product:	Red Hat Gluster Storage	Reporter:	Prashanth Pai <ppai>
Component:	gluster-swift	Assignee:	Prashanth Pai <ppai>
Status:	CLOSED ERRATA	QA Contact:	surabhi <sbhaloth>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	rhgs-3.1	CC:	amukherj, ppai, rcyriac, rhinduja, rhs-bugs, sasundar, sbhaloth, storage-qa-internal, thiago
Target Milestone:	Development Freeze
Target Release:	RHGS 3.2.0
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:	swiftonfile-1.13.1-10.el6rhs	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:	1351640	Environment:
Last Closed:	2017-03-23 04:56:57 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:
Bug Depends On:	1351640, 1374302
Bug Blocks:	1351522

Description Prashanth Pai 2016-09-22 11:30:35 UTC

+++ This bug was initially created as a clone of Bug #1351640 +++

Description of problem:
Account server and container server processes make excessive and redundant stat() calls while serving GET requests


Version-Release number of selected component (if applicable):
RHGS 3.1.3
swiftonfile-2.3.0-3.el7rhgs


How reproducible:
Always. Do a GET on a container and watch syscalls made by the container server process.


Steps to Reproduce:
1. Create a container
2. Create some objects in the container
3. Do GET on the container while strace is attached to container server process

root# ps aux | grep container-server
root      1396  0.0  1.2 272164 25396 ?        Ss   18:10   0:00 /usr/bin/python /usr/bin/swift-container-server /etc/swift/container-server.conf
root      1429  0.0  1.0 272564 20976 ?        S    18:10   0:00 /usr/bin/python /usr/bin/swift-container-server /etc/swift/container-server.conf

root# strace -ff -p 1396,1429
Process 1396 attached
Process 1429 attached

[pid  1429] stat("/mnt/gluster-object/test/c1", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  1429] getxattr("/mnt/gluster-object/test/c1", "user.swift.metadata", 0x0, 0) = 148
[pid  1429] getxattr("/mnt/gluster-object/test/c1", "user.swift.metadata", "{\"X-Object-Count\":[0,0],\"X-Timestamp\":[\"1467290429.21123\",0],\"X-Type\":[\"container\",0],\"X-PUT-Timestamp\":[\"1467290429.34439\",0],\"X-Bytes-Used\":[0,0]}", 148) = 148
[pid  1429] stat("/mnt/gluster-object/test/c1", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  1429] stat("/mnt/gluster-object/test/c1", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  1429] openat(AT_FDCWD, "/mnt/gluster-object/test/c1", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 8
[pid  1429] getdents(8, /* 8 entries */, 32768) = 200
[pid  1429] getdents(8, /* 0 entries */, 32768) = 0
[pid  1429] close(8)                    = 0
[pid  1429] stat("/mnt/gluster-object/test/c1/o1", {st_mode=S_IFREG|0755, st_size=1, ...}) = 0
[pid  1429] stat("/mnt/gluster-object/test/c1/o2", {st_mode=S_IFREG|0755, st_size=1, ...}) = 0
[pid  1429] stat("/mnt/gluster-object/test/c1/o3", {st_mode=S_IFREG|0755, st_size=1, ...}) = 0
[pid  1429] stat("/mnt/gluster-object/test/c1/o4", {st_mode=S_IFREG|0755, st_size=1, ...}) = 0
[pid  1429] stat("/mnt/gluster-object/test/c1/dirobject", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  1429] stat("/mnt/gluster-object/test/c1/o5", {st_mode=S_IFREG|0755, st_size=1, ...}) = 0
[pid  1429] getxattr("/mnt/gluster-object/test/c1/dirobject", "user.swift.metadata", 0x0, 0) = 174
[pid  1429] getxattr("/mnt/gluster-object/test/c1/dirobject", "user.swift.metadata", "{\"Content-Length\":0,\"ETag\":\"d41d8cd98f00b204e9800998ecf8427e\",\"X-Object-Type\":\"dir\",\"X-Timestamp\":\"1467291058.57983\",\"X-Type\":\"Object\",\"Content-Type\":\"application/directory\"}", 174) = 174
[pid  1429] poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
[pid  1429] lstat("/mnt/gluster-object/test/c1/dirobject", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  1429] openat(AT_FDCWD, "/mnt/gluster-object/test/c1/dirobject", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 8
[pid  1429] getdents(8, /* 2 entries */, 32768) = 48
[pid  1429] getdents(8, /* 0 entries */, 32768) = 0
[pid  1429] close(8)                    = 0


Actual results:
Lot of stat() calls observed while serving the container listing.


Expected results:
Container server should not do additional stat() to figure out if an entry is a file or directory. Container server should use d_type information returned by readdir call.

--- Additional comment from Red Hat Bugzilla Rules Engine on 2016-06-30 09:11:11 EDT ---

This bug is automatically being proposed for the current z-stream release of Red Hat Gluster Storage 3 by setting the release flag 'rhgs‑3.1.z' to '?'. 

If this bug should be proposed for a different release, please manually change the proposed release flag.

--- Additional comment from Prashanth Pai on 2016-07-28 09:30:12 EDT ---

Upstream patches:
http://review.gluster.org/#/c/14543/
http://review.gluster.org/#/c/14460/

--- Additional comment from Red Hat Bugzilla Rules Engine on 2016-08-09 07:35:53 EDT ---

Since this bug has been approved for the RHGS 3.2.0 release of Red Hat Gluster Storage 3, through release flag 'rhgs-3.2.0+', and through the Internal Whiteboard entry of '3.2.0', the Target Release is being automatically set to 'RHGS 3.2.0'

--- Additional comment from errata-xmlrpc on 2016-09-19 11:54:04 EDT ---

This bug has been dropped from advisory RHEA-2016:24869 by Milind Changire (mchangir)

--- Additional comment from errata-xmlrpc on 2016-09-19 11:56:29 EDT ---

This bug has been dropped from advisory RHEA-2016:24870 by Milind Changire (mchangir)

Comment 2 Prashanth Pai 2016-10-03 06:26:00 UTC

Upstream patches:
http://review.gluster.org/#/c/14543/
http://review.gluster.org/#/c/14460/

Comment 3 Prashanth Pai 2016-11-21 12:23:24 UTC

Downstream patches merged:
https://code.engineering.redhat.com/gerrit/#/q/topic:bug-1378424

Comment 4 surabhi 2016-12-15 11:23:48 UTC

On previpous versions while doing GET on container, lots of redundant stat calls were made , with the fix now the redundant stat calls are not seen.Performance is not tested it,s only the reduced number of calls verified via strace.

pid  8567] accept(5, {sa_family=AF_INET, sin_port=htons(47532), sin_addr=inet_addr("127.0.0.1")}, [16]) = 6
[pid  8567] fcntl(6, F_GETFL)           = 0x2 (flags O_RDWR)
[pid  8567] fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid  8567] fcntl(6, F_GETFL)           = 0x802 (flags O_RDWR|O_NONBLOCK)
[pid  8567] fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid  8567] gettimeofday({1481800913, 460029}, NULL) = 0
[pid  8567] accept(5, 0x7fff2429c520, [16]) = -1 EAGAIN (Resource temporarily unavailable)
[pid  8567] gettimeofday({1481800913, 460317}, NULL) = 0
[pid  8567] recvfrom(6, "GET /test/0/AUTH_test/c1/ HTTP/1"..., 8192, 0, NULL, NULL) = 282
[pid  8567] getsockname(6, {sa_family=AF_INET, sin_port=htons(6011), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
[pid  8567] gettimeofday({1481800913, 461091}, NULL) = 0
[pid  8567] gettimeofday({1481800913, 461148}, NULL) = 0
[pid  8567] gettimeofday({1481800913, 461421}, NULL) = 0
[pid  8567] lstat("/mnt/gluster-object/test", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  8567] lstat("/mnt/gluster-object/test/..", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  8567] stat("/mnt/gluster-object/test/c1", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  8567] getxattr("/mnt/gluster-object/test/c1", "user.swift.metadata", 0x0, 0) = 148
[pid  8567] getxattr("/mnt/gluster-object/test/c1", "user.swift.metadata", "{"X-Object-Count":[0,0],"X-Timestamp":["1481799921.98239",0],"X-Type":["container",0],"X-PUT-Timestamp":["1481799921.97939",0],"X-Bytes-Used":[0,0]}", 148) = 148
[pid  8567] open("/mnt/gluster-object/test/c1", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 8
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 23 entries */, 32768) = 552
[pid  8567] getdents(8, /* 20 entries */, 32768) = 488
[pid  8567] getdents(8, /* 0 entries */, 32768) = 0
[pid  8567] close(8)                    = 0
[pid  8567] getxattr("/mnt/gluster-object/test/c1/dirobject", "user.swift.metadata", 0x0, 0) = 183
[pid  8567] getxattr("/mnt/gluster-object/test/c1/dirobject", "user.swift.metadata", "{"Content-Length":"0","ETag":"d41d8cd98f00b204e9800998ecf8427e","X-Timestamp":"1481800157.44880","X-Object-Type":"marker_dir","X-Type":"Object","Content-Type":"application/directory"}", 183) = 183
[pid  8567] brk(0x231c000)              = 0x231c000
[pid  8567] gettimeofday({1481800913, 518749}, NULL) = 0
[pid  8567] gettimeofday({1481800913, 518822}, NULL) = 0
[pid  8567] poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
[pid  8567] gettimeofday({1481800913, 518892}, NULL) = 0
[pid  8567] open("/mnt/gluster-object/test/c1/dirobject", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 8
[pid  8567] getdents(8, /* 2 entries */, 32768) = 48
[pid  8567] getdents(8, /* 0 entries */, 32768) = 0
[pid  8567] close(8)                    = 0
[pid  8567] gettimeofday({1481800913, 521279}, NULL) = 0
[pid  8567] gettimeofday({1481800913, 521326}, NULL) = 0
[pid  8567] poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
[pid  8567] gettimeofday({1481800913, 521456}, NULL) = 0
[pid  8567] setxattr("/mnt/gluster-object/test/c1", "user.swift.metadata", "{"X-Object-Count":[501,0],"X-Timestamp":["1481799921.98239",0],"X-Type":["container",0],"X-PUT-Timestamp":["1481799921.97939",0],"X-Bytes-Used":[0,0]}", 150, 0) = 0
[pid  8567] gettimeofday({1481800913, 524083}, NULL) = 0
[pid  8567] gettimeofday({1481800913, 524205}, NULL) = 0
[pid  8567] sendto(6, "HTTP/1.1 200 OK\r\nContent-Length:"..., 2647, 0, NULL, 0) = 2647
[pid  8567] gettimeofday({1481800913, 524458}, NULL) = 0
[pid  8567] gettimeofday({1481800913, 524496}, NULL) = 0
[pid  8567] shutdown(6, SHUT_RDWR)      = 0
[pid  8567] close(6)                    = 0
[pid  8567] poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 60000



Marking the BZ verified.

Comment 6 errata-xmlrpc 2017-03-23 04:56:57 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2017-0489.html