Re: Busy-wait delay in qmail 1.03 after upgrading to Linux 2.6

[Andrew Morton <akpm@osdl.org>]

Haakon Riiser <haakon.riiser@fys.uio.no> wrote:
>
> The entire output from strace is available for download from
> <http://home.chello.no/~hakonrk/2.6.1.strace.out>, but I think
> only this line is interesting:
> 
>   5083  16:00:30.714309 write(5, "\0", 1) = 1 <1.637019>
> 
> This the only write() to file descriptor 5 issued by qmail-queue,
> right before it exists, and this is what causes the delay.
> Notice that writing this single NUL-byte takes almost 1.64 seconds
> (the number in the angle brackets at the end of the line is the
> time spent in the system call, given by the -T flag to strace).
> Furthermore, the kernel appears to be busy-waiting in this system
> call, because the CPU usage quickly jumps to 100%.

Odd.

5083  16:00:30.714217 open("lock/trigger", O_WRONLY|O_NONBLOCK) = 5 <0.000013>
5083  16:00:30.714260 fcntl64(5, F_GETFL) = 0x801 (flags O_WRONLY|O_NONBLOCK) <0.000004>
5083  16:00:30.714287 fcntl64(5, F_SETFL, O_WRONLY|O_NONBLOCK) = 0 <0.000004>
5083  16:00:30.714309 write(5, "\0", 1) = 1 <1.637019>
5083  16:00:32.351378 close(5)          = 0 <0.000005>

Seems innocuous.  What filesystem type is lock/trigger on?

Can you generate a kernel profile of this activity?

Boot with `profile=1', copy this:

SM=/boot/System.map
TIMEFILE=/tmp/prof.time
sudo readprofile -r
sudo readprofile -M10
time $@
readprofile -n -v -m $SM | sort -n +2 | tail -40 | tee $TIMEFILE >&2

into /tmp/foo and do

	/tmp/foo whatever-command-you-were-using

Thanks.