G
ghostwhoowalks
Hi All
I see 52 ms being spent in calls to readFully() method of the
RandomAccessFile. I ran strace against my process and figured that
these weren't reads going to disk. All reads were being served from
the buffer cache (verified by running iostat). It also looks like the
52 ms is a futex timeout but strace doesn't report which system call
causes this. I was wondering if anyone has seen this problem before
and how do I go about addressing this? Do I have access to the source
code of the native library used by RandomAccessFile? Here is the
output from strace (the offending line is in bold):
29673 16:36:47.747658
futex(0x2aac3f62a674, FUTEX_WAIT, 1, {0, 49972000} <unfinished
....>
29716 16:36:47.784379 <... futex
resumed> ) = -1 ETIMEDOUT (Connection timed out)
<0.044427>
29716 16:36:47.784469
futex(0x2aac3f66e328, FUTEX_WAKE, 1) = 0
<0.000012>
29716 16:36:47.784548
clock_gettime(CLOCK_REALTIME, {1197938207, 784565000}) = 0
<0.000012>
29716 16:36:47.784610
futex(0x2aac3f670314, FUTEX_WAIT, 1, {0, 19970000} <unfinished
....>
29673 16:36:47.799354 <... futex
resumed> ) = -1 ETIMEDOUT (Connection timed out)
<0.051676>
29673 16:36:47.799392
futex(0x2aac3f2a7228, FUTEX_WAKE, 1) = 0
<0.000011>
29673 16:36:47.799434
clock_gettime(CLOCK_MONOTONIC, {6497274, 522227024}) = 0
<0.000007>
29673 16:36:47.799481
clock_gettime(CLOCK_MONOTONIC, {6497274, 522275024}) = 0
<0.000007>
Thanks
Avinash
I see 52 ms being spent in calls to readFully() method of the
RandomAccessFile. I ran strace against my process and figured that
these weren't reads going to disk. All reads were being served from
the buffer cache (verified by running iostat). It also looks like the
52 ms is a futex timeout but strace doesn't report which system call
causes this. I was wondering if anyone has seen this problem before
and how do I go about addressing this? Do I have access to the source
code of the native library used by RandomAccessFile? Here is the
output from strace (the offending line is in bold):
29673 16:36:47.747658
futex(0x2aac3f62a674, FUTEX_WAIT, 1, {0, 49972000} <unfinished
....>
29716 16:36:47.784379 <... futex
resumed> ) = -1 ETIMEDOUT (Connection timed out)
<0.044427>
29716 16:36:47.784469
futex(0x2aac3f66e328, FUTEX_WAKE, 1) = 0
<0.000012>
29716 16:36:47.784548
clock_gettime(CLOCK_REALTIME, {1197938207, 784565000}) = 0
<0.000012>
29716 16:36:47.784610
futex(0x2aac3f670314, FUTEX_WAIT, 1, {0, 19970000} <unfinished
....>
29673 16:36:47.799354 <... futex
resumed> ) = -1 ETIMEDOUT (Connection timed out)
<0.051676>
29673 16:36:47.799392
futex(0x2aac3f2a7228, FUTEX_WAKE, 1) = 0
<0.000011>
29673 16:36:47.799434
clock_gettime(CLOCK_MONOTONIC, {6497274, 522227024}) = 0
<0.000007>
29673 16:36:47.799481
clock_gettime(CLOCK_MONOTONIC, {6497274, 522275024}) = 0
<0.000007>
Thanks
Avinash