I wrote:
> I vaguely remember that we had exactly the same problem (hangs when
> using sequencer on RT kernel) some time ago, and that it was somehow
> related to tasklets.

http://lkml.org/lkml/2006/3/7/256
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

On Fri, 2008-11-07 at 10:12 +0100, Clemens Ladisch wrote:
> Fernando Lopez-Lezcano wrote:
> > I'm seeing a realtime patch related hard hang in the kernel alsa
> > subsystem (MIDI input/output). In a nutshell:
> >
> > - alsa rawmidi works (ie: "rawmidi -v -i hw:0" outputs a stream of
> > messages when pointed to a midi capable card that has an external
> > keyboard connected).
> >
> > - the alsa sequencer interface works (ie: aplaymidi connected to
> > aseqdump transfers data just fine).
> >
> > - BOTH combined do NOT work (ie: use aconnect to connect the port that
> > corresponds to the external midi interface to aseqdump: aseqdump hangs
> > forever after transferring the first message and the only way out is a
> > reboot).
>
> Please try the snd-virmidi driver, then we'd have a test case that does
> not require MIDI hardware.
>
> > ... including the output of a "echo t >/proc/sysrq-trigger" that
> > should show where aseqdump currently hangs (or so I think).
>
> It hangs in tasklet_kill(), which gets called while it tries to close
> the rawmidi port.
>
> The rawmidi framework uses this tasklet to notify the sequencer that new
> MIDI data is available. The handler function is
> snd_rawmidi_input_event_tasklet() in sound/core/rawmidi.c; the sequencer
> callback that gets called from there is snd_midi_input_event() in
> core/seq/seq_midi.c.
>
> You say that the first event gets delivered, so it might be possible
> that the tasklet never finishes executing. Please check whether the
> call to snd_seq_kernel_client_dispatch() in snd_midi_input_event()
> ever returns.

I added a printk before and after the call, it looks like it gets called
and it returns (but only _once_... aseqdump hangs in an unkillable state
as before).

But the hang is different, I'll reboot and retry to see if it is
repeatable:

--------
Nov 7 10:05:36 host kernel: =======================
Nov 7 10:05:36 host kernel: aseqdump S [f2e5c330] f78df0f0 0
5256 5185
Nov 7 10:05:36 host kernel: f2cffbd4 00000086 f2cffb88 f78df0f0
00000003 f2e5c330 f2e5c5c4 c4847700
Nov 7 10:05:36 host kernel: 00000001 c4847700 ef1ba352 0000002c
c4844054 00000000 fffe5e91 00000246
Nov 7 10:05:36 host kernel: f57fc274 00000000 00000000 00000000
ffffffff 00000000 7fffffff f2cffe98
Nov 7 10:05:36 host kernel: Call Trace:
Nov 7 10:05:36 host kernel: [] schedule+0xbf/0xd8
Nov 7 10:05:36 host kernel: [] schedule_timeout+0x17/0xbc
Nov 7 10:05:36 host kernel: [] ? __pollwait+0xad/0xb6
Nov 7 10:05:36 host kernel: [] ? snd_seq_fifo_poll_wait
+0x18/0x25 [snd_seq]
Nov 7 10:05:36 host kernel: [] ? snd_seq_poll+0x4d/0x9f
[snd_seq]
Nov 7 10:05:36 host kernel: [] do_sys_poll+0x292/0x348
Nov 7 10:05:36 host kernel: [] ? __pollwait+0x0/0xb6
Nov 7 10:05:36 host kernel: [] ? default_wake_function
+0x0/0x12
Nov 7 10:05:36 host kernel: [] ? rt_spin_lock+0x38/0x3b
Nov 7 10:05:36 host kernel: [] ? page_address+0x88/0xaa
Nov 7 10:05:36 host kernel: [] ? kmap_high+0x421/0x42a
Nov 7 10:05:36 host kernel: [] ? radix_valid_always+0x0/0xa
Nov 7 10:05:36 host kernel: [] ? __rcu_read_unlock+0x6d/0x72
Nov 7 10:05:36 host kernel: [] ? find_get_page+0xfa/0x120
Nov 7 10:05:36 host kernel: [] ? __rt_spin_lock+0x24/0x61
Nov 7 10:05:36 host kernel: [] ? rt_spin_lock+0x38/0x3b
Nov 7 10:05:36 host kernel: [] ? __enqueue_entity+0xe3/0xeb
Nov 7 10:05:36 host kernel: [] ? task_rq_lock+0x44/0x6e
Nov 7 10:05:36 host kernel: [] ? try_to_wake_up+0x212/0x21d
Nov 7 10:05:36 host kernel: [] ? default_wake_function
+0x10/0x12
Nov 7 10:05:36 host kernel: [] ? __wake_up_common+0x35/0x5b
Nov 7 10:05:36 host kernel: [] ? __wake_up+0x28/0x32
Nov 7 10:05:36 host kernel: [] ? n_tty_receive_buf
+0xfa9/0xff7
Nov 7 10:05:36 host kernel: [] ? n_tty_receive_buf
+0xfa9/0xff7
Nov 7 10:05:36 host kernel: [] ? rt_mutex_up_read+0x1b7/0x25d
Nov 7 10:05:36 host kernel: [] ? rt_up_read+0x8/0xa
Nov 7 10:05:36 host kernel: [] ? do_page_fault+0x45f/0x7d8
Nov 7 10:05:36 host kernel: [] ? copy_to_user+0x36/0x106
Nov 7 10:05:36 host kernel: [] ? rt_spin_lock_slowlock
+0x1bd/0x1d8
Nov 7 10:05:36 host kernel: [] ? __rt_spin_lock+0x24/0x61
Nov 7 10:05:36 host kernel: [] ? rt_spin_lock+0x38/0x3b
Nov 7 10:05:36 host kernel: [] ? snd_seq_fifo_cell_out
+0x47/0xee [snd_seq]
Nov 7 10:05:36 host kernel: [] ? default_wake_function
+0x0/0x12
Nov 7 10:05:36 host kernel: [] ? snd_seq_read+0x0/0x1d8
[snd_seq]
Nov 7 10:05:36 host kernel: [] ? snd_seq_read+0xdd/0x1d8
[snd_seq]
Nov 7 10:05:36 host kernel: [] ? security_file_permission
+0xf/0x11
Nov 7 10:05:36 host kernel: [] ? audit_syscall_entry
+0xf9/0x123
Nov 7 10:05:36 host kernel: [] sys_poll+0x3a/0x6a
Nov 7 10:05:36 host kernel: [] syscall_call+0x7/0xb
Nov 7 10:05:36 host kernel: =======================
--------

# cat /proc/5256/status
Name: aseqdump
State: D (disk sleep)
Tgid: 5256
Pid: 5256
PPid: 5185
TracerPid: 0
Uid: 743 743 743 743
Gid: 10 10 10 10
FDSize: 32
Groups: 10 11 30 31 400
VmPeak: 3104 kB
VmSize: 3048 kB
VmLck: 0 kB
VmHWM: 884 kB
VmRSS: 884 kB
VmData: 172 kB
VmStk: 84 kB
VmExe: 12 kB
VmLib: 2700 kB
VmPTE: 20 kB
Threads: 1
SigQ: 1/32768
SigPnd: 0000000000000000
ShdPnd: 0000000000004000
SigBlk: 0000000000000000
SigIgn: 0000000000000000
SigCgt: 0000000180004002
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: ffffffffffffffff
Cpus_allowed: 0000000f
Cpus_allowed_list: 0-3
Mems_allowed: 1
Mems_allowed_list: 0
voluntary_ctxt_switches: 66283
nonvoluntary_ctxt_switches: 4

# cat /proc/5256/wchan
msleep

-- Fernando


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

On Fri, 2008-11-07 at 10:12 -0800, Fernando Lopez-Lezcano wrote:
> On Fri, 2008-11-07 at 10:12 +0100, Clemens Ladisch wrote:
> > Fernando Lopez-Lezcano wrote:
> > > I'm seeing a realtime patch related hard hang in the kernel alsa
> > > subsystem (MIDI input/output). In a nutshell:
> > >
> > > - alsa rawmidi works (ie: "rawmidi -v -i hw:0" outputs a stream of
> > > messages when pointed to a midi capable card that has an external
> > > keyboard connected).
> > >
> > > - the alsa sequencer interface works (ie: aplaymidi connected to
> > > aseqdump transfers data just fine).
> > >
> > > - BOTH combined do NOT work (ie: use aconnect to connect the port that
> > > corresponds to the external midi interface to aseqdump: aseqdump hangs
> > > forever after transferring the first message and the only way out is a
> > > reboot).
> >
> > Please try the snd-virmidi driver, then we'd have a test case that does
> > not require MIDI hardware.
> >
> > > ... including the output of a "echo t >/proc/sysrq-trigger" that
> > > should show where aseqdump currently hangs (or so I think).
> >
> > It hangs in tasklet_kill(), which gets called while it tries to close
> > the rawmidi port.
> >
> > The rawmidi framework uses this tasklet to notify the sequencer that new
> > MIDI data is available. The handler function is
> > snd_rawmidi_input_event_tasklet() in sound/core/rawmidi.c; the sequencer
> > callback that gets called from there is snd_midi_input_event() in
> > core/seq/seq_midi.c.
> >
> > You say that the first event gets delivered, so it might be

Nope, different this time. Maybe this one points closer to the culprit?
(BTW, snd_midi_input_event only gets called _once_, I added a few more
printk's there):

--------
Nov 7 10:34:51 host kernel: aseqdump S [f15ce070] f7910d70 0
5341 5247
Nov 7 10:34:51 host kernel: f3691bd4 00000086 f3691b88 f7910d70
00000001 f15ce070 f15ce304 c4852700
Nov 7 10:34:51 host kernel: 00000002 c4852700 9a9894aa 0000002c
c484f054 00000000 fffeb4bf 00000246
Nov 7 10:34:51 host kernel: f35cf274 00000000 00000000 00000000
ffffffff 00000000 7fffffff f3691e98
Nov 7 10:34:51 host kernel: Call Trace:
Nov 7 10:34:51 host kernel: [] schedule+0xbf/0xd8
Nov 7 10:34:51 host kernel: [] schedule_timeout+0x17/0xbc
Nov 7 10:34:51 host kernel: [] ? __pollwait+0xad/0xb6
Nov 7 10:34:51 host kernel: [] ? snd_seq_fifo_poll_wait
+0x18/0x25 [snd_seq]
Nov 7 10:34:51 host kernel: [] ? snd_seq_poll+0x4d/0x9f
[snd_seq]
Nov 7 10:34:51 host kernel: [] do_sys_poll+0x292/0x348
Nov 7 10:34:51 host kernel: [] ? __pollwait+0x0/0xb6
Nov 7 10:34:51 host kernel: [] ? default_wake_function
+0x0/0x12
Nov 7 10:34:51 host kernel: [] ? rt_spin_lock+0x38/0x3b
Nov 7 10:34:51 host kernel: [] ? page_address+0x88/0xaa
Nov 7 10:34:51 host kernel: [] ? kmap_high+0x421/0x42a
Nov 7 10:34:51 host kernel: [] ? radix_valid_always+0x0/0xa
Nov 7 10:34:51 host kernel: [] ? __rcu_read_unlock+0x6d/0x72
Nov 7 10:34:51 host kernel: [] ? find_get_page+0xfa/0x120
Nov 7 10:34:51 host kernel: [] ? __rt_spin_lock+0x24/0x61
Nov 7 10:34:51 host kernel: [] ? rt_spin_lock+0x38/0x3b
Nov 7 10:34:51 host kernel: [] ? __enqueue_entity+0xe3/0xeb
Nov 7 10:34:51 host kernel: [] ? task_rq_lock+0x44/0x6e
Nov 7 10:34:51 host kernel: [] ? try_to_wake_up+0x212/0x21d
Nov 7 10:34:51 host kernel: [] ? default_wake_function
+0x10/0x12
Nov 7 10:34:51 host kernel: [] ? __wake_up_common+0x35/0x5b
Nov 7 10:34:51 host kernel: [] ? __wake_up+0x28/0x32
Nov 7 10:34:51 host kernel: [] ? n_tty_receive_buf
+0xfa9/0xff7
Nov 7 10:34:51 host kernel: [] ? n_tty_receive_buf
+0xfa9/0xff7
Nov 7 10:34:51 host kernel: [] ? rt_mutex_up_read+0x1b7/0x25d
Nov 7 10:34:51 host kernel: [] ? rt_up_read+0x8/0xa
Nov 7 10:34:51 host kernel: [] ? do_page_fault+0x45f/0x7d8
Nov 7 10:34:51 host kernel: [] ? hrtimer_start+0x133/0x162
Nov 7 10:34:51 host kernel: [] ? hrtick_set+0x97/0xe5
Nov 7 10:34:51 host kernel: [] ? __rt_spin_lock+0x24/0x61
Nov 7 10:34:51 host kernel: [] ? rt_spin_lock+0x38/0x3b
Nov 7 10:34:51 host kernel: [] ? snd_seq_fifo_cell_out
+0x47/0xee [snd_seq]
Nov 7 10:34:51 host kernel: [] ? default_wake_function
+0x0/0x12
Nov 7 10:34:51 host kernel: [] ? snd_seq_read+0x0/0x1d8
[snd_seq]
Nov 7 10:34:51 host kernel: [] ? snd_seq_read+0xdd/0x1d8
[snd_seq]
Nov 7 10:34:51 host kernel: [] ? security_file_permission
+0xf/0x11
Nov 7 10:34:51 host kernel: [] ? audit_syscall_entry
+0xf9/0x123
Nov 7 10:34:51 host kernel: [] sys_poll+0x3a/0x6a
Nov 7 10:34:51 host kernel: [] syscall_call+0x7/0xb
Nov 7 10:34:51 host kernel: =======================
--------

-- Fernando


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

On Fri, 2008-11-07 at 10:12 -0800, Fernando Lopez-Lezcano wrote:
> On Fri, 2008-11-07 at 10:12 +0100, Clemens Ladisch wrote:
> > Fernando Lopez-Lezcano wrote:
> > > I'm seeing a realtime patch related hard hang in the kernel alsa
> > > subsystem (MIDI input/output). In a nutshell:
> > >
> > > - alsa rawmidi works (ie: "rawmidi -v -i hw:0" outputs a stream of
> > > messages when pointed to a midi capable card that has an external
> > > keyboard connected).
> > >
> > > - the alsa sequencer interface works (ie: aplaymidi connected to
> > > aseqdump transfers data just fine).
> > >
> > > - BOTH combined do NOT work (ie: use aconnect to connect the port that
> > > corresponds to the external midi interface to aseqdump: aseqdump hangs
> > > forever after transferring the first message and the only way out is a
> > > reboot).
> >
> > Please try the snd-virmidi driver, then we'd have a test case that does
> > not require MIDI hardware.
> >
> > > ... including the output of a "echo t >/proc/sysrq-trigger" that
> > > should show where aseqdump currently hangs (or so I think).
> >
> > It hangs in tasklet_kill(), which gets called while it tries to close
> > the rawmidi port.
> >
> > The rawmidi framework uses this tasklet to notify the sequencer that new
> > MIDI data is available. The handler function is
> > snd_rawmidi_input_event_tasklet() in sound/core/rawmidi.c; the sequencer
> > callback that gets called from there is snd_midi_input_event() in
> > core/seq/seq_midi.c.
> >
> > You say that the first event gets delivered, so it might be possible
> > that the tasklet never finishes executing. Please check whether the
> > call to snd_seq_kernel_client_dispatch() in snd_midi_input_event()
> > ever returns.
>
> I added a printk before and after the call, it looks like it gets called
> and it returns (but only _once_... aseqdump hangs in an unkillable state
> as before).

Just in case, the tasklet keeps getting called as long as midi bytes are
received. So the tasklet runs once, snd_midi_input_event gets called
once and the tasklet keeps running again and again, but nobody runs
snd_midi_input_event. Who should?

-- Fernando


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

On Fri, 2008-11-07 at 15:12 -0800, Fernando Lopez-Lezcano wrote:
> On Fri, 2008-11-07 at 10:12 -0800, Fernando Lopez-Lezcano wrote:
> > On Fri, 2008-11-07 at 10:12 +0100, Clemens Ladisch wrote:
> > > Fernando Lopez-Lezcano wrote:
> > > > I'm seeing a realtime patch related hard hang in the kernel alsa
> > > > subsystem (MIDI input/output). In a nutshell:
> > > >
> > > > - alsa rawmidi works (ie: "rawmidi -v -i hw:0" outputs a stream of
> > > > messages when pointed to a midi capable card that has an external
> > > > keyboard connected).
> > > >
> > > > - the alsa sequencer interface works (ie: aplaymidi connected to
> > > > aseqdump transfers data just fine).
> > > >
> > > > - BOTH combined do NOT work (ie: use aconnect to connect the port that
> > > > corresponds to the external midi interface to aseqdump: aseqdump hangs
> > > > forever after transferring the first message and the only way out is a
> > > > reboot).
> > >
> > > Please try the snd-virmidi driver, then we'd have a test case that does
> > > not require MIDI hardware.
> > >
> > > > ... including the output of a "echo t >/proc/sysrq-trigger" that
> > > > should show where aseqdump currently hangs (or so I think).
> > >
> > > It hangs in tasklet_kill(), which gets called while it tries to close
> > > the rawmidi port.
> > >
> > > The rawmidi framework uses this tasklet to notify the sequencer that new
> > > MIDI data is available. The handler function is
> > > snd_rawmidi_input_event_tasklet() in sound/core/rawmidi.c; the sequencer
> > > callback that gets called from there is snd_midi_input_event() in
> > > core/seq/seq_midi.c.
> > >
> > > You say that the first event gets delivered, so it might be possible
> > > that the tasklet never finishes executing. Please check whether the
> > > call to snd_seq_kernel_client_dispatch() in snd_midi_input_event()
> > > ever returns.
> >
> > I added a printk before and after the call, it looks like it gets called
> > and it returns (but only _once_... aseqdump hangs in an unkillable state
> > as before).
>
> Just in case, the tasklet keeps getting called as long as midi bytes are
> received. So the tasklet runs once, snd_midi_input_event gets called
> once and the tasklet keeps running again and again, but nobody runs
> snd_midi_input_event. Who should?

I normally use rtirq to tune realtime priorities for realtime kernel
processes, as I looked around and noticed tasklets seem to be related to
(or are) software interrupts and those have priorities, so I disabled
rtirq and rebooted (which leaves the default priority of 50 for all
realtime kernel processes).

Now I get __two__ midi bytes instead of one (active sensing messages
from the keyboard) and the whole thing stalls as before.
??
So is this a priority inversion problem?
-- Fernando


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

On Fri, 2008-11-07 at 16:48 -0800, Fernando Lopez-Lezcano wrote:
> On Fri, 2008-11-07 at 15:12 -0800, Fernando Lopez-Lezcano wrote:
> > On Fri, 2008-11-07 at 10:12 -0800, Fernando Lopez-Lezcano wrote:
> > > On Fri, 2008-11-07 at 10:12 +0100, Clemens Ladisch wrote:
> > > > Fernando Lopez-Lezcano wrote:
> > > > > I'm seeing a realtime patch related hard hang in the kernel alsa
> > > > > subsystem (MIDI input/output). In a nutshell:
> > > > >
> > > > > - alsa rawmidi works (ie: "rawmidi -v -i hw:0" outputs a stream of
> > > > > messages when pointed to a midi capable card that has an external
> > > > > keyboard connected).
> > > > >
> > > > > - the alsa sequencer interface works (ie: aplaymidi connected to
> > > > > aseqdump transfers data just fine).
> > > > >
> > > > > - BOTH combined do NOT work (ie: use aconnect to connect the port that
> > > > > corresponds to the external midi interface to aseqdump: aseqdump hangs
> > > > > forever after transferring the first message and the only way out is a
> > > > > reboot).
> > > >
> > > > Please try the snd-virmidi driver, then we'd have a test case that does
> > > > not require MIDI hardware.
> > > >
> > > > > ... including the output of a "echo t >/proc/sysrq-trigger" that
> > > > > should show where aseqdump currently hangs (or so I think).
> > > >
> > > > It hangs in tasklet_kill(), which gets called while it tries to close
> > > > the rawmidi port.
> > > >
> > > > The rawmidi framework uses this tasklet to notify the sequencer that new
> > > > MIDI data is available. The handler function is
> > > > snd_rawmidi_input_event_tasklet() in sound/core/rawmidi.c; the sequencer
> > > > callback that gets called from there is snd_midi_input_event() in
> > > > core/seq/seq_midi.c.
> > > >
> > > > You say that the first event gets delivered, so it might be possible
> > > > that the tasklet never finishes executing. Please check whether the
> > > > call to snd_seq_kernel_client_dispatch() in snd_midi_input_event()
> > > > ever returns.
> > >
> > > I added a printk before and after the call, it looks like it gets called
> > > and it returns (but only _once_... aseqdump hangs in an unkillable state
> > > as before).
> >
> > Just in case, the tasklet keeps getting called as long as midi bytes are
> > received. So the tasklet runs once, snd_midi_input_event gets called
> > once and the tasklet keeps running again and again, but nobody runs
> > snd_midi_input_event. Who should?
>
> I normally use rtirq to tune realtime priorities for realtime kernel
> processes, as I looked around and noticed tasklets seem to be related to
> (or are) software interrupts and those have priorities, so I disabled
> rtirq and rebooted (which leaves the default priority of 50 for all
> realtime kernel processes).
>
> Now I get __two__ midi bytes instead of one (active sensing messages
> from the keyboard) and the whole thing stalls as before.

This is repeatable.

> ??
> So is this a priority inversion problem?

And for that matter, what _should_ be the priority order of all the
realtime little tasks of rt kernels?? Names have changed and there's a
lot more of those...

(I can readily hang the whole machine if I change the wrong one to a
higher priority!)

Any help appreciated...
-- Fernando


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/