GlusterFS FUSE getdents debugging

glusterfs-fuse-mount-strace-fulfilling-1-getdents-call.txt

[pid 16145] 1505577636.694266 writev(8, [{iov_base="`\350\1\0\0\0\0\0[\0\0\0\0\0\0\0", iov_len=16}, {iov_base="\240\271\35\354r\177\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., iov_len=125008}], 2) = 125024 <0.000856>
[pid 16149] 1505577636.695674 <... readv resumed> [{iov_base="P\0\0\0,\0\0\0\\\0\0\0\0\0\0\0\0\3\1\354r\177\0\0\0\0\0\0\0\0\0\0"..., iov_len=80}, {iov_base="", iov_len=131072}], 2) = 80 <0.028768>
[pid 16149] 1505577636.695732 gettimeofday({tv_sec=1505577636, tv_usec=695751}, NULL) = 0 <0.000005>
[pid 16149] 1505577636.696159 writev(8, [{iov_base="\300\346\1\0\0\0\0\0\\\0\0\0\0\0\0\0", iov_len=16}, {iov_base="p\261!\354r\177\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., iov_len=124592}], 2) = 124608 <0.000794>
[pid 16149] 1505577636.697149 readv(8, [{iov_base="P\0\0\0,\0\0\0]\0\0\0\0\0\0\0\0\3\1\354r\177\0\0\0\0\0\0\0\0\0\0"..., iov_len=80}, {iov_base="", iov_len=131072}], 2) = 80 <0.000009>
[pid 16149] 1505577636.697225 gettimeofday({tv_sec=1505577636, tv_usec=697243}, NULL) = 0 <0.000006>
[pid 16149] 1505577636.697287 readv(8,  <unfinished ...>
[pid 16145] 1505577636.697317 madvise(0x7f72ecae6000, 176128, MADV_DONTNEED) = 0 <0.000023>
[pid 16145] 1505577636.697637 write(10, "\27\3\3\0\34\300\321\355\31(\377q@H\24k\367\251\252\341;\31\16\303\267\314R\n\375\27\320|"..., 33) = 33 <0.000040>
[pid 16145] 1505577636.697741 write(10, "\27\3\3\0`\300\321\355\31(\377qA\226\276%\206@\263\r\t\247?\232d\01626X\254\315\246"..., 101) = 101 <0.000035>
[pid 16145] 1505577636.697852 write(10, "\27\3\3\0p\300\321\355\31(\377qB+lI\262e\32\345\217\307!\377h*\246+\341\272\6("..., 117) = 117 <0.004962>
[pid 16145] 1505577636.703173 gettimeofday({tv_sec=1505577636, tv_usec=703204}, NULL) = 0 <0.000008>
[pid 16145] 1505577636.703256 madvise(0x7f72ecae4000, 8192, MADV_DONTNEED) = 0 <0.000013>
[pid 16145] 1505577636.703739 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.004294>
[pid 16145] 1505577636.708088 read(10, "\27\3\3\0\34", 5) = 5 <0.000006>
[pid 16145] 1505577636.708107 read(10, "\337\205\"{G\6|=\370\273\324E\17dP\254p$\357\347\247\325\350M\n\216=\375", 28) = 28 <0.000005>
[pid 16145] 1505577636.708128 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000006>
[pid 16145] 1505577636.708149 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000048>
[pid 16145] 1505577636.708221 read(10, "\27\3\3\0000", 5) = 5 <0.000006>
[pid 16145] 1505577636.708238 read(10, "\337\205\"{G\6|>\365\213~7\202n\304\344~I\326\264\251\5\326Mo/\25\244\244\261\320\312"..., 48) = 48 <0.000013>
[pid 16145] 1505577636.708312 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000006>
[pid 16145] 1505577636.708333 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.708350 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000062>
[pid 16145] 1505577636.708435 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.708452 read(10, "\337\205\"{G\6|?S\366\230V\257\303\266\216\220\0\252\246-\366\312\211\210\f\16\340\202ln\344"..., 16408) = 16408 <0.000009>
[pid 16145] 1505577636.708485 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.708504 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000052>
[pid 16145] 1505577636.708578 read(10, "\27\3\3@\30", 5) = 5 <0.000013>
[pid 16145] 1505577636.708603 read(10, "\337\205\"{G\6|@N*\2558\314\222\200L6e\227\222\213\343\315\362cfL\370\233\227rt"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.708635 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.708654 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000049>
[pid 16145] 1505577636.708724 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.708741 read(10, "\337\205\"{G\6|AP\10\357;\3478\346\177S\354|\245\243\22\313n\366\376\346\211\"\201\206n"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.708771 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.708790 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000070>
[pid 16145] 1505577636.708882 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.708898 read(10, "\337\205\"{G\6|B\303\300\213\307n\304h\210\300\344\253[B4\207F\235u\225\353@\217\321\\"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.708929 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.708948 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000050>
[pid 16145] 1505577636.709020 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.709037 read(10, "\337\205\"{G\6|CH\236F\244\311\27*\273w\372i\6{\370\370\375\374\345\200\205\307Z\321\242"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.709067 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.709086 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000051>
[pid 16145] 1505577636.709158 read(10, "\27\3\3@\30", 5) = 5 <0.000005>
[pid 16145] 1505577636.709174 read(10, "\337\205\"{G\6|D\2Y>\222&J\232\17\16Cj\252\214\214\215\234\313\242GF\246\355E\362"..., 16408) = 16408 <0.000006>
[pid 16145] 1505577636.709204 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.709223 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000049>
[pid 16145] 1505577636.709292 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.709309 read(10, "\337\205\"{G\6|E\364\t2\1Q\262^\221Zt\212\211\251\213m\223~6\370RO\316\206\16"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.709339 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.709358 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000041>
[pid 16145] 1505577636.709420 read(10, "\27\3\3\2(", 5) = 5 <0.000005>
[pid 16145] 1505577636.709436 read(10, "\337\205\"{G\6|F\322\261\23\353\360\254J\252g\337M8\307U)F\1\2f\32b\276!\213"..., 552) = 552 <0.000007>
[pid 16145] 1505577636.709489 gettimeofday({tv_sec=1505577636, tv_usec=709506}, NULL) = 0 <0.000005>
[pid 16145] 1505577636.711287 write(10, "\27\3\3\0\34\300\321\355\31(\377qC\36\301\255]\226\200Y_@\5\226Q\16\322\16\n\214\270["..., 33) = 33 <0.000019>
[pid 16145] 1505577636.711371 write(10, "\27\3\3\0`\300\321\355\31(\377qD$J\363\305\200P!%r\270\2\364\224\366K\237zV\26"..., 101) = 101 <0.000013>
[pid 16145] 1505577636.711434 write(10, "\27\3\3\0p\300\321\355\31(\377qE\3465\321\361\350\335\253k\1\20\366\362\363*8u*P\352"..., 117) = 117 <0.000012>
[pid 16145] 1505577636.713853 gettimeofday({tv_sec=1505577636, tv_usec=713873}, NULL) = 0 <0.000015>
[pid 16145] 1505577636.714131 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.006843>
[pid 16145] 1505577636.721027 read(10, "\27\3\3\0\34", 5) = 5 <0.000007>
[pid 16145] 1505577636.721047 read(10, "\337\205\"{G\6|G\272\242p}\0\302\247\276\255&@\346\353O\220\314\345Y\2\303", 28) = 28 <0.000006>
[pid 16145] 1505577636.721070 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000006>
[pid 16145] 1505577636.721093 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000052>
[pid 16145] 1505577636.721167 read(10, "\27\3\3\0000", 5) = 5 <0.000006>
[pid 16145] 1505577636.721184 read(10, "\337\205\"{G\6|H\374?\267\322\253\277p\214]y\243\277\372\350.\327\223\26\212\307i\372f1"..., 48) = 48 <0.000013>
[pid 16145] 1505577636.721263 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000006>
[pid 16145] 1505577636.721283 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.721300 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000057>
[pid 16145] 1505577636.721379 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.721396 read(10, "\337\205\"{G\6|I\251\211\213\2210\2\314\271\375\312\351K~\240\310\357\25\7\201\327\r,q\201"..., 16408) = 16408 <0.000008>
[pid 16145] 1505577636.721429 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.721448 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000051>
[pid 16145] 1505577636.721520 read(10, "\27\3\3@\30", 5) = 5 <0.000013>
[pid 16145] 1505577636.721546 read(10, "\337\205\"{G\6|J\204A!\5J\200Ip\241oR#\202\323!z'\250\371\302R]3\252"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.721577 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000006>
[pid 16145] 1505577636.721596 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000049>
[pid 16145] 1505577636.721666 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.721682 read(10, "\337\205\"{G\6|K\364\342\v|;#\245B5\276r\371\356hAA\330\362\352\211\241q\257d"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.721720 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.721739 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000053>
[pid 16145] 1505577636.721828 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.721847 read(10, "\337\205\"{G\6|L\251L\263\234\36\217p_k\321\251\201[\300K:|\235\24?\265yc\202"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.721878 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.721897 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000052>
[pid 16145] 1505577636.721971 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.721988 read(10, "\337\205\"{G\6|M d\245\"\364=\306K\240\212\273\354\301\2059\232\20\217\271\367VZ\272u"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.722018 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.722037 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000051>
[pid 16145] 1505577636.722110 read(10, "\27\3\3@\30", 5) = 5 <0.000006>
[pid 16145] 1505577636.722127 read(10, "\337\205\"{G\6|N\266\222B\36\372\16mc\325\325\22\212=\255\232z\215\251!w>\244[\352"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.722157 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.722176 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000053>
[pid 16145] 1505577636.722250 read(10, "\27\3\3@\30", 5) = 5 <0.000005>
[pid 16145] 1505577636.722267 read(10, "\337\205\"{G\6|O\\\2g\322*I\t\t)\354x\2L\213\267{\311\6\204\270y8\215\307"..., 16408) = 16408 <0.000007>
[pid 16145] 1505577636.722297 read(10, 0x7f731c007d23, 5) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
[pid 16145] 1505577636.722316 poll([{fd=14, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, -1) = 1 ([{fd=10, revents=POLLIN}]) <0.000042>
[pid 16145] 1505577636.722381 read(10, "\27\3\3\2(", 5) = 5 <0.000006>
[pid 16145] 1505577636.722435 read(10, "\337\205\"{G\6|P\275\316P\362\302\225r.l5h]\206\366\315\234\351\366\20^\2025\274\243"..., 552) = 552 <0.000006>
[pid 16145] 1505577636.722538 gettimeofday({tv_sec=1505577636, tv_usec=722557}, NULL) = 0 <0.000005>
[pid 16145] 1505577636.725203 writev(8, [{iov_base="`\350\1\0\0\0\0\0]\0\0\0\0\0\0\0", iov_len=16}, {iov_base="p\2170\354r\177\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., iov_len=125008}], 2 <unfinished ...>
[pid 16149] 1505577636.726531 <... readv resumed> [{iov_base="P\0\0\0,\0\0\0^\0\0\0\0\0\0\0\0\3\1\354r\177\0\0\0\0\0\0\0\0\0\0"..., iov_len=80}, {iov_base="", iov_len=131072}], 2) = 80 <0.029200>

Analysis:

To fulfill this one getdents() between "readv resumed" and the next writev, within the 29 ms, these larger things happen:

• at .696159: a writev() takes 0.8 ms
• at .697852: the third write(): 4.9 ms, for 117 bytes, certainly blocks
• at .703739: a poll() blocks for 4.3 ms; now data is available for reading
• from .708088: some data is received in multiple read/poll calls over 1.4 ms (10 polls)
  • the polls account for 10*50us = 0.5 ms
  • after each poll there's one read() of 5 bytes and one of 16408 bytes, and one EAGAIN initiating the next poll(); the reads are super fast (5 us independent of the size), together 0.2 ms
  • that means there are 0.7 ms lost here, either syscall overhead or CPU time
• before .711287: between the last read/gettimeofday and the first write(), 1.8 ms CPU time
• at .711434: 2.4 ms CPU time
• at .714131: a poll() blocks for 6.8 ms
• from .721027: some data is received in multiple read/poll calls over 1.4 ms (10 polls); same details as before
• before .725203: 2.7 ms CPU time
• at .725203: the writev() happens, fulfilling the getdents() (FUSE "readdir") request

We have accounted for 0.8 + 4.9 + 4.3 + 1.4 + 1.8 + 2.4 + 6.8 + 1.4 + 2.7 = 26.5 ms of 29 ms.

Note strace overhead on the glusterfs FUSE process is minimal here (wall time is almost unaffected by strace being attached), unlike glusterfsd, strace-attaching to which will increase the wall time for the getdents to finish by 5x.