lkml.org 
[lkml]   [2004]   [Oct]   [29]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: [Fwd: Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.4]
    On Sat, 30 Oct 2004 00:31:22 +0200
    Florian Schmidt <mista.tapas@gmx.net> wrote:

    > Ok,
    >
    > .config attached,

    now it is :)

    > Oct 30 00:28:29 mango kernel: (IRQ 3/118/CPU#0): new 205 us maximum-latency wakeup.

    i could as well include this one

    preemption latency trace v1.0.7 on 2.6.9-mm1-RT-V0.5.14-rt
    -------------------------------------------------------
    latency: 205 us, entries: 36 (36) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: jackd/1083, uid:1000 nice:0 policy:1 rt_prio:60
    -----------------
    => started at: try_to_wake_up+0x5a/0x110 <c01151ca>
    => ended at: finish_task_switch+0x31/0xc0 <c0115691>
    =======>
    768 80000000 0.000ms (+0.000ms): (39) ((115))
    768 80000000 0.000ms (+0.000ms): (1083) ((768))
    768 80000000 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up)
    768 80000000 0.000ms (+0.000ms): preempt_schedule (__up_write)
    768 00000000 0.000ms (+0.000ms): preempt_schedule (up_write_mutex)
    768 80000000 0.000ms (+0.000ms): __schedule (preempt_schedule)
    768 80000000 0.000ms (+0.000ms): profile_hit (__schedule)
    768 80000000 0.000ms (+0.000ms): sched_clock (__schedule)
    1083 80000000 0.001ms (+0.000ms): __switch_to (__schedule)
    1083 80000000 0.002ms (+0.000ms): (768) ((1083))
    1083 80000000 0.002ms (+0.000ms): (115) ((39))
    1083 80000000 0.002ms (+0.000ms): finish_task_switch (__schedule)
    1083 80000000 0.002ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
    1083 80000000 0.002ms (+0.000ms): (1083) ((39))
    1083 00000000 0.003ms (+0.000ms): bad_range (free_pages_bulk)
    1083 00000000 0.003ms (+0.000ms): bad_range (free_pages_bulk)
    1083 00000000 0.003ms (+0.000ms): _mutex_unlock_irqrestore (free_pages_bulk)
    1083 00000000 0.003ms (+0.000ms): up_mutex (free_pages_bulk)
    1083 00000000 0.003ms (+0.000ms): up_write_mutex (free_pages_bulk)
    1083 00000000 0.003ms (+0.000ms): __up_write (up_write_mutex)
    1083 80000000 0.004ms (+0.000ms): wake_up_process_mutex (__up_write)
    1083 80000000 0.004ms (+0.000ms): try_to_wake_up (wake_up_process_mutex)
    1083 80000000 0.004ms (+0.000ms): task_rq_lock (try_to_wake_up)
    1083 80000000 0.004ms (+0.000ms): activate_task (try_to_wake_up)
    1083 80000000 0.004ms (+0.000ms): sched_clock (activate_task)
    1083 80000000 0.004ms (+0.000ms): recalc_task_prio (activate_task)
    1083 80000000 0.004ms (+0.000ms): effective_prio (recalc_task_prio)
    1083 80000000 0.005ms (+0.000ms): enqueue_task (activate_task)
    1083 80000000 0.005ms (+0.000ms): (115) ((39))
    1083 80000000 0.005ms (+0.004ms): (834) ((1083))
    1083 00000000 0.010ms (+0.000ms): sys_gettimeofday (syscall_call)
    1083 00000000 0.010ms (+0.000ms): user_trace_stop (sys_gettimeofday)
    1083 80000000 0.010ms (+0.000ms): user_trace_stop (sys_gettimeofday)
    1083 80000000 0.010ms (+0.000ms): update_max_trace (user_trace_stop)
    1083 80000000 0.011ms (+0.000ms): _mmx_memcpy (update_max_trace)
    1083 80000000 0.011ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)


    and another one:

    preemption latency trace v1.0.7 on 2.6.9-mm1-RT-V0.5.14-rt
    -------------------------------------------------------
    latency: 225 us, entries: 36 (36) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: jackd/1083, uid:1000 nice:0 policy:1 rt_prio:60
    -----------------
    => started at: try_to_wake_up+0x5a/0x110 <c01151ca>
    => ended at: finish_task_switch+0x31/0xc0 <c0115691>
    =======>
    637 80000000 0.000ms (+0.000ms): (39) ((116))
    637 80000000 0.000ms (+0.000ms): (1083) ((637))
    637 80000000 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up)
    637 80000000 0.000ms (+0.000ms): preempt_schedule (__up_write)
    637 00000000 0.000ms (+0.000ms): preempt_schedule (up_write_mutex)
    637 80000000 0.000ms (+0.000ms): __schedule (preempt_schedule)
    637 80000000 0.000ms (+0.000ms): profile_hit (__schedule)
    637 80000000 0.000ms (+0.001ms): sched_clock (__schedule)
    1083 80000000 0.002ms (+0.000ms): __switch_to (__schedule)
    1083 80000000 0.002ms (+0.000ms): (637) ((1083))
    1083 80000000 0.002ms (+0.000ms): (116) ((39))
    1083 80000000 0.002ms (+0.000ms): finish_task_switch (__schedule)
    1083 80000000 0.002ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
    1083 80000000 0.002ms (+0.000ms): (1083) ((39))
    1083 00000000 0.003ms (+0.000ms): bad_range (free_pages_bulk)
    1083 00000000 0.003ms (+0.000ms): bad_range (free_pages_bulk)
    1083 00000000 0.003ms (+0.000ms): _mutex_unlock_irqrestore (free_pages_bulk)
    1083 00000000 0.003ms (+0.000ms): up_mutex (free_pages_bulk)
    1083 00000000 0.004ms (+0.000ms): up_write_mutex (free_pages_bulk)
    1083 00000000 0.004ms (+0.000ms): __up_write (up_write_mutex)
    1083 80000000 0.004ms (+0.000ms): wake_up_process_mutex (__up_write)
    1083 80000000 0.004ms (+0.000ms): try_to_wake_up (wake_up_process_mutex)
    1083 80000000 0.004ms (+0.000ms): task_rq_lock (try_to_wake_up)
    1083 80000000 0.004ms (+0.000ms): activate_task (try_to_wake_up)
    1083 80000000 0.004ms (+0.000ms): sched_clock (activate_task)
    1083 80000000 0.004ms (+0.000ms): recalc_task_prio (activate_task)
    1083 80000000 0.004ms (+0.000ms): effective_prio (recalc_task_prio)
    1083 80000000 0.004ms (+0.000ms): enqueue_task (activate_task)
    1083 80000000 0.005ms (+0.000ms): (115) ((39))
    1083 80000000 0.005ms (+0.006ms): (782) ((1083))
    1083 00000000 0.011ms (+0.000ms): sys_gettimeofday (syscall_call)
    1083 00000000 0.011ms (+0.000ms): user_trace_stop (sys_gettimeofday)
    1083 80000000 0.012ms (+0.000ms): user_trace_stop (sys_gettimeofday)
    1083 80000000 0.012ms (+0.000ms): update_max_trace (user_trace_stop)
    1083 80000000 0.012ms (+0.000ms): _mmx_memcpy (update_max_trace)
    1083 80000000 0.013ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)


    Oct 30 00:48:45 mango kernel: (IRQ 3/118/CPU#0): new 225 us maximum-latency wakeup.
    Oct 30 00:49:15 mango kernel: jackd:1083 userspace BUG: scheduling in user-atomic context!
    Oct 30 00:49:15 mango kernel: [show_registers+99/464] dump_stack+0x23/0x30 (20)
    Oct 30 00:49:15 mango kernel: [kernel_config_data+2090/6569] schedule+0x7a/0x120 (36)
    Oct 30 00:49:15 mango kernel: [Bad_offset+13/23] down_write_mutex+0xc2/0x1a0 (48)
    Oct 30 00:49:15 mango kernel: [do_posix_clock_monotonic_gettime_parts+83/96] __mutex_lock+0x43/0x50 (24)
    Oct 30 00:49:15 mango kernel: [do_posix_clock_nonanosleep+13/16] _mutex_lock_irqsave+0x1d/0x30 (16)
    Oct 30 00:49:15 mango kernel: [stop_tty+2/144] tty_ldisc_try+0x22/0x60 (24)
    Oct 30 00:49:15 mango kernel: [stop_tty+88/144] tty_ldisc_ref_wait+0x18/0xb0 (84)
    Oct 30 00:49:15 mango kernel: [release_dev+865/1984] tty_write+0x91/0x230 (80)
    Oct 30 00:49:15 mango kernel: [sys_llseek+90/176] vfs_write+0xca/0x140 (44)
    Oct 30 00:49:15 mango kernel: [vfs_read+16/320] sys_write+0x50/0x80 (44)
    Oct 30 00:49:15 mango kernel: [irq_entries_start+3/128] syscall_call+0x7/0xb (-8124)
    Oct 30 00:49:15 mango kernel: ---------------------------
    Oct 30 00:49:15 mango kernel: | preempt count: 00000001 ]
    Oct 30 00:49:15 mango kernel: | 1-level deep critical section nesting:
    Oct 30 00:49:15 mango kernel: ----------------------------------------
    Oct 30 00:49:15 mango kernel: .. [l_show+173/272] .... print_traces+0x1d/0x90
    Oct 30 00:49:15 mango kernel: .....[show_registers+99/464] .. ( <= dump_stack+0x23/0x30)
    Oct 30 00:49:15 mango kernel:
    [unhandled content-type:application/octet-stream]
    \
     
     \ /
      Last update: 2005-03-22 14:07    [W:4.068 / U:0.052 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site