wacky select timeout behaviour in strace

wacky select timeout behaviour in strace

[Chris Friesen]

I've got something odd in a couple of recent strace logs (running on an 
older kernel, I haven't yet tried to reproduce in mainline).

First case:

20418 22:06:50.583303 select(19, [7 11 12 13 14 15 16 17 18], NULL, 
NULL, {0, 498508}) = 1 (in [11], left {0, 0}) <5.074137>

select() was called with a timeout of half a second.  Five seconds later 
it returns with zero time left and a single socket readable.  Why 
wouldn't it have returned after half a second with a timeout?



Second case:

18383 01:46:23.572951 select(16, [15], NULL, NULL, {1, 0}) = 1 (in [15], 
left {0, 732000}) <1.337443>

Here we call select with a timeout of 1 sec, then 1.3337 sec later we 
return saying that we have 732ms left to sleep.

In addition, there was an interval timer set up to fire every 500ms, and 
it didn't interrupt the select call.  It did fire 60ms after the select 
call returned.  Interestingly, the timing of that firing (x.97 sec) 
didn't match the normal times (x.07 and x.57), but it then returned to 
the normal times after the single abnormal firing.

Anyone have any ideas what's going on?  This doesn't appear to be an 
strace artifact, as I can reproduce it without tracing the process in 
question.  It also doesn't appear to be a system-wide artifact as I know 
from instrumentation that other tasks are running during this interval.

Thanks,

Chris