Re: fio main thread got stuck over the weekend

[Jens Axboe <axboe@kernel.dk>]

On 12/15/2014 05:52 PM, Elliott, Robert (Server Storage) wrote:
> 
> 
>> -----Original Message-----
>> From: Jens Axboe [mailto:axboe@kernel.dk]
>> Sent: Monday, 15 December, 2014 2:50 PM
>> To: Elliott, Robert (Server Storage); stephenmcameron@gmail.com
>> Cc: fio@vger.kernel.org
>> Subject: Re: fio main thread got stuck over the weekend
>>
>> On 12/15/2014 01:31 PM, Jens Axboe wrote:
>>> On 12/15/2014 01:12 PM, Jens Axboe wrote:
>>>>> (gdb) thread 212
>>>>> [Switching to thread 212 (Thread 0x7fa9a086e700 (LWP 6509))]#0
>> 0x0000003974c0b98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from
>> /lib64/libpthread.so.0
>>>>> (gdb) bt
>>>>> #0  0x0000003974c0b98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from
>> /lib64/libpthread.so.0
>>>>> #1  0x0000000000449381 in helper_thread_main (data=<value optimized
>> out>) at backend.c:2127
>>>>> #2  0x0000003974c079d1 in start_thread () from /lib64/libpthread.so.0
>>>>> #3  0x00000039748e8b7d in clone () from /lib64/libc.so.6
>>>>> (gdb) select-frame 1
>>>>> (gdb) info local
>>>>> ts = {tv_sec = 1418658662, tv_nsec = 980074000}
>>>>> tv = {tv_sec = 1418658662, tv_usec = 730074}
>>>>> ret = <value optimized out>
>>>>> (gdb) print helper_exit
>>>>> $36 = 0
>>>>> (gdb) print nr_thread
>>>>> $37 = 224
>>>>> (gdb) print nr_process
>>>>> $38 = 0
>>>>
>>>> This is the helper thread, this is what will output the ETA etc stats.
>>>> There's a signal handler that runs and sets/wakes it to do so. So it
>>>> would be interesting if you could see what it is up to, set a break
>>>> point in there and check what the control flow ends up being.
>>>>
>>>> It's backend.c:helper_thread_main()
>>>>
>>>> backend.c:sig_show_status() should repeatedly fire and end up waking
>>>> this thread.
>>>
>>> So that referred to the output status, your bug was on the ETA, correct?
> 
> Yes, the first anomaly was no ETAs incrementing, while IO was still
> occurring. 
> 
> The second anomaly was running forever.
> 
> 
>>> For that, we never get woken up by someone signaling our condvar, we
>>> just wake up every second to do the ETA display. The time conversion
>>> looks wrong, though:
>>>
>>> gettimeofday(&tv, NULL);
>>> ts.tv_sec = tv.tv_sec + sec;
>>> ts.tv_nsec = (tv.tv_usec * 1000) + nsec;
>>> if (ts.tv_nsec > 1000000000ULL) {
>>> 	ts.tv_nsec -= 1000000000ULL;
>>> 	ts.tv_sec++;
>>> }
>>>
>>> I wonder what happens if ts.tv_nsec == 10^6, that check really should be
>>> on >= instead. Not sure if this explains it though, I'll conjure up a
>>> test case...
>>
>> On my system, pthread_cond_timedwait() returns EINVAL if nsec is 10^9 or
>> higher, which is the sane thing to do. I wonder if it does that at your
>> end too, or whether it hangs? If it hangs indefinitely, that could
>> explain it. Test case attached, I checked in a fix for the off-by-one.
> 
> That program results in EINVAL here:
> will wait
> done wait 22
> 
> In backend.c helper_thread_main():
> * should the gettimeofday() return value be checked?
> * should fio_gettime() be used instead of gettimeofday() to honor
> the clocksource setting?  
> 
> In this pool of machines, I have occasionally seen time issues where
> some timeserver communication is messed up and "make" complains that
> files are newer than expected.  Maybe some time warp occurred during
> the test?  

I think I figured out what was going in, another user reported a similar
issue. Since you have it running, can you try and gdb attach to one of
the fio jobs? Then add a breakpoint in backend.c:__update_tv_cache(),
and print td->tv_cache after each call. Just do that a handful of times,
enough so we can see if it's incrementing or if it's stuck at the same
value.

-- 
Jens Axboe