lkml.org 
[lkml]   [2003]   [Apr]   [24]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    Subjectexpiring tasks who are holding semaphores
    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 ;-)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
    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
    \
     
     \ /
      Last update: 2005-03-22 13:34    [W:7.373 / U:0.964 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site