Bug 1314171 - [RHEL-7] gluster-swift [PERF]: Remove redundant syscalls and reduce network calls
Summary: [RHEL-7] gluster-swift [PERF]: Remove redundant syscalls and reduce network c...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Gluster Storage
Classification: Red Hat Storage
Component: gluster-swift
Version: rhgs-3.1
Hardware: All
OS: All
medium
low
Target Milestone: ---
: RHGS 3.1.3
Assignee: Prashanth Pai
QA Contact: surabhi
URL:
Whiteboard:
Depends On: 1317790
Blocks: 1299184 1328444
TreeView+ depends on / blocked
 
Reported: 2016-03-03 07:23 UTC by Prashanth Pai
Modified: 2016-06-23 05:31 UTC (History)
5 users (show)

Fixed In Version: swiftonfile-2.3.0-3
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1328444 (view as bug list)
Environment:
Last Closed: 2016-06-23 05:31:26 UTC
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2016:1289 0 normal SHIPPED_LIVE gluster-swift update for Red Hat Gluster Storage 3.1 update 3 2016-06-23 09:12:16 UTC

Description Prashanth Pai 2016-03-03 07:23:32 UTC 
Description of problem:

Some syscalls are redundant and is not necessarry:
Further details here: https://gist.github.com/prashanthpai/62e0bec770421561ea79

The fix[1] for this is already in upstream swiftonfile, needs to be ported to gluster-swift.

[1]: https://review.openstack.org/#/c/246365/
Comment 2 Prashanth Pai 2016-03-03 10:14:24 UTC 
PUT- new object
[pid 10245] open("/mnt/gluster-object/test/c1/o4", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 10245] open("/mnt/gluster-object/test/c1/.o4.6b830611ad5547a487f6ff758be59d3e", O_WRONLY|O_CREAT|O_EXCL|O_CLOEXEC, 0777) = 7
[pid 10245] fchown(7, 4294967295, 4294967295) = 0
[pid 10245] write(7, "hello world", 11) = 11
[pid 10276] fsetxattr(7, "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1456998373.13304","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded"}", 190, 0 <unfinished ...>
[pid 10276] fsync(7)                    = 0
[pid 10276] fadvise64(7, 0, 11, POSIX_FADV_DONTNEED) = 0
[pid 10276] rename("/mnt/gluster-object/test/c1/.o4.6b830611ad5547a487f6ff758be59d3e", "/mnt/gluster-object/test/c1/o4") = 0
[pid 10276] close(7)                    = 0


GET - existing object
[pid 10245] open("/mnt/gluster-object/test/c1/o5", O_RDONLY|O_CLOEXEC) = 7
[pid 10245] fstat(7, {st_mode=S_IFREG|0755, st_size=11, ...}) = 0
[pid 10245] fgetxattr(7, "user.swift.metadata", 0x0, 0) = 190
[pid 10245] fgetxattr(7, "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1456998767.91671","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded"}", 190) = 190
[pid 10245] read(7, "hello world", 65536) = 11
[pid 10245] read(7, "", 65536)          = 0
[pid 10245] close(7)                    = 0


GET - existing object created over mount point (first time)
[pid 10245] open("/mnt/gluster-object/test/c1/f2", O_RDONLY|O_CLOEXEC) = 7
[pid 10245] fstat(7, {st_mode=S_IFREG|0644, st_size=12, ...}) = 0
[pid 10245] fgetxattr(7, "user.swift.metadata", 0x0, 0) = -1 ENODATA (No data available)
[pid 10245] fstat(7, {st_mode=S_IFREG|0644, st_size=12, ...}) = 0
[pid 10245] dup(7)                      = 8
[pid 10245] read(8, "hello world\n", 65536) = 12
[pid 10245] read(8, "", 65536)          = 0
[pid 10245] lseek(7, 0, SEEK_SET)       = 0
[pid 10245] fgetxattr(7, "user.swift.metadata", 0x0, 0) = -1 ENODATA (No data available)
[pid 10245] fsetxattr(7, "user.swift.metadata", "{"Content-Length":12,"ETag":"6f5902ac237024bdd0c176cb93063dc4","X-Timestamp":"1456999080.38636","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/octet-stream"}", 179, 0) = 0
[pid 10245] fgetxattr(7, "user.swift.metadata", 0x0, 0) = 179
[pid 10245] fgetxattr(7, "user.swift.metadata", "{"Content-Length":12,"ETag":"6f5902ac237024bdd0c176cb93063dc4","X-Timestamp":"1456999080.38636","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/octet-stream"}", 179) = 179
[pid 10245] read(7, "hello world\n", 65536) = 12
[pid 10245] read(7, "", 65536)          = 0
[pid 10245] close(7)                    = 0


curl -i http://localhost:8080/v1/AUTH_test/c1/f2 -X POST -H 'X-Object-Meta-Hello: World'
[pid 10245] open("/mnt/gluster-object/test/c1/f2", O_RDONLY|O_CLOEXEC) = 7
[pid 10245] fstat(7, {st_mode=S_IFREG|0644, st_size=12, ...}) = 0
[pid 10245] fgetxattr(7, "user.swift.metadata", 0x0, 0) = 179
[pid 10245] fgetxattr(7, "user.swift.metadata", "{"Content-Length":12,"ETag":"6f5902ac237024bdd0c176cb93063dc4","X-Timestamp":"1456999080.38636","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/octet-stream"}", 179) = 179
[pid 10245] close(7)                    = 0
[pid 10245] open("/mnt/gluster-object/test/c1/f2", O_RDONLY|O_CLOEXEC) = 7
[pid 10245] fstat(7, {st_mode=S_IFREG|0644, st_size=12, ...}) = 0
[pid 10245] fgetxattr(7, "user.swift.metadata", 0x0, 0) = 179
[pid 10245] fgetxattr(7, "user.swift.metadata", "{"Content-Length":12,"ETag":"6f5902ac237024bdd0c176cb93063dc4","X-Timestamp":"1456999080.38636","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/octet-stream"}", 179) = 179
[pid 10245] close(7)                    = 0
[pid 10245] setxattr("/mnt/gluster-object/test/c1/f2", "user.swift.metadata", "{"Content-Length":12,"ETag":"6f5902ac237024bdd0c176cb93063dc4","X-Timestamp":"1456999524.90103","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/octet-stream","X-Object-Meta-Hello":"World"}", 209, 0) = 0
Comment 3 Prashanth Pai 2016-03-10 09:09:56 UTC 
Upstream change for GET path: http://review.gluster.org/#/c/13624/

TODO: Reduce syscalls for POST path.

Will be moved to POST once both the changes are sent.
Comment 4 Prashanth Pai 2016-03-10 10:06:48 UTC 
Syscalls in POST path:

# curl -i http://localhost:8080/v1/AUTH_test/c1/a/b/c -X POST -H 'X-Object-Meta-Hello: World'

BEFORE fix

open("/mnt/gluster-object/test/c1/a/b/c", O_RDONLY|O_CLOEXEC) = 7
fstat(7, {st_mode=S_IFREG|0755, st_size=11, ...}) = 0
fgetxattr(7, "user.swift.metadata", 0x0, 0) = 220
fgetxattr(7, "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1457523994.58742","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded","X-Object-Meta-Hello":"World"}", 220) = 220
close(7)                                = 0
open("/mnt/gluster-object/test/c1/a/b/c", O_RDONLY|O_CLOEXEC) = 7
fstat(7, {st_mode=S_IFREG|0755, st_size=11, ...}) = 0
fgetxattr(7, "user.swift.metadata", 0x0, 0) = 220
fgetxattr(7, "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1457523994.58742","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded","X-Object-Meta-Hello":"World"}", 220) = 220
close(7)                                = 0
setxattr("/mnt/gluster-object/test/c1/a/b/c", "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1457604223.15336","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded","X-Object-Meta-Hello":"World"}", 220, 0) = 0

AFTER fix

[pid 24032] open("/mnt/gluster-object/test/c1/a/b/c", O_RDONLY|O_CLOEXEC) = 7
[pid 24032] fstat(7, {st_mode=S_IFREG|0755, st_size=11, ...}) = 0
[pid 24032] fgetxattr(7, "user.swift.metadata", 0x0, 0) = 190
[pid 24032] fgetxattr(7, "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1457523986.13577","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded"}", 190) = 190
[pid 24032] close(7)                    = 0
[pid 24032] setxattr("/mnt/gluster-object/test/c1/a/b/c", "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1457523994.58742","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded","X-Object-Meta-Hello":"World"}", 220, 0) = 0
Comment 5 Prashanth Pai 2016-03-10 10:59:02 UTC 
Syscalls in DELETE path when file has been modified:

root# curl -i http://localhost:8080/v1/AUTH_test/c1/o1 -X PUT -d'hello world'
root# echo "aaaaaaa" > /mnt/gluster-object/test/c1/o1
root# curl -i http://localhost:8080/v1/AUTH_test/c1/o1 -X DELETE


open("/mnt/gluster-object/test/c1/o1", O_RDONLY|O_CLOEXEC) = 7
fstat(7, {st_mode=S_IFREG|0755, st_size=8, ...}) = 0
fgetxattr(7, "user.swift.metadata", 0x0, 0) = 190
fgetxattr(7, "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1457607366.29935","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded"}", 190) = 190
dup(7)                                  = 8
read(8, "aaaaaaa\n", 65536)             = 8
read(8, "", 65536)                      = 0
lseek(7, 0, SEEK_SET)                   = 0
close(8)                                = 0
fsetxattr(7, "user.swift.metadata", "{"Content-Length":8,"ETag":"15fe514867dd5b4a1abf91ea35ff9e22","X-Object-Type":"file","X-Timestamp":"1457607368.67762","X-Type":"Object","Content-Type":"application/octet-stream"}", 178, 0) = 0
close(7)                                = 0
getxattr("/mnt/gluster-object/test/c1/o1", "user.swift.metadata", 0x0, 0) = 178
getxattr("/mnt/gluster-object/test/c1/o1", "user.swift.metadata", "{"Content-Length":8,"ETag":"15fe514867dd5b4a1abf91ea35ff9e22","X-Object-Type":"file","X-Timestamp":"1457607368.67762","X-Type":"Object","Content-Type":"application/octet-stream"}", 178) = 178
unlink("/mnt/gluster-object/test/c1/o1") = 0

Syscalls in DELETE path when file hasn't been modified:

root# curl -i http://localhost:8080/v1/AUTH_test/c1/o1 -X PUT -d'hello world'
root# curl -i http://localhost:8080/v1/AUTH_test/c1/o1 -X DELETE

open("/mnt/gluster-object/test/c1/o1", O_RDONLY|O_CLOEXEC) = 7
fstat(7, {st_mode=S_IFREG|0755, st_size=11, ...}) = 0
fgetxattr(7, "user.swift.metadata", 0x0, 0) = 190
fgetxattr(7, "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1457607434.87066","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded"}", 190) = 190
close(7)                                = 0
getxattr("/mnt/gluster-object/test/c1/o1", "user.swift.metadata", 0x0, 0) = 190
getxattr("/mnt/gluster-object/test/c1/o1", "user.swift.metadata", "{"Content-Length":"11","ETag":"5eb63bbbe01eeed093cb22bb8f5acdc3","X-Timestamp":"1457607434.87066","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded"}", 190) = 190
unlink("/mnt/gluster-object/test/c1/o1") = 0


What should really happen ?
Just a getxattr() followed by unlink()
Comment 6 Prashanth Pai 2016-03-11 12:52:37 UTC 
These changes upstream fix this BZ:

http://review.gluster.org/#/c/13624/ (MERGED)
http://review.gluster.org/#/c/13668/ (ON REVIEW)
http://review.gluster.org/#/c/13684/ (ON REVIEW)

The perf improvement from above changes is as good as it can get without having to modify swift code or change existing behaviour.
Comment 7 Mike McCune 2016-03-28 23:21:47 UTC 
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune with any questions
Comment 8 Prashanth Pai 2016-05-04 15:35:47 UTC 
Changes merged.

https://code.engineering.redhat.com/gerrit/#/q/status:merged+project:swiftonfile+branch:rhgs-3.1.3-rhel-7+topic:bug-1314171
Comment 9 surabhi 2016-05-09 14:06:31 UTC 
As discussed with Dev: Just verified the reduced syscalls for different operations.In the previous versions for each PUT,GET or DELETE operations there were multiple xattr calls but with the latest version I see only once which may improve the performance.
Following is the result:

DELETE

[pid 19074] open("/mnt/gluster-object/test/c1/o1", O_RDONLY|O_CLOEXEC) = 10
[pid 19074] fstat(10, {st_mode=S_IFREG|0755, st_size=8, ...}) = 0
[pid 19074] fgetxattr(10, "user.swift.metadata", 0x0, 0) = 178
[pid 19074] fgetxattr(10, "user.swift.metadata", "{"Content-Length":8,"ETag":"15fe514867dd5b4a1abf91ea35ff9e22","X-Object-Type":"file","X-Timestamp":"1462801876.06361","X-Type":"Object","Content-Type":"application/octet-stream"}", 178) = 178
[pid 19074] close(10)                   = 0
[pid 19074] setxattr("/mnt/gluster-object/test/c1/o1", "user.swift.metadata", "{"Content-Length":8,"ETag":"15fe514867dd5b4a1abf91ea35ff9e22","X-Timestamp":"1462802038.60981","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/octet-stream","X-Object-Meta-Hello":"World"}", 208, 0) = 0
[pid 19074] poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP}, {fd=13, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 2, 0) = 0 (Timeout)
[pid 19074] sendto(6, "HTTP/1.1 202 Accepted\r\nContent-L"..., 217, 0, NULL, 0) = 217
[pid 19074] shutdown(6, SHUT_RDWR)      = 0
[pid 19074] close(6)                    = 0
[pid 19074] poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP}, {fd=13, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 2, 60000


GET :

[pid 19074] open("/mnt/gluster-object/test/c1/o1", O_RDONLY|O_CLOEXEC) = 10
[pid 19074] fstat(10, {st_mode=S_IFREG|0755, st_size=8, ...}) = 0
[pid 19074] fgetxattr(10, "user.swift.metadata", 0x0, 0) = 208
[pid 19074] fgetxattr(10, "user.swift.metadata", "{"Content-Length":8,"ETag":"15fe514867dd5b4a1abf91ea35ff9e22","X-Timestamp":"1462802038.60981","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/octet-stream","X-Object-Meta-Hello":"World"}", 208) = 208
[pid 19074] read(10, "aaaaaaa\n", 65536) = 8
[pid 19074] poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP}, {fd=13, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 2, 0) = 0 (Timeout)
[pid 19074] read(10, "", 65536)         = 0
[pid 19074] poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP}, {fd=13, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 2, 0) = 0 (Timeout)
[pid 19074] close(10)                   = 0
[pid 19074] sendto(6, "HTTP/1.1 200 OK\r\nContent-Length:"..., 328, 0, NULL, 0) = 328
[pid 19074] shutdown(6, SHUT_RDWR)      = 0
[pid 19074] close(6)                    = 0
[pid 19074] poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP}, {fd=13, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 2, 60000

PUT:
[pid 19074] open("/mnt/gluster-object/test/c1/.o1.f6c0220ac8d34403a3928c477d5a5e96", O_WRONLY|O_CREAT|O_EXCL|O_CLOEXEC, 0777) = 10
[pid 19074] fchown(10, 4294967295, 4294967295) = 0
[pid 19074] sendto(6, "HTTP/1.1 100 Continue\r\n\r\n", 25, 0, NULL, 0) = 25
[pid 19074] recvfrom(6, 0x1e14714, 11, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 19074] poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP}, {fd=13, events=POLLIN|POLLPRI|POLLERR|POLLHUP}, {fd=6, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 3, 59998) = 1 ([{fd=6, revents=POLLIN}])
[pid 19074] recvfrom(6, "swiftonfile", 11, 0, NULL, NULL) = 11
[pid 19074] write(10, "swiftonfile", 11) = 11
[pid 19074] futex(0x7f35cc0014f0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 22808] <... futex resumed> )       = 0
[pid 19074] <... futex resumed> )       = 1
[pid 22808] futex(0x1e40c00, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 19074] futex(0x1e40c00, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 22808] <... futex resumed> )       = 0
[pid 19074] <... futex resumed> )       = 1
[pid 22808] fsetxattr(10, "user.swift.metadata", "{"Content-Length":"11","ETag":"3a77a6a87e94b5d57f21a2f52ef1c0e4","X-Timestamp":"1462802397.22017","X-Object-Type":"file","X-Type":"Object","Content-Type":"application/x-www-form-urlencoded","X-Object-Meta-Hello":"World"}", 220, 0 <unfinished

Not verified the perf part of it, will take that up in regression cycle. the reduced syscall path is verified. marking the BZ to verified.
Comment 11 errata-xmlrpc 2016-06-23 05:31:26 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://access.redhat.com/errata/RHEA-2016:1289
Note You need to log in before you can comment on or make changes to this bug.