expiring tasks who are holding semaphores

[Mike Galbraith <efault@gmx.de>]

[-- Attachment #1: Type: text/plain, Size: 1472 bytes --]

Greetings Folks,

In order to explore why SCHED_RR tasks are being delayed under load on my 
box, I added some debug code to semaphores (knew it was proc for [RR] 
vmstat, but what about others?).  At the moment, normal semaphores only 
record the fact that they have been downed in the owner's task 
struct.  rw_semaphores, however,  also have some timeout code (lib/rwsem.c) 
to find out _who_ is holding the semaphore for so long.  In 
scheduler_tick(), I print out stats as to how many expires/second, along 
with the number of tasks which were expired while holding a semaphore.  See 
the attached logs... the numbers seems _awfully_ high to me, and if I 
prevent expiration of these guys, most of my SCHED_RR vmstat/top stalls 
just go away.

I'm wondering if it's worth while adding the wrappers and starvation 
timeout code to normal semaphores (hmm, what about spinlocks... we do have 
a might_sleep check which amounts to the same thing if you send any lock 
holder off to the expired land when there are interactive tasks doing round 
robin) to see if anybody starves for these.  The same random thoughts occur 
for yield() for normal tasks, though I've yet to trigger a printk there.

Anyway, logs attached in case they might be of interest.

	-Mike

P.S. logs are from 67-mm4 in case anyone looks up line numbers and 
wonders.  There are no twiddlings from yours truely other than the 
semaphore stuff... it's virgin code, no wild/crazy/stupid experiments ;-)

[-- Attachment #2: xx.txt --]
[-- Type: text/plain, Size: 5584 bytes --]

SysRq : Changing Loglevel
Loglevel set to 9
0 expires/sec, 0 with sem down.
0 expires/sec, 0 with sem down.
19 expires/sec, 9 with sem down.
9 expires/sec, 0 with sem down.
26 expires/sec, 3 with sem down.
16 expires/sec, 1 with sem down.
3 expires/sec, 1 with sem down.
16 expires/sec, 1 with sem down.
13 expires/sec, 2 with sem down.
28 expires/sec, 9 with sem down.
8 expires/sec, 1 with sem down.
9 expires/sec, 2 with sem down.
11 expires/sec, 2 with sem down.
5 expires/sec, 1 with sem down.
27 expires/sec, 5 with sem down.
15 expires/sec, 1 with sem down.
3 expires/sec, 0 with sem down.
13 expires/sec, 0 with sem down.
12 expires/sec, 2 with sem down.
301:-2 starved 1 secs by 11846:23 who last ran 1459 ticks ago.
semaphore downed at kernel/fork.c:260.
sh            D C7E84F84 11846  11845                     (NOTLB)
Call Trace:
 [<c014b8bc>] pte_chain_alloc+0x78/0x82
 [<c0107cb8>] __down+0xf4/0x1c4
 [<c011b458>] default_wake_function+0x0/0x1c
 [<c0108044>] __down_failed+0x8/0xc
 [<c011f844>] .text.lock.fork+0x11/0x5d
 [<c011eff0>] copy_process+0x67c/0xd24
 [<c011f711>] do_fork+0x79/0x164
 [<c0107728>] sys_fork+0x18/0x2c
 [<c0109183>] syscall_call+0x7/0xb

3265:-2 starved 1 secs by 11843:25 who last ran 1189 ticks ago.
semaphore downed at fs/binfmt_elf.c:264.
cc1           D C7E84F84 11843  11841         11844 11842 (NOTLB)
Call Trace:
 [<c0107cb8>] __down+0xf4/0x1c4
 [<c011b458>] default_wake_function+0x0/0x1c
 [<c0108044>] __down_failed+0x8/0xc
 [<c0148b0f>] .text.lock.mmap+0x39/0xba
 [<c0147b80>] do_mmap_pgoff+0x4a4/0x630
 [<c017ca62>] elf_map+0xb2/0xf0
 [<c017cbf3>] load_elf_interp+0x153/0x224
 [<c017d4fb>] load_elf_binary+0x717/0xa60
 [<c017cde4>] load_elf_binary+0x0/0xa60
 [<c0119715>] change_page_attr+0x6d/0xc4
 [<c016033d>] search_binary_handler+0xe5/0x2d8
 [<c01606b3>] do_execve+0x183/0x204
1 expires/sec, 0 with sem down.
 [<c01606ca>] do_execve+0x19a/0x204
 [<c01077db>] sys_execve+0x2f/0x6c
 [<c0109183>] syscall_call+0x7/0xb

15 expires/sec, 1 with sem down.
13 expires/sec, 4 with sem down.
14 expires/sec, 3 with sem down.
301:-2 starved 1 secs by 11862:25 who last ran 1910 ticks ago.
semaphore downed at arch/i386/kernel/sys_i386.c:58.
cc1           R C7FED8D4 11862  11855         11863 11861 (NOTLB)
Call Trace:
 [<c01090cd>] need_resched+0x27/0x32
 [<c013eaf9>] kmem_cache_alloc+0x81/0x158
 [<c0147a3a>] do_mmap_pgoff+0x35e/0x630
 [<c010fd1e>] old_mmap+0x122/0x170
 [<c0109183>] syscall_call+0x7/0xb

10 expires/sec, 4 with sem down.
7 expires/sec, 0 with sem down.
10 expires/sec, 3 with sem down.
8 expires/sec, 1 with sem down.
8 expires/sec, 2 with sem down.
6 expires/sec, 2 with sem down.
10 expires/sec, 3 with sem down.
9 expires/sec, 2 with sem down.
11 expires/sec, 4 with sem down.
15 expires/sec, 4 with sem down.
3265:-2 starved 1 secs by 11905:23 who last ran 1609 ticks ago.
semaphore downed at mm/mmap.c:1318.
as            R C7AB9794 11905  11902               11904 (NOTLB)
Call Trace:
 [<c014856c>] do_munmap+0x120/0x16c
 [<c011b43c>] preempt_schedule+0x2c/0x48
 [<c01485a2>] do_munmap+0x156/0x16c
 [<c0148615>] sys_munmap+0x5d/0x88
 [<c0109183>] syscall_call+0x7/0xb

301:-2 starved 1 secs by 11905:23 who last ran 1686 ticks ago.
semaphore downed at mm/mmap.c:1318.
as            R C7AB9794 11905  11902               11904 (NOTLB)
Call Trace:
 [<c014856c>] do_munmap+0x120/0x16c
 [<c011b43c>] preempt_schedule+0x2c/0x48
 [<c01485a2>] do_munmap+0x156/0x16c
 [<c0148615>] sys_munmap+0x5d/0x88
 [<c0109183>] syscall_call+0x7/0xb

12 expires/sec, 2 with sem down.
12 expires/sec, 5 with sem down.
11 expires/sec, 5 with sem down.
9 expires/sec, 3 with sem down.
11 expires/sec, 4 with sem down.
12 expires/sec, 3 with sem down.
10 expires/sec, 4 with sem down.
3265:-2 starved 1 secs by 11975:24 who last ran 1183 ticks ago.
semaphore downed at mm/mprotect.c:242.
sed           R 0000012B 11975  11973               11974 (NOTLB)
Call Trace:
 [<c011b43c>] preempt_schedule+0x2c/0x48
 [<c014739f>] move_vma_start+0x17f/0x188
 [<c01483f2>] split_vma+0x7a/0xd4
 [<c0148f8e>] mprotect_fixup+0xb2/0x178
 [<c01491d3>] sys_mprotect+0x17f/0x2d9
 [<c0109183>] syscall_call+0x7/0xb

301:-2 starved 1 secs by 11975:24 who last ran 1755 ticks ago.
semaphore downed at mm/mprotect.c:242.
sed           R 0000012B 11975  11973               11974 (NOTLB)
Call Trace:
 [<c011b43c>] preempt_schedule+0x2c/0x48
 [<c014739f>] move_vma_start+0x17f/0x188
 [<c01483f2>] split_vma+0x7a/0xd4
 [<c0148f8e>] mprotect_fixup+0xb2/0x178
 [<c01491d3>] sys_mprotect+0x17f/0x2d9
 [<c0109183>] syscall_call+0x7/0xb

8 expires/sec, 0 with sem down.
3265:-2 starved 2 secs by 11975:24 who last ran 2200 ticks ago.
semaphore downed at mm/mprotect.c:242.
sed           R 0000012B 11975  11973               11974 (NOTLB)
Call Trace:
 [<c011b43c>] preempt_schedule+0x2c/0x48
 [<c014739f>] move_vma_start+0x17f/0x188
 [<c01483f2>] split_vma+0x7a/0xd4
 [<c0148f8e>] mprotect_fixup+0xb2/0x178
 [<c01491d3>] sys_mprotect+0x17f/0x2d9
 [<c0109183>] syscall_call+0x7/0xb

301:-2 starved 2 secs by 11975:24 who last ran 2768 ticks ago.
semaphore downed at mm/mprotect.c:242.
sed           R 0000012B 11975  11973               11974 (NOTLB)
Call Trace:
 [<c011b43c>] preempt_schedule+0x2c/0x48
 [<c014739f>] move_vma_start+0x17f/0x188
 [<c01483f2>] split_vma+0x7a/0xd4
 [<c0148f8e>] mprotect_fixup+0xb2/0x178
 [<c01491d3>] sys_mprotect+0x17f/0x2d9
 [<c0109183>] syscall_call+0x7/0xb

15 expires/sec, 2 with sem down.
10 expires/sec, 4 with sem down.
4 expires/sec, 0 with sem down.
0 expires/sec, 0 with sem down.
SysRq : Changing Loglevel
Loglevel set to 0

[-- Attachment #3: yy.txt --]
[-- Type: text/plain, Size: 7999 bytes --]

SysRq : Changing Loglevel
Loglevel set to 9
0 expires/sec, 0 with sem down.
0 expires/sec, 0 with sem down.
13 expires/sec, 7 with sem down.
17 expires/sec, 2 with sem down.
13 expires/sec, 1 with sem down.
19 expires/sec, 2 with sem down.
10 expires/sec, 3 with sem down.
19 expires/sec, 3 with sem down.
4 expires/sec, 0 with sem down.
8 expires/sec, 3 with sem down.
14 expires/sec, 1 with sem down.
8 expires/sec, 3 with sem down.
28 expires/sec, 4 with sem down.
4 expires/sec, 1 with sem down.
16 expires/sec, 0 with sem down.
3 expires/sec, 2 with sem down.
16 expires/sec, 0 with sem down.
24 expires/sec, 3 with sem down.
301:-2 starved 1 secs by 9085:25 who last ran 1162 ticks ago.
semaphore downed at mm/mprotect.c:242.
gcc           R 0000012B  9085   8789                     (NOTLB)
Call Trace:
 [<c011b43c>] preempt_schedule+0x2c/0x48
 [<c014739f>] move_vma_start+0x17f/0x188
 [<c01483f2>] split_vma+0x7a/0xd4
 [<c0148f8e>] mprotect_fixup+0xb2/0x178
 [<c01491d3>] sys_mprotect+0x17f/0x2d9
 [<c0109183>] syscall_call+0x7/0xb

11 expires/sec, 1 with sem down.
3265:-2 starved 1 secs by 9085:25 who last ran 1338 ticks ago.
semaphore downed at mm/mprotect.c:242.
gcc           R 0000012B  9085   8789                     (NOTLB)
Call Trace:
 [<c011b43c>] preempt_schedule+0x2c/0x48
 [<c014739f>] move_vma_start+0x17f/0x188
 [<c01483f2>] split_vma+0x7a/0xd4
 [<c0148f8e>] mprotect_fixup+0xb2/0x178
 [<c01491d3>] sys_mprotect+0x17f/0x2d9
 [<c0109183>] syscall_call+0x7/0xb

19 expires/sec, 7 with sem down.
23 expires/sec, 8 with sem down.
27 expires/sec, 8 with sem down.
9 expires/sec, 3 with sem down.
21 expires/sec, 5 with sem down.
22 expires/sec, 8 with sem down.
9 expires/sec, 0 with sem down.
15 expires/sec, 4 with sem down.
22 expires/sec, 5 with sem down.
17 expires/sec, 3 with sem down.
11 expires/sec, 3 with sem down.
22 expires/sec, 4 with sem down.
10 expires/sec, 2 with sem down.
17 expires/sec, 2 with sem down.
6 expires/sec, 1 with sem down.
19 expires/sec, 4 with sem down.
13 expires/sec, 2 with sem down.
10 expires/sec, 3 with sem down.
16 expires/sec, 6 with sem down.
13 expires/sec, 4 with sem down.
14 expires/sec, 4 with sem down.
15 expires/sec, 4 with sem down.
13 expires/sec, 3 with sem down.
9 expires/sec, 2 with sem down.
9 expires/sec, 4 with sem down.
8 expires/sec, 5 with sem down.
6 expires/sec, 2 with sem down.
6 expires/sec, 3 with sem down.
2 expires/sec, 0 with sem down.
4 expires/sec, 4 with sem down.
4 expires/sec, 1 with sem down.
2 expires/sec, 2 with sem down.
5 expires/sec, 3 with sem down.
9 expires/sec, 2 with sem down.
9 expires/sec, 5 with sem down.
9 expires/sec, 8 with sem down.
7 expires/sec, 5 with sem down.
3 expires/sec, 3 with sem down.
11 expires/sec, 5 with sem down.
14 expires/sec, 9 with sem down.
12 expires/sec, 3 with sem down.
11 expires/sec, 2 with sem down.
9 expires/sec, 1 with sem down.
8 expires/sec, 1 with sem down.
9 expires/sec, 5 with sem down.
2 expires/sec, 0 with sem down.
1 expires/sec, 1 with sem down.
7 expires/sec, 5 with sem down.
3 expires/sec, 2 with sem down.
10 expires/sec, 10 with sem down.
3 expires/sec, 0 with sem down.
1 expires/sec, 1 with sem down.
2 expires/sec, 0 with sem down.
3 expires/sec, 2 with sem down.
3 expires/sec, 3 with sem down.
2 expires/sec, 0 with sem down.
0 expires/sec, 0 with sem down.
3 expires/sec, 3 with sem down.
4 expires/sec, 0 with sem down.
5 expires/sec, 2 with sem down.
2 expires/sec, 2 with sem down.
5 expires/sec, 5 with sem down.
6 expires/sec, 6 with sem down.
2 expires/sec, 2 with sem down.
2 expires/sec, 2 with sem down.
2 expires/sec, 2 with sem down.
6 expires/sec, 2 with sem down.
4 expires/sec, 3 with sem down.
5 expires/sec, 2 with sem down.
10 expires/sec, 7 with sem down.
10 expires/sec, 9 with sem down.
9 expires/sec, 8 with sem down.
5 expires/sec, 3 with sem down.
9 expires/sec, 6 with sem down.
15 expires/sec, 12 with sem down.
11 expires/sec, 9 with sem down.
11 expires/sec, 9 with sem down.
9 expires/sec, 7 with sem down.
9 expires/sec, 7 with sem down.
15 expires/sec, 10 with sem down.
9 expires/sec, 9 with sem down.
9 expires/sec, 7 with sem down.
15 expires/sec, 10 with sem down.
12 expires/sec, 9 with sem down.
10 expires/sec, 6 with sem down.
12 expires/sec, 8 with sem down.
13 expires/sec, 6 with sem down.
13 expires/sec, 7 with sem down.
11 expires/sec, 2 with sem down.
10 expires/sec, 6 with sem down.
5 expires/sec, 4 with sem down.
10 expires/sec, 4 with sem down.
301:-2 starved 1 secs by 10724:23 who last ran 1629 ticks ago.
semaphore downed at arch/i386/kernel/sys_i386.c:58.
cpp0          D C0E71E0C 10724  10712         10725       (NOTLB)
Call Trace:
 [<c013791e>] find_get_page+0x3a/0x88
 [<c011ca25>] io_schedule+0x29/0x38
 [<c0155c3e>] __wait_on_buffer+0xa2/0xbc
 [<c011dc18>] autoremove_wake_function+0x0/0x40
 [<c011dc18>] autoremove_wake_function+0x0/0x40
 [<c0197602>] do_get_write_access+0x72/0x788
 [<c0197d60>] journal_get_write_access+0x48/0x6c
 [<c018e890>] ext3_reserve_inode_write+0x30/0x90
 [<c018e90a>] ext3_mark_inode_dirty+0x1a/0x34
 [<c018e977>] ext3_dirty_inode+0x53/0x68
 [<c0175451>] __mark_inode_dirty+0x31/0x12c
 [<c016f2f8>] update_atime+0x88/0xc4
 [<c0138bbd>] generic_file_mmap+0x21/0x3c
 [<c0147ae9>] do_mmap_pgoff+0x40d/0x630
 [<c010fd1e>] old_mmap+0x122/0x170
 [<c0109183>] syscall_call+0x7/0xb

8 expires/sec, 3 with sem down.
7 expires/sec, 3 with sem down.
4 expires/sec, 0 with sem down.
8 expires/sec, 2 with sem down.
11 expires/sec, 9 with sem down.
3265:-2 starved 1 secs by 10727:24 who last ran 528 ticks ago.
semaphore downed at fs/binfmt_elf.c:264.
touch         R C6D8C000 10727  10543                     (NOTLB)
Call Trace:
 [<c0155b3f>] wake_up_buffer+0xb/0x28
 [<c0197965>] do_get_write_access+0x3d5/0x788
 [<c011b458>] default_wake_function+0x0/0x1c
 [<c0197d60>] journal_get_write_access+0x48/0x6c
 [<c018e890>] ext3_reserve_inode_write+0x30/0x90
 [<c018e90a>] ext3_mark_inode_dirty+0x1a/0x34
 [<c018e977>] ext3_dirty_inode+0x53/0x68
 [<c0175451>] __mark_inode_dirty+0x31/0x12c
 [<c016f2f8>] update_atime+0x88/0xc4
 [<c0138bbd>] generic_file_mmap+0x21/0x3c
 [<c0147ae9>] do_mmap_pgoff+0x40d/0x630
 [<c017ca62>] elf_map+0xb2/0xf0
 [<c017d3c9>] load_elf_binary+0x5e5/0xa60
 [<c017cde4>] load_elf_binary+0x0/0xa60
 [<c010f766>] timer_interrupt+0xba/0x1a8
 [<c016033d>] search_binary_handler+0xe5/0x2d8
 [<c01606b3>] do_execve+0x183/0x204
 [<c01606ca>] do_execve+0x19a/0x204
 [<c01077db>] sys_execve+0x2f/0x6c
 [<c0109183>] syscall_call+0x7/0xb

4 expires/sec, 4 with sem down.
301:-2 starved 1 secs by 10727:24 who last ran 244 ticks ago.
semaphore downed at fs/binfmt_elf.c:264.
touch         D C7EEF178 10727  10543                     (NOTLB)
Call Trace:
 [<c013791e>] find_get_page+0x3a/0x88
 [<c01573dc>] bh_lru_install+0xe4/0xf0
 [<c0107cb8>] __down+0xf4/0x1c4
 [<c011b458>] default_wake_function+0x0/0x1c
 [<c0108044>] __down_failed+0x8/0xc
 [<c01998f6>] .text.lock.transaction+0xb9/0x173
 [<c011b458>] default_wake_function+0x0/0x1c
 [<c0197d60>] journal_get_write_access+0x48/0x6c
 [<c018e890>] ext3_reserve_inode_write+0x30/0x90
 [<c018e90a>] ext3_mark_inode_dirty+0x1a/0x34
 [<c018e977>] ext3_dirty_inode+0x53/0x68
 [<c0175451>] __mark_inode_dirty+0x31/0x12c
 [<c016f2f8>] update_atime+0x88/0xc4
 [<c0138bbd>] generic_file_mmap+0x21/0x3c
 [<c0147ae9>] do_mmap_pgoff+0x40d/0x630
 [<c017ca62>] elf_map+0xb2/0xf0
 [<c017d3c9>] load_elf_binary+0x5e5/0xa60
 [<c017cde4>] load_elf_binary+0x0/0xa60
 [<c010f766>] timer_interrupt+0xba/0x1a8
 [<c016033d>] search_binary_handler+0xe5/0x2d8
 [<c01606b3>] do_execve+0x183/0x204
 [<c01606ca>] do_execve+0x19a/0x204
 [<c01077db>] sys_execve+0x2f/0x6c
 [<c0109183>] syscall_call+0x7/0xb

11 expires/sec, 11 with sem down.
6 expires/sec, 6 with sem down.
7 expires/sec, 7 with sem down.
6 expires/sec, 6 with sem down.
4 expires/sec, 4 with sem down.
11 expires/sec, 10 with sem down.
0 expires/sec, 0 with sem down.
0 expires/sec, 0 with sem down.
SysRq : Changing Loglevel
Loglevel set to 0