Re: [Fwd: Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.4]
From: Lee Revell
Date: Fri Oct 29 2004 - 22:39:45 EST
On Sat, 2004-10-30 at 00:31 +0200, Florian Schmidt wrote:
> On Fri, 29 Oct 2004 23:25:45 +0200
> Ingo Molnar <mingo@xxxxxxx> wrote:
>
> > > will do so. btw: i think i'm a bit confused right now. What debugging
> > > features should i have enabled for this test?
> >
> > this particular one (atomicity-checking) is always-enabled if you have
> > the -RT patch applied (it's a really cheap check).
> >
> > for the 'application-triggered tracing' facility we talked about earlier
> > is only active if LATENCY_TRACING is enabled. In that case to turn the
> > tracer on, call:
> [snip]
>
> Ok,
>
> .config attached,
>
> running the patched jackd -R -P 60 -d alsa -p64 for a bit and provoking
> xruns via window wiggling :)
>
Ingo, here are some of my traces with the same settings. These do seem
to correspond to the xruns. Many of them look tty related - could the
recent changes to the tty layer be responsible? Possibly this has
nothing to do with RT preempt, but is an unrelated bug in -mm? The
xruns do seem to correspond to display activity such as switching tabs
in gnome-terminal.
jackd:1507 userspace BUG: scheduling in user-atomic context!
[<c01069fc>] dump_stack+0x1c/0x20 (20)
[<c02834d0>] schedule+0x70/0x100 (24)
[<c010639b>] work_resched+0x6/0x17 (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c012e5d3>] .... print_traces+0x13/0x50
.....[<c01069fc>] .. ( <= dump_stack+0x1c/0x20)
jackd:1507 userspace BUG: scheduling in user-atomic context!
[<c01069fc>] dump_stack+0x1c/0x20 (20)
[<c02834d0>] schedule+0x70/0x100 (24)
[<c028465d>] down_write_mutex+0xbd/0x180 (36)
[<c012cbf6>] __mutex_lock+0x36/0x40 (16)
[<c012cc75>] _mutex_lock_irqsave+0x15/0x20 (16)
[<c01f1237>] tty_ldisc_try+0x17/0x50 (20)
[<c01f1287>] tty_ldisc_ref_wait+0x17/0xc0 (88)
[<c01f21fd>] tty_write+0x7d/0x230 (68)
[<c01546ac>] vfs_write+0xbc/0x110 (36)
[<c01547b1>] sys_write+0x41/0x70 (44)
[<c0106367>] syscall_call+0x7/0xb (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c012e5d3>] .... print_traces+0x13/0x50
.....[<c01069fc>] .. ( <= dump_stack+0x1c/0x20)
jackd:1507 userspace BUG: scheduling in user-atomic context!
[<c01069fc>] dump_stack+0x1c/0x20 (20)
[<c02834d0>] schedule+0x70/0x100 (24)
[<c010639b>] work_resched+0x6/0x17 (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c012e5d3>] .... print_traces+0x13/0x50
.....[<c01069fc>] .. ( <= dump_stack+0x1c/0x20)
jackd:1507 userspace BUG: scheduling in user-atomic context!
[<c01069fc>] dump_stack+0x1c/0x20 (20)
[<c02834d0>] schedule+0x70/0x100 (24)
[<c028465d>] down_write_mutex+0xbd/0x180 (36)
[<c012cbf6>] __mutex_lock+0x36/0x40 (16)
[<c012cc75>] _mutex_lock_irqsave+0x15/0x20 (16)
[<c01f1237>] tty_ldisc_try+0x17/0x50 (20)
[<c01f1287>] tty_ldisc_ref_wait+0x17/0xc0 (88)
[<c01f21fd>] tty_write+0x7d/0x230 (68)
[<c01546ac>] vfs_write+0xbc/0x110 (36)
[<c01547b1>] sys_write+0x41/0x70 (44)
[<c0106367>] syscall_call+0x7/0xb (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c012e5d3>] .... print_traces+0x13/0x50
.....[<c01069fc>] .. ( <= dump_stack+0x1c/0x20)
jackd:1507 userspace BUG: scheduling in user-atomic context!
[<c01069fc>] dump_stack+0x1c/0x20 (20)
[<c02834d0>] schedule+0x70/0x100 (24)
[<c028449c>] _down_write+0xcc/0x170 (32)
[<c01131d3>] lock_kernel+0x23/0x30 (16)
[<c01f22f0>] tty_write+0x170/0x230 (64)
[<c01546ac>] vfs_write+0xbc/0x110 (36)
[<c01547b1>] sys_write+0x41/0x70 (44)
[<c0106367>] syscall_call+0x7/0xb (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c012e5d3>] .... print_traces+0x13/0x50
.....[<c01069fc>] .. ( <= dump_stack+0x1c/0x20)
jackd:1507 userspace BUG: scheduling in user-atomic context!
[<c01069fc>] dump_stack+0x1c/0x20 (20)
[<c02834d0>] schedule+0x70/0x100 (24)
[<c0119cba>] do_exit+0x29a/0x500 (24)
[<c0119f56>] sys_exit+0x16/0x20 (12)
[<c0106367>] syscall_call+0x7/0xb (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c012e5d3>] .... print_traces+0x13/0x50
.....[<c01069fc>] .. ( <= dump_stack+0x1c/0x20)
However the longest latency recorded during all these xruns is 40-150 usecs:
preemption latency trace v1.0.7 on 2.6.9-mm1-RT-V0.5.14
-------------------------------------------------------
latency: 48 us, entries: 26 (26) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1]
-----------------
| task: jackd/1629, uid:1000 nice:0 policy:1 rt_prio:10
-----------------
=> started at: try_to_wake_up+0x4c/0x100 <c01126ec>
=> ended at: finish_task_switch+0x27/0xb0 <c0112b77>
=======>
1101 80000000 0.000ms (+0.000ms): (89) ((116))
1101 80000000 0.000ms (+0.000ms): (1629) ((1101))
1101 80000000 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up)
1101 80000000 0.001ms (+0.000ms): preempt_schedule (__up_write)
1101 00000000 0.001ms (+0.000ms): preempt_schedule (up_write_mutex)
1101 80000000 0.002ms (+0.000ms): __schedule (preempt_schedule)
1101 80000000 0.002ms (+0.000ms): profile_hit (__schedule)
1101 80000000 0.003ms (+0.002ms): sched_clock (__schedule)
1629 80000000 0.005ms (+0.000ms): __switch_to (__schedule)
1629 80000000 0.006ms (+0.000ms): (1101) ((1629))
1629 80000000 0.006ms (+0.000ms): (116) ((89))
1629 80000000 0.006ms (+0.000ms): finish_task_switch (__schedule)
1629 80000000 0.007ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
1629 80000000 0.007ms (+0.002ms): (1629) ((89))
1629 00000000 0.010ms (+0.000ms): bad_range (free_pages_bulk)
1629 00000000 0.010ms (+0.000ms): bad_range (free_pages_bulk)
1629 00000000 0.011ms (+0.000ms): _mutex_unlock_irqrestore (free_pages_bulk)
1629 00000000 0.011ms (+0.000ms): up_mutex (free_pages_bulk)
1629 00000000 0.011ms (+0.000ms): up_write_mutex (free_pages_bulk)
1629 00000000 0.012ms (+0.004ms): __up_write (up_write_mutex)
1629 00000000 0.016ms (+0.000ms): sys_gettimeofday (syscall_call)
1629 00000000 0.016ms (+0.000ms): user_trace_stop (sys_gettimeofday)
1629 80000000 0.017ms (+0.000ms): user_trace_stop (sys_gettimeofday)
1629 80000000 0.017ms (+0.000ms): update_max_trace (user_trace_stop)
1629 80000000 0.018ms (+0.000ms): _mmx_memcpy (update_max_trace)
1629 80000000 0.018ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)
We know that jackd prints from the realtime thread, and that in theory
this could be a problem, in practice it works OK. Maybe some recent
changes to the tty layer made this problematic.
I think there was a patch posted to the JACK mailing list to print from
a separate thread, I will look into this.
Lee
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/