Re: [PATCH] x86_64: fix delayed signals

Linus Torvalds
2008-07-11T20:38:57Z

On Fri, 11 Jul 2008, Linus Torvalds wrote:
>
> Btw, did any of the impacted people test -rc9? Edwin's report is about
> -rc2 and -rc8, and one of the things we fixed since -rc8 is that incorrect
> and unintentional nr_zones zeroing that effectively disabled kswapd - and
> made everybody do synchronous memory freeing when they wanted to allocate
> more memory.. That can play havoc with any interactive stuff.

No, after testing more, I think Edwin is right.

There _does_ seem to be something wrong in signal handling when the signal
happens during 'D' state (although I guess it could also be an artifact of
other scheduling activity). I just put my machine under heavy read load by
having a background process that does

while : ; do echo 3 > /proc/sys/vm/drop_caches ; sleep 5; done

to flush the caches all the time, and then doing endless loops of "git
grep" and other things, and I can definitely re-create the bad latency.

The best example is doing just

[torvalds@woody ~]$ ls -l /usr/bin
^Ctotal 367720
-rwxr-xr-x 1 root root 43648 2008-07-04 09:35 [
[torvalds@woody ~]$

and there are several seconds between the '^C' and the printout of the two
lines (after which the 'ls' finally dies).

Perhaps more interestingly: when this happens (it doesn't happen all the
time), it will _always_ die at the first two lines of printout for me, on
two different machines: ie I *always* get that exact pattern of those two
lines printed out (except when it reacts immediately, or when I press ^C
so late that it has printed out much more).

And it's not some single system call latency that is long. I checked with
strace, and while the IO load is high and causes the whole 'ls' to take a
long time (up to 10 seconds - /usr/bin is *big*), each individual system
call never takes very long. The longest system call latency I saw was 0.24
seconds, which was for some very unlucky lstat() calls. Most of them were
in the millisecond range, even though they obviously had to do IO.

More tellingly, those two writes are simply not even done with a single
system call. The 'strace' for an 'ls -l' shows

...
write(1, "total 367720\n", 13) = 13 <0.000085>
open("/etc/localtime", O_RDONLY) = 3 <0.000016>
fstat(3, {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 <0.000004>
fstat(3, {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 <0.000004>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6d996dd000 <0.000006>
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 2819 <0.041416>
lseek(3, -1802, SEEK_CUR) = 1017 <0.000005>
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\5\0\0\0\0"..., 4096) = 1802 <0.000006>
close(3) = 0 <0.000006>
munmap(0x7f6d996dd000, 4096) = 0 <0.000014>
write(1, "-rwxr-xr-x 1 root root 436"..., 54) = 54 <0.000008>
...

so there is actually *many* system calls in there between the header line
that does the 'total' and the first line of actual real output, but
despite that, it reacts to the ^C consistently after the second line.

Very odd.

And the problem definitely happens on x86-32 too.

It also happens on the text console, so this is not some bad interaction
with X and pty's and xterm or gnome-terminal or something like that. At
first I thought "no way can that actually happen, I think the terminal is
broken and only sends the signal after it has seen output", but no, it
happens for me in text-mode too.

Oleg added to the Cc as the master of signal handling code.

Linus