wacky select timeout behaviour in strace

From: Chris Friesen
Date: Thu Jun 26 2008 - 13:49:25 EST

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.


To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/