2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Fernando Lopez-Lezcano]

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

(starting a new thread with the hope of being more precise after a lot
of testing and rebooting)

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). 

Just tested this on 2.6.26.7 + rt11, Gina3G soundcard with an external
MIDI keyboard sending messages. This is not specific to the Gina card, I
have tested also USB midi interfaces and an RME hdsp card with a
Multiface interface. 

2.6.24.7 + rt21 works fine on the same hardware combinations. The
standard Fedora 9 2.6.26.x kernel works fine as well. 

I'm attaching the kernel configuration for the kernel I'm currently
testing plus a dmesg dump of the whole boot process (rt kernel hackers
can find there some additional sleeping in wrong context warning
messages there), including the output of a "echo t >/proc/sysrq-trigger"
that should show where aseqdump currently hangs (or so I think). 

Hopefully this will narrow the area affected enough so that a solution
can be found or more debugging info can be requested. Currently
2.6.26.x-rtx is unusable for musical purposes (at least when you have to
interact with external midi controllers). 

Thanks for any help...
-- Fernando


[-- Attachment #2: dmesg.bz2 --]
[-- Type: application/x-bzip, Size: 38161 bytes --]

[-- Attachment #3: config-2.6.26.7-1.rt11.1fc9.ccrma.i686.rt.bz2 --]
[-- Type: application/x-bzip, Size: 21348 bytes --]

Re: 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Clemens Ladisch]

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 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.


Regards,
Clemens

Re: 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Clemens Ladisch]

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

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Fernando Lopez-Lezcano]

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: [<c0643ba5>] schedule+0xbf/0xd8
Nov  7 10:05:36 host kernel: [<c0643c72>] schedule_timeout+0x17/0xbc
Nov  7 10:05:36 host kernel: [<c0496c8f>] ? __pollwait+0xad/0xb6
Nov  7 10:05:36 host kernel: [<f8971b34>] ? snd_seq_fifo_poll_wait
+0x18/0x25 [snd_seq]
Nov  7 10:05:36 host kernel: [<f896efad>] ? snd_seq_poll+0x4d/0x9f
[snd_seq]
Nov  7 10:05:36 host kernel: [<c0495d92>] do_sys_poll+0x292/0x348
Nov  7 10:05:36 host kernel: [<c0496be2>] ? __pollwait+0x0/0xb6
Nov  7 10:05:36 host kernel: [<c0425c81>] ? default_wake_function
+0x0/0x12
Nov  7 10:05:36 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov  7 10:05:36 host kernel: [<c04752f7>] ? page_address+0x88/0xaa
Nov  7 10:05:36 host kernel: [<c047596d>] ? kmap_high+0x421/0x42a
Nov  7 10:05:36 host kernel: [<c04ff574>] ? radix_valid_always+0x0/0xa
Nov  7 10:05:36 host kernel: [<c046430b>] ? __rcu_read_unlock+0x6d/0x72
Nov  7 10:05:36 host kernel: [<c04699ec>] ? find_get_page+0xfa/0x120
Nov  7 10:05:36 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
Nov  7 10:05:36 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov  7 10:05:36 host kernel: [<c0420afc>] ? __enqueue_entity+0xe3/0xeb
Nov  7 10:05:36 host kernel: [<c041f87b>] ? task_rq_lock+0x44/0x6e
Nov  7 10:05:36 host kernel: [<c0425c76>] ? try_to_wake_up+0x212/0x21d
Nov  7 10:05:36 host kernel: [<c0425c91>] ? default_wake_function
+0x10/0x12
Nov  7 10:05:36 host kernel: [<c041ddd8>] ? __wake_up_common+0x35/0x5b
Nov  7 10:05:36 host kernel: [<c0423172>] ? __wake_up+0x28/0x32
Nov  7 10:05:36 host kernel: [<c0554f2e>] ? n_tty_receive_buf
+0xfa9/0xff7
Nov  7 10:05:36 host kernel: [<c0554f2e>] ? n_tty_receive_buf
+0xfa9/0xff7
Nov  7 10:05:36 host kernel: [<c0447cef>] ? rt_mutex_up_read+0x1b7/0x25d
Nov  7 10:05:36 host kernel: [<c0448f40>] ? rt_up_read+0x8/0xa
Nov  7 10:05:36 host kernel: [<c0647c26>] ? do_page_fault+0x45f/0x7d8
Nov  7 10:05:36 host kernel: [<c0502f6c>] ? copy_to_user+0x36/0x106
Nov  7 10:05:36 host kernel: [<c0644770>] ? rt_spin_lock_slowlock
+0x1bd/0x1d8
Nov  7 10:05:36 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
Nov  7 10:05:36 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov  7 10:05:36 host kernel: [<f8971c46>] ? snd_seq_fifo_cell_out
+0x47/0xee [snd_seq]
Nov  7 10:05:36 host kernel: [<c0425c81>] ? default_wake_function
+0x0/0x12
Nov  7 10:05:36 host kernel: [<f896f041>] ? snd_seq_read+0x0/0x1d8
[snd_seq]
Nov  7 10:05:36 host kernel: [<f896f11e>] ? snd_seq_read+0xdd/0x1d8
[snd_seq]
Nov  7 10:05:36 host kernel: [<c04d73d3>] ? security_file_permission
+0xf/0x11
Nov  7 10:05:36 host kernel: [<c045e231>] ? audit_syscall_entry
+0xf9/0x123
Nov  7 10:05:36 host kernel: [<c049606a>] sys_poll+0x3a/0x6a
Nov  7 10:05:36 host kernel: [<c0404be6>] 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

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Fernando Lopez-Lezcano]

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: [<c0643ba5>] schedule+0xbf/0xd8
Nov  7 10:34:51 host kernel: [<c0643c72>] schedule_timeout+0x17/0xbc
Nov  7 10:34:51 host kernel: [<c0496c8f>] ? __pollwait+0xad/0xb6
Nov  7 10:34:51 host kernel: [<f893cb34>] ? snd_seq_fifo_poll_wait
+0x18/0x25 [snd_seq]
Nov  7 10:34:51 host kernel: [<f8939fad>] ? snd_seq_poll+0x4d/0x9f
[snd_seq]
Nov  7 10:34:51 host kernel: [<c0495d92>] do_sys_poll+0x292/0x348
Nov  7 10:34:51 host kernel: [<c0496be2>] ? __pollwait+0x0/0xb6
Nov  7 10:34:51 host kernel: [<c0425c81>] ? default_wake_function
+0x0/0x12
Nov  7 10:34:51 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov  7 10:34:51 host kernel: [<c04752f7>] ? page_address+0x88/0xaa
Nov  7 10:34:51 host kernel: [<c047596d>] ? kmap_high+0x421/0x42a
Nov  7 10:34:51 host kernel: [<c04ff574>] ? radix_valid_always+0x0/0xa
Nov  7 10:34:51 host kernel: [<c046430b>] ? __rcu_read_unlock+0x6d/0x72
Nov  7 10:34:51 host kernel: [<c04699ec>] ? find_get_page+0xfa/0x120
Nov  7 10:34:51 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
Nov  7 10:34:51 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov  7 10:34:51 host kernel: [<c0420afc>] ? __enqueue_entity+0xe3/0xeb
Nov  7 10:34:51 host kernel: [<c041f87b>] ? task_rq_lock+0x44/0x6e
Nov  7 10:34:51 host kernel: [<c0425c76>] ? try_to_wake_up+0x212/0x21d
Nov  7 10:34:51 host kernel: [<c0425c91>] ? default_wake_function
+0x10/0x12
Nov  7 10:34:51 host kernel: [<c041ddd8>] ? __wake_up_common+0x35/0x5b
Nov  7 10:34:51 host kernel: [<c0423172>] ? __wake_up+0x28/0x32
Nov  7 10:34:51 host kernel: [<c0554f2e>] ? n_tty_receive_buf
+0xfa9/0xff7
Nov  7 10:34:51 host kernel: [<c0554f2e>] ? n_tty_receive_buf
+0xfa9/0xff7
Nov  7 10:34:51 host kernel: [<c0447cef>] ? rt_mutex_up_read+0x1b7/0x25d
Nov  7 10:34:51 host kernel: [<c0448f40>] ? rt_up_read+0x8/0xa
Nov  7 10:34:51 host kernel: [<c0647c26>] ? do_page_fault+0x45f/0x7d8
Nov  7 10:34:51 host kernel: [<c043e441>] ? hrtimer_start+0x133/0x162
Nov  7 10:34:51 host kernel: [<c04249d0>] ? hrtick_set+0x97/0xe5
Nov  7 10:34:51 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
Nov  7 10:34:51 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov  7 10:34:51 host kernel: [<f893cc46>] ? snd_seq_fifo_cell_out
+0x47/0xee [snd_seq]
Nov  7 10:34:51 host kernel: [<c0425c81>] ? default_wake_function
+0x0/0x12
Nov  7 10:34:51 host kernel: [<f893a041>] ? snd_seq_read+0x0/0x1d8
[snd_seq]
Nov  7 10:34:51 host kernel: [<f893a11e>] ? snd_seq_read+0xdd/0x1d8
[snd_seq]
Nov  7 10:34:51 host kernel: [<c04d73d3>] ? security_file_permission
+0xf/0x11
Nov  7 10:34:51 host kernel: [<c045e231>] ? audit_syscall_entry
+0xf9/0x123
Nov  7 10:34:51 host kernel: [<c049606a>] sys_poll+0x3a/0x6a
Nov  7 10:34:51 host kernel: [<c0404be6>] syscall_call+0x7/0xb
Nov  7 10:34:51 host kernel: =======================
--------

-- Fernando

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Fernando Lopez-Lezcano]

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

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Fernando Lopez-Lezcano]

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

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Fernando Lopez-Lezcano]

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

Re: 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Fernando Lopez-Lezcano]

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

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).
> 
> > ... 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.

Going back to this in the hope of a bit more data helping solve the
problem...

I don't understand what is going on (of course! :-)

Cards look like this:

$ cat /proc/asound/cards
 0 [Gina3G         ]: Echo_Echo3G - Gina3G
                      Gina3G rev.0 (DSP56361) at 0xfeb00000 irq 18
 1 [Intel          ]: HDA-Intel - HDA Intel
                      HDA Intel at 0xfe7f8000 irq 22
 2 [PCR            ]: USB-Audio - PCR
                      EDIROL PCR at usb-0000:00:1d.0-1, full speed

Here's what I do:
  - start aseqdump
  - aconnect 16:0 128:0
  - aseqdump receives one midi message (one byte active sensing msg)
  - aseqdump hangs forever (reboot needed)

This is what dmesg prints (patch attached which shows where the printk's
are located in the source for rawmidi.c and seq_midi.c):

== this starts happening as soon as I run aconnect:
rawmidi: before input ops trigger
rawmidi: after input ops trigger
rawmidi: before input ops trigger
rawmidi: after input ops trigger
== hmmm, after it is actually subscribed?
rawmidi: before receive spinlock
rawmidi: after receive spinlock
rawmidi: about to run receive tasklet
rawmidi: run receive tasklet
rawmidi: before receive spin unlock
rawmidi: after receive spin unlock
rawmidi: about to run input tasklet
seq: snd_midi_input_event called
seq: seq_midi_input_event loop begin
rawmidi: before input ops trigger
rawmidi: after input ops trigger
seq: snd_seq_kernel_client_dispatch called
seq: snd_seq_kernel_client_dispatch returned
seq: snd_midi_input_event exiting
rawmidi: after running input tasklet
rawmidi: before receive spinlock
rawmidi: after receive spinlock
rawmidi: about to run receive tasklet
rawmidi: run receive tasklet
rawmidi: before receive spin unlock
rawmidi: after receive spin unlock
rawmidi: before receive spinlock
rawmidi: after receive spinlock
rawmidi: about to run receive tasklet
rawmidi: run receive tasklet
rawmidi: before receive spin unlock
rawmidi: after receive spin unlock
rawmidi: before receive spinlock
rawmidi: after receive spinlock
rawmidi: about to run receive tasklet
rawmidi: run receive tasklet
rawmidi: before receive spin unlock
rawmidi: after receive spin unlock
rawmidi: before receive spinlock
rawmidi: after receive spinlock

So, snd_midi_input_event runs once but never gets called back. 

Something else is deadlocking, what can it be? (ie: where can I put more
printk's to try to see what is going on??)

This is where I think aseqdujmp hangs:

Nov 13 11:36:53 host kernel: =======================
Nov 13 11:36:53 host kernel: aseqdump      S [f3505170] f7960f30     0
5580   5515
Nov 13 11:36:53 host kernel:       f567bbd4 00200082 00000001 f7960f30
00200246 f3505170 f3505404 c485d700 
Nov 13 11:36:53 host kernel:       00000003 c485d700 9a5d89b4 000000bc
f567bba4 f567bba4 0007c8c8 00200246 
Nov 13 11:36:53 host kernel:       f35a7af4 00000000 00000000 00000000
ffffffff 00000000 7fffffff f567be98 
Nov 13 11:36:53 host kernel: Call Trace:
Nov 13 11:36:53 host kernel: [<c0643ba5>] schedule+0xbf/0xd8
Nov 13 11:36:53 host kernel: [<c0643c72>] schedule_timeout+0x17/0xbc
Nov 13 11:36:53 host kernel: [<c0496c8f>] ? __pollwait+0xad/0xb6
Nov 13 11:36:53 host kernel: [<f8968b34>] ? snd_seq_fifo_poll_wait
+0x18/0x25 [snd_seq]
Nov 13 11:36:53 host kernel: [<f8965fad>] ? snd_seq_poll+0x4d/0x9f
[snd_seq]
Nov 13 11:36:53 host kernel: [<c0495d92>] do_sys_poll+0x292/0x348
Nov 13 11:36:53 host kernel: [<c0496be2>] ? __pollwait+0x0/0xb6
Nov 13 11:36:53 host kernel: [<c0425c81>] ? default_wake_function
+0x0/0x12
Nov 13 11:36:53 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov 13 11:36:53 host kernel: [<c04752f7>] ? page_address+0x88/0xaa
Nov 13 11:36:53 host kernel: [<c047596d>] ? kmap_high+0x421/0x42a
Nov 13 11:36:53 host kernel: [<c04ff574>] ? radix_valid_always+0x0/0xa
Nov 13 11:36:53 host kernel: [<c046430b>] ? __rcu_read_unlock+0x6d/0x72
Nov 13 11:36:53 host kernel: [<c04699ec>] ? find_get_page+0xfa/0x120
Nov 13 11:36:53 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
Nov 13 11:36:53 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov 13 11:36:53 host kernel: [<c0420afc>] ? __enqueue_entity+0xe3/0xeb
Nov 13 11:36:53 host kernel: [<c041f87b>] ? task_rq_lock+0x44/0x6e
Nov 13 11:36:53 host kernel: [<c0425c76>] ? try_to_wake_up+0x212/0x21d
Nov 13 11:36:53 host kernel: [<c0425c91>] ? default_wake_function
+0x10/0x12
Nov 13 11:36:53 host kernel: [<c041ddd8>] ? __wake_up_common+0x35/0x5b
Nov 13 11:36:53 host kernel: [<c0423172>] ? __wake_up+0x28/0x32
Nov 13 11:36:53 host kernel: [<c0554f2e>] ? n_tty_receive_buf
+0xfa9/0xff7
Nov 13 11:36:53 host kernel: [<c0554f2e>] ? n_tty_receive_buf
+0xfa9/0xff7
Nov 13 11:36:53 host kernel: [<c0447cef>] ? rt_mutex_up_read+0x1b7/0x25d
Nov 13 11:36:53 host kernel: [<c0448f40>] ? rt_up_read+0x8/0xa
Nov 13 11:36:53 host kernel: [<c0647c26>] ? do_page_fault+0x45f/0x7d8
Nov 13 11:36:53 host kernel: [<c0502f6c>] ? copy_to_user+0x36/0x106
Nov 13 11:36:53 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
Nov 13 11:36:53 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov 13 11:36:53 host kernel: [<f8968c46>] ? snd_seq_fifo_cell_out
+0x47/0xee [snd_seq]
Nov 13 11:36:53 host kernel: [<c0425c81>] ? default_wake_function
+0x0/0x12
Nov 13 11:36:53 host kernel: [<f8966041>] ? snd_seq_read+0x0/0x1d8
[snd_seq]
Nov 13 11:36:53 host kernel: [<f896611e>] ? snd_seq_read+0xdd/0x1d8
[snd_seq]
Nov 13 11:36:53 host kernel: [<c04d73d3>] ? security_file_permission
+0xf/0x11
Nov 13 11:36:53 host kernel: [<c045e231>] ? audit_syscall_entry
+0xf9/0x123
Nov 13 11:36:53 host kernel: [<c049606a>] sys_poll+0x3a/0x6a
Nov 13 11:36:53 host kernel: [<c0404be6>] syscall_call+0x7/0xb
Nov 13 11:36:53 host kernel: =======================

Looks like it is a poll...

Then, when I try to actually kill aseqdump I get this in the log:

Nov 13 11:39:02 host kernel: rawmidi: about to kill input tasklet

And the trace:

Nov 13 11:39:13 host kernel: aseqdump      D [f3505170] f786c0b0     0
5580   5515
Nov 13 11:39:13 host kernel:       f567be0c 00200082 00000000 f786c0b0
00200246 f3505170 f3505404 c483c700 
Nov 13 11:39:13 host kernel:       00000000 c483c700 5618b41d 00000121
f567bdf4 000e6262 f567bdf4 c04320f3 
Nov 13 11:39:13 host kernel:       f567be1c f567be1c f567be14 c0432918
000e6263 000e6263 f567be1c f567be48 
Nov 13 11:39:13 host kernel: Call Trace:
Nov 13 11:39:13 host kernel: [<c04320f3>] ? internal_add_timer+0x88/0x8c
Nov 13 11:39:13 host kernel: [<c0432918>] ? __mod_timer+0xc8/0xd3
Nov 13 11:39:13 host kernel: [<c0643ba5>] schedule+0xbf/0xd8
Nov 13 11:39:13 host kernel: [<c0643cf8>] schedule_timeout+0x9d/0xbc
Nov 13 11:39:13 host kernel: [<c0431da2>] ? process_timeout+0x0/0xa
Nov 13 11:39:13 host kernel: [<c0643cf3>] ? schedule_timeout+0x98/0xbc
Nov 13 11:39:13 host kernel: [<c0643d2c>]
schedule_timeout_uninterruptible+0x15/0x17
Nov 13 11:39:13 host kernel: [<c0432a1b>] msleep+0x10/0x16
Nov 13 11:39:13 host kernel: [<c042eaef>] tasklet_kill+0x2e/0x58
Nov 13 11:39:13 host kernel: [<f89bb755>] snd_rawmidi_input_trigger
+0x31/0x44 [snd_rawmidi]
Nov 13 11:39:13 host kernel: [<f89bceeb>] snd_rawmidi_kernel_release
+0x37/0x105 [snd_rawmidi]
Nov 13 11:39:13 host kernel: [<f8f28633>] midisynth_unsubscribe+0xb/0xd
[snd_seq_midi]
Nov 13 11:39:13 host kernel: [<f8969cb9>] unsubscribe_port+0x3c/0x71
[snd_seq]
Nov 13 11:39:13 host kernel: [<f896a510>] clear_subscriber_list
+0xae/0xdb [snd_seq]
Nov 13 11:39:13 host kernel: [<f896a57e>] port_delete+0x41/0x65
[snd_seq]
Nov 13 11:39:13 host kernel: [<f896a63c>] snd_seq_delete_all_ports
+0x9a/0xba [snd_seq]
Nov 13 11:39:13 host kernel: [<f8965175>] seq_free_client1+0xb/0x90
[snd_seq]
Nov 13 11:39:13 host kernel: [<f8965232>] seq_free_client+0x38/0x6f
[snd_seq]
Nov 13 11:39:13 host kernel: [<f896527e>] snd_seq_release+0x15/0x35
[snd_seq]
Nov 13 11:39:13 host kernel: [<c048b5a2>] __fput+0xae/0x158
Nov 13 11:39:13 host kernel: [<c048b663>] fput+0x17/0x19
Nov 13 11:39:13 host kernel: [<c0488b95>] filp_close+0x50/0x5a
Nov 13 11:39:13 host kernel: [<c0488c12>] sys_close+0x73/0xad
Nov 13 11:39:13 host kernel: [<c0404be6>] syscall_call+0x7/0xb
Nov 13 11:39:13 host kernel: =======================

-- Fernando


[-- Attachment #2: patch --]
[-- Type: text/x-patch, Size: 9526 bytes --]

--- ./sound/core/rawmidi.c.orig	2008-11-06 15:26:03.000000000 -0800
+++ ./sound/core/rawmidi.c	2008-11-13 12:31:23.000000000 -0800
@@ -95,7 +95,10 @@
 static void snd_rawmidi_input_event_tasklet(unsigned long data)
 {
 	struct snd_rawmidi_substream *substream = (struct snd_rawmidi_substream *)data;
+	printk(KERN_ERR "rawmidi: about to run input tasklet\n");
 	substream->runtime->event(substream);
+	printk(KERN_ERR "rawmidi: after running input tasklet\n");
+
 }
 
 static void snd_rawmidi_output_trigger_tasklet(unsigned long data)
@@ -149,18 +152,28 @@
 static inline void snd_rawmidi_output_trigger(struct snd_rawmidi_substream *substream,int up)
 {
 	if (up) {
+	        printk(KERN_ERR "rawmidi: about to run output tasklet\n");
 		tasklet_hi_schedule(&substream->runtime->tasklet);
+	        printk(KERN_ERR "rawmidi: run output tasklet\n");
 	} else {
+	        printk(KERN_ERR "rawmidi: about to kill output tasklet\n");
 		tasklet_kill(&substream->runtime->tasklet);
 		substream->ops->trigger(substream, 0);
+		printk(KERN_ERR "rawmidi: killed output tasklet\n");
 	}
 }
 
 static void snd_rawmidi_input_trigger(struct snd_rawmidi_substream *substream, int up)
 {
+        printk(KERN_ERR "rawmidi: before input ops trigger\n");
 	substream->ops->trigger(substream, up);
-	if (!up && substream->runtime->event)
+        printk(KERN_ERR "rawmidi: after input ops trigger\n");
+	if (!up && substream->runtime->event) {
+
+	        printk(KERN_ERR "rawmidi: about to kill input tasklet\n");
 		tasklet_kill(&substream->runtime->tasklet);
+		printk(KERN_ERR "rawmidi: killed input tasklet\n");
+	}
 }
 
 int snd_rawmidi_drop_output(struct snd_rawmidi_substream *substream)
@@ -861,7 +874,9 @@
 		snd_printd("snd_rawmidi_receive: input is not active!!!\n");
 		return -EINVAL;
 	}
+	printk(KERN_ERR "rawmidi: before receive spinlock\n");
 	spin_lock_irqsave(&runtime->lock, flags);
+	printk(KERN_ERR "rawmidi: after receive spinlock\n");
 	if (count == 1) {	/* special case, faster code */
 		substream->bytes++;
 		if (runtime->avail < runtime->buffer_size) {
@@ -901,12 +916,17 @@
 		}
 	}
 	if (result > 0) {
-		if (runtime->event)
-			tasklet_hi_schedule(&runtime->tasklet);
+	  if (runtime->event) {
+	    printk(KERN_ERR "rawmidi: about to run receive tasklet\n");
+	    tasklet_hi_schedule(&runtime->tasklet);
+	    printk(KERN_ERR "rawmidi: run receive tasklet\n");
+	  }
 		else if (snd_rawmidi_ready(substream))
 			wake_up(&runtime->sleep);
 	}
+	printk(KERN_ERR "rawmidi: before receive spin unlock\n");
 	spin_unlock_irqrestore(&runtime->lock, flags);
+	printk(KERN_ERR "rawmidi: after receive spin unlock\n");
 	return result;
 }
 
--- ./sound/core/seq/seq_midi.c.orig	2008-11-07 09:53:31.000000000 -0800
+++ ./sound/core/seq/seq_midi.c	2008-11-07 10:21:31.000000000 -0800
@@ -80,6 +80,8 @@
 	char buf[16], *pbuf;
 	long res, count;
 
+	printk(KERN_ERR "seq: snd_midi_input_event called\n");
+
 	if (substream == NULL)
 		return;
 	runtime = substream->runtime;
@@ -88,6 +90,9 @@
 		return;
 	memset(&ev, 0, sizeof(ev));
 	while (runtime->avail > 0) {
+
+	        printk(KERN_ERR "seq: seq_midi_input_event loop begin\n");
+
 		res = snd_rawmidi_kernel_read(substream, buf, sizeof(buf));
 		if (res <= 0)
 			continue;
@@ -115,6 +120,9 @@
 			}
 		}
 	}
+
+	printk(KERN_ERR "seq: snd_midi_input_event exiting\n");
+
 }
 
 static int dump_midi(struct snd_rawmidi_substream *substream, const char *buf, int count)
--- ./sound/core/rawmidi.c.orig	2008-11-06 15:26:03.000000000 -0800
+++ ./sound/core/rawmidi.c	2008-11-13 11:41:46.000000000 -0800
@@ -151,16 +151,22 @@
 	if (up) {
 		tasklet_hi_schedule(&substream->runtime->tasklet);
 	} else {
+	        printk(KERN_ERR "rawmidi: about to kill output tasklet\n");
 		tasklet_kill(&substream->runtime->tasklet);
 		substream->ops->trigger(substream, 0);
+		printk(KERN_ERR "rawmidi: killed output tasklet\n");
 	}
 }
 
 static void snd_rawmidi_input_trigger(struct snd_rawmidi_substream *substream, int up)
 {
 	substream->ops->trigger(substream, up);
-	if (!up && substream->runtime->event)
+	if (!up && substream->runtime->event) {
+
+	        printk(KERN_ERR "rawmidi: about to kill input tasklet\n");
 		tasklet_kill(&substream->runtime->tasklet);
+		printk(KERN_ERR "rawmidi: killed input tasklet\n");
+	}
 }
 
 int snd_rawmidi_drop_output(struct snd_rawmidi_substream *substream)
@@ -861,7 +867,9 @@
 		snd_printd("snd_rawmidi_receive: input is not active!!!\n");
 		return -EINVAL;
 	}
+	printk(KERN_ERR "rawmidi: before receive spinlock\n");
 	spin_lock_irqsave(&runtime->lock, flags);
+	printk(KERN_ERR "rawmidi: after receive spinlock\n");
 	if (count == 1) {	/* special case, faster code */
 		substream->bytes++;
 		if (runtime->avail < runtime->buffer_size) {
@@ -901,12 +909,17 @@
 		}
 	}
 	if (result > 0) {
-		if (runtime->event)
-			tasklet_hi_schedule(&runtime->tasklet);
+	  if (runtime->event) {
+	    printk(KERN_ERR "rawmidi: about to run tasklet\n");
+	    tasklet_hi_schedule(&runtime->tasklet);
+	    printk(KERN_ERR "rawmidi: run tasklet\n");
+	  }
 		else if (snd_rawmidi_ready(substream))
 			wake_up(&runtime->sleep);
 	}
+	printk(KERN_ERR "rawmidi: before receive spin unlock\n");
 	spin_unlock_irqrestore(&runtime->lock, flags);
+	printk(KERN_ERR "rawmidi: after receive spin unlock\n");
 	return result;
 }
 
--- ./sound/core/seq/seq_midi.c.orig	2008-11-07 09:53:31.000000000 -0800
+++ ./sound/core/seq/seq_midi.c	2008-11-07 10:21:31.000000000 -0800
@@ -80,6 +80,8 @@
 	char buf[16], *pbuf;
 	long res, count;
 
+	printk(KERN_ERR "seq: snd_midi_input_event called\n");
+
 	if (substream == NULL)
 		return;
 	runtime = substream->runtime;
@@ -88,6 +90,9 @@
 		return;
 	memset(&ev, 0, sizeof(ev));
 	while (runtime->avail > 0) {
+
+	        printk(KERN_ERR "seq: seq_midi_input_event loop begin\n");
+
 		res = snd_rawmidi_kernel_read(substream, buf, sizeof(buf));
 		if (res <= 0)
 			continue;
@@ -115,6 +120,9 @@
 			}
 		}
 	}
+
+	printk(KERN_ERR "seq: snd_midi_input_event exiting\n");
+
 }
 
 static int dump_midi(struct snd_rawmidi_substream *substream, const char *buf, int count)

--- ./sound/core/rawmidi.c.orig	2008-11-06 15:26:03.000000000 -0800
+++ ./sound/core/rawmidi.c	2008-11-13 12:31:23.000000000 -0800
@@ -95,7 +95,10 @@
 static void snd_rawmidi_input_event_tasklet(unsigned long data)
 {
 	struct snd_rawmidi_substream *substream = (struct snd_rawmidi_substream *)data;
+	printk(KERN_ERR "rawmidi: about to run input tasklet\n");
 	substream->runtime->event(substream);
+	printk(KERN_ERR "rawmidi: after running input tasklet\n");
+
 }
 
 static void snd_rawmidi_output_trigger_tasklet(unsigned long data)
@@ -149,18 +152,28 @@
 static inline void snd_rawmidi_output_trigger(struct snd_rawmidi_substream *substream,int up)
 {
 	if (up) {
+	        printk(KERN_ERR "rawmidi: about to run output tasklet\n");
 		tasklet_hi_schedule(&substream->runtime->tasklet);
+	        printk(KERN_ERR "rawmidi: run output tasklet\n");
 	} else {
+	        printk(KERN_ERR "rawmidi: about to kill output tasklet\n");
 		tasklet_kill(&substream->runtime->tasklet);
 		substream->ops->trigger(substream, 0);
+		printk(KERN_ERR "rawmidi: killed output tasklet\n");
 	}
 }
 
 static void snd_rawmidi_input_trigger(struct snd_rawmidi_substream *substream, int up)
 {
+        printk(KERN_ERR "rawmidi: before input ops trigger\n");
 	substream->ops->trigger(substream, up);
-	if (!up && substream->runtime->event)
+        printk(KERN_ERR "rawmidi: after input ops trigger\n");
+	if (!up && substream->runtime->event) {
+
+	        printk(KERN_ERR "rawmidi: about to kill input tasklet\n");
 		tasklet_kill(&substream->runtime->tasklet);
+		printk(KERN_ERR "rawmidi: killed input tasklet\n");
+	}
 }
 
 int snd_rawmidi_drop_output(struct snd_rawmidi_substream *substream)
@@ -861,7 +874,9 @@
 		snd_printd("snd_rawmidi_receive: input is not active!!!\n");
 		return -EINVAL;
 	}
+	printk(KERN_ERR "rawmidi: before receive spinlock\n");
 	spin_lock_irqsave(&runtime->lock, flags);
+	printk(KERN_ERR "rawmidi: after receive spinlock\n");
 	if (count == 1) {	/* special case, faster code */
 		substream->bytes++;
 		if (runtime->avail < runtime->buffer_size) {
@@ -901,12 +916,17 @@
 		}
 	}
 	if (result > 0) {
-		if (runtime->event)
-			tasklet_hi_schedule(&runtime->tasklet);
+	  if (runtime->event) {
+	    printk(KERN_ERR "rawmidi: about to run receive tasklet\n");
+	    tasklet_hi_schedule(&runtime->tasklet);
+	    printk(KERN_ERR "rawmidi: run receive tasklet\n");
+	  }
 		else if (snd_rawmidi_ready(substream))
 			wake_up(&runtime->sleep);
 	}
+	printk(KERN_ERR "rawmidi: before receive spin unlock\n");
 	spin_unlock_irqrestore(&runtime->lock, flags);
+	printk(KERN_ERR "rawmidi: after receive spin unlock\n");
 	return result;
 }
 
--- ./sound/core/seq/seq_midi.c.orig	2008-11-07 09:53:31.000000000 -0800
+++ ./sound/core/seq/seq_midi.c	2008-11-07 10:21:31.000000000 -0800
@@ -80,6 +80,8 @@
 	char buf[16], *pbuf;
 	long res, count;
 
+	printk(KERN_ERR "seq: snd_midi_input_event called\n");
+
 	if (substream == NULL)
 		return;
 	runtime = substream->runtime;
@@ -88,6 +90,9 @@
 		return;
 	memset(&ev, 0, sizeof(ev));
 	while (runtime->avail > 0) {
+
+	        printk(KERN_ERR "seq: seq_midi_input_event loop begin\n");
+
 		res = snd_rawmidi_kernel_read(substream, buf, sizeof(buf));
 		if (res <= 0)
 			continue;
@@ -115,6 +120,9 @@
 			}
 		}
 	}
+
+	printk(KERN_ERR "seq: snd_midi_input_event exiting\n");
+
 }
 
 static int dump_midi(struct snd_rawmidi_substream *substream, const char *buf, int count)

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang

[Fernando Lopez-Lezcano]

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

On Thu, 2008-11-13 at 13:01 -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).
> > 
> > > ... 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.
> 
> Going back to this in the hope of a bit more data helping solve the
> problem...
> 
> I don't understand what is going on (of course! :-)
> 
> Cards look like this:
> 
> $ cat /proc/asound/cards
>  0 [Gina3G         ]: Echo_Echo3G - Gina3G
>                       Gina3G rev.0 (DSP56361) at 0xfeb00000 irq 18
>  1 [Intel          ]: HDA-Intel - HDA Intel
>                       HDA Intel at 0xfe7f8000 irq 22
>  2 [PCR            ]: USB-Audio - PCR
>                       EDIROL PCR at usb-0000:00:1d.0-1, full speed
> 
> Here's what I do:
>   - start aseqdump
>   - aconnect 16:0 128:0
>   - aseqdump receives one midi message (one byte active sensing msg)
>   - aseqdump hangs forever (reboot needed)
> 
> This is what dmesg prints (patch attached which shows where the printk's
> are located in the source for rawmidi.c and seq_midi.c):

More info with some more printk's (see attached patch for location):

after aseqdump startup:

snd_seq_fifo: before init
snd_seq_fifo: after init
snd_seq_fifo_poll_wait: before poll_wait
snd_seq_fifo_poll_wait: after poll_wait

after aconnect:

snd_seq_fifo: before init
snd_seq_fifo: after init
rawmidi: before input ops trigger
rawmidi: after input ops trigger
rawmidi: before input ops trigger
rawmidi: after input ops trigger
snd_seq_fifo_event_in: before wake_up
snd_seq_fifo_event_in: after wake_up
snd_seq_fifo_poll_wait: before poll_wait
snd_seq_fifo_poll_wait: after poll_wait
snd_seq_fifo_cell_out: before spin_unlock
snd_seq_fifo_cell_out: after spin_unlock
snd_seq_fifo_poll_wait: before poll_wait
snd_seq_fifo_poll_wait: after poll_wait
rawmidi: before receive spinlock
rawmidi: after receive spinlock
rawmidi: about to run receive tasklet
rawmidi: run receive tasklet
rawmidi: before receive spin unlock
rawmidi: after receive spin unlock
rawmidi: about to run input tasklet
seq: snd_midi_input_event called
seq: seq_midi_input_event loop begin
rawmidi: before input ops trigger
rawmidi: after input ops trigger
seq: snd_seq_kernel_client_dispatch called
snd_seq_fifo_event_in: before wake_up
snd_seq_fifo_event_in: after wake_up
seq: snd_seq_kernel_client_dispatch returned
snd_seq_fifo_poll_wait: before poll_wait
snd_seq_fifo_poll_wait: after poll_wait
seq: snd_midi_input_event exiting
rawmidi: after running input tasklet
snd_seq_fifo_cell_out: before spin_unlock
snd_seq_fifo_cell_out: after spin_unlock
snd_seq_fifo_poll_wait: before poll_wait
snd_seq_fifo_poll_wait: after poll_wait
rawmidi: before receive spinlock
rawmidi: after receive spinlock
rawmidi: about to run receive tasklet
rawmidi: run receive tasklet
rawmidi: before receive spin unlock
rawmidi: after receive spin unlock
rawmidi: before receive spinlock
rawmidi: after receive spinlock
rawmidi: about to run receive tasklet
rawmidi: run receive tasklet
rawmidi: before receive spin unlock
rawmidi: after receive spin unlock
rawmidi: before receive spinlock
rawmidi: after receive spinlock
rawmidi: about to run receive tasklet

Hangs here:

Nov 13 14:39:57 host kernel: aseqdump      S [f55762f0] f714dbe0     0
5360   5318
Nov 13 14:39:57 host kernel:       f714dbd4 00200082 f628edc0 f714dbe0
c042ab6d f55762f0 f5576584 c4847700 
Nov 13 14:39:57 host kernel:       00000001 c4847700 098b418d 0000003d
00000000 00000000 00200246 f63980f4 
Nov 13 14:39:57 host kernel:       f714dbc0 c06456c1 f63980f4 f714dc5c
f714dbcc 00000000 7fffffff f714de98 
Nov 13 14:39:57 host kernel: Call Trace:
Nov 13 14:39:57 host kernel: [<c042ab6d>] ? vprintk+0x30e/0x331
Nov 13 14:39:57 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
Nov 13 14:39:57 host kernel: [<c0643ba5>] schedule+0xbf/0xd8
Nov 13 14:39:57 host kernel: [<c0643c72>] schedule_timeout+0x17/0xbc
Nov 13 14:39:57 host kernel: [<c0642de5>] ? printk+0xf/0x12
Nov 13 14:39:57 host kernel: [<f8967c0c>] ? snd_seq_fifo_poll_wait
+0x32/0x44 [snd_seq]
Nov 13 14:39:57 host kernel: [<f8964fad>] ? snd_seq_poll+0x4d/0x9f
[snd_seq]
Nov 13 14:39:57 host kernel: [<c0495d92>] do_sys_poll+0x292/0x348
Nov 13 14:39:57 host kernel: [<c0496be2>] ? __pollwait+0x0/0xb6
Nov 13 14:39:57 host kernel: [<c0425c81>] ? default_wake_function
+0x0/0x12
Nov 13 14:39:57 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov 13 14:39:57 host kernel: [<c04752f7>] ? page_address+0x88/0xaa
Nov 13 14:39:57 host kernel: [<c047596d>] ? kmap_high+0x421/0x42a
Nov 13 14:39:57 host kernel: [<c04ff574>] ? radix_valid_always+0x0/0xa
Nov 13 14:39:57 host kernel: [<c046430b>] ? __rcu_read_unlock+0x6d/0x72
Nov 13 14:39:57 host kernel: [<c04699ec>] ? find_get_page+0xfa/0x120
Nov 13 14:39:57 host kernel: [<c0440314>] ? getnstimeofday+0x3c/0xd6
Nov 13 14:39:57 host kernel: [<c043e653>] ? ktime_get_ts+0x4a/0x4e
Nov 13 14:39:57 host kernel: [<c043e66a>] ? ktime_get+0x13/0x2f
Nov 13 14:39:57 host kernel: [<c0424060>] ? hrtick_start_fair
+0x140/0x148
Nov 13 14:39:57 host kernel: [<c041f87b>] ? task_rq_lock+0x44/0x6e
Nov 13 14:39:57 host kernel: [<c0425c76>] ? try_to_wake_up+0x212/0x21d
Nov 13 14:39:57 host kernel: [<c0425c91>] ? default_wake_function
+0x10/0x12
Nov 13 14:39:57 host kernel: [<c041ddd8>] ? __wake_up_common+0x35/0x5b
Nov 13 14:39:57 host kernel: [<c0423172>] ? __wake_up+0x28/0x32
Nov 13 14:39:57 host kernel: [<c0554f2e>] ? n_tty_receive_buf
+0xfa9/0xff7
Nov 13 14:39:57 host kernel: [<c0554f2e>] ? n_tty_receive_buf
+0xfa9/0xff7
Nov 13 14:39:57 host kernel: [<c05009a6>] ? rb_insert_color+0x56/0xc0
Nov 13 14:39:57 host kernel: [<c043dbab>] ? enqueue_hrtimer+0x112/0x11e
Nov 13 14:39:57 host kernel: [<c043e441>] ? hrtimer_start+0x133/0x162
Nov 13 14:39:57 host kernel: [<c04249d0>] ? hrtick_set+0x97/0xe5
Nov 13 14:39:57 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
Nov 13 14:39:57 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
Nov 13 14:39:57 host kernel: [<f8967c68>] ? snd_seq_fifo_cell_out
+0x4a/0x146 [snd_seq]
Nov 13 14:39:57 host kernel: [<c0425c81>] ? default_wake_function
+0x0/0x12
Nov 13 14:39:57 host kernel: [<f8965041>] ? snd_seq_read+0x0/0x1d8
[snd_seq]
Nov 13 14:39:57 host kernel: [<f896511e>] ? snd_seq_read+0xdd/0x1d8
[snd_seq]
Nov 13 14:39:57 host kernel: [<c04d73d3>] ? security_file_permission
+0xf/0x11
Nov 13 14:39:57 host kernel: [<c045e231>] ? audit_syscall_entry
+0xf9/0x123
Nov 13 14:39:57 host kernel: [<c049606a>] sys_poll+0x3a/0x6a
Nov 13 14:39:57 host kernel: [<c0404be6>] syscall_call+0x7/0xb
Nov 13 14:39:57 host kernel: =======================

After I try to kill aseqdump:

snd_seq_fifo_poll_wait: before poll_wait
snd_seq_fifo_poll_wait: after poll_wait
rawmidi: before input ops trigger
rawmidi: after input ops trigger
rawmidi: about to kill input tasklet
(definitely hangs there as well, never kills tasklet)

Help!
What can I try next??
-- Fernando


[-- Attachment #2: patch --]
[-- Type: text/x-patch, Size: 2530 bytes --]

--- ./sound/core/seq/seq_fifo.c.orig	2008-11-13 13:04:48.000000000 -0800
+++ ./sound/core/seq/seq_fifo.c	2008-11-13 14:28:11.000000000 -0800
@@ -51,7 +51,9 @@
 
 	spin_lock_init(&f->lock);
 	snd_use_lock_init(&f->use_lock);
+        printk("snd_seq_fifo: before init\n");
 	init_waitqueue_head(&f->input_sleep);
+        printk("snd_seq_fifo: after init\n");
 	atomic_set(&f->overflow, 0);
 
 	f->head = NULL;
@@ -73,8 +75,11 @@
 	snd_seq_fifo_clear(f);
 
 	/* wake up clients if any */
-	if (waitqueue_active(&f->input_sleep))
+	if (waitqueue_active(&f->input_sleep)) {
+	        printk("snd_seq_fifo_delete: before wake_up\n");
 		wake_up(&f->input_sleep);
+	        printk("snd_seq_fifo_delete: after wake_up\n");
+	};
 
 	/* release resources...*/
 	/*....................*/
@@ -138,8 +143,11 @@
 	spin_unlock_irqrestore(&f->lock, flags);
 
 	/* wakeup client */
-	if (waitqueue_active(&f->input_sleep))
+	if (waitqueue_active(&f->input_sleep)) {
+	        printk("snd_seq_fifo_event_in: before wake_up\n");
 		wake_up(&f->input_sleep);
+	        printk("snd_seq_fifo_event_in: after wake_up\n");
+	};
 
 	snd_use_lock_free(&f->use_lock);
 
@@ -186,17 +194,25 @@
 			return -EAGAIN;
 		}
 		set_current_state(TASK_INTERRUPTIBLE);
+	        printk("snd_seq_fifo_cell_out: before add_wait_queue\n");
 		add_wait_queue(&f->input_sleep, &wait);
+	        printk("snd_seq_fifo_cell_out: after add_wait_queue\n");
 		spin_unlock_irq(&f->lock);
 		schedule();
 		spin_lock_irq(&f->lock);
+	        printk("snd_seq_fifo_cell_out: before remove_wait_queue\n");
 		remove_wait_queue(&f->input_sleep, &wait);
+	        printk("snd_seq_fifo_cell_out: after remove_wait_queue\n");
 		if (signal_pending(current)) {
+		        printk("snd_seq_fifo_cell_out: before spin_unlock pend\n");
 			spin_unlock_irqrestore(&f->lock, flags);
+		        printk("snd_seq_fifo_cell_out: after spin_unlock pend\n");
 			return -ERESTARTSYS;
 		}
 	}
+	printk("snd_seq_fifo_cell_out: before spin_unlock\n");
 	spin_unlock_irqrestore(&f->lock, flags);
+	printk("snd_seq_fifo_cell_out: after spin_unlock\n");
 	*cellp = cell;
 
 	return 0;
@@ -222,9 +238,9 @@
 int snd_seq_fifo_poll_wait(struct snd_seq_fifo *f, struct file *file,
 			   poll_table *wait)
 {
-	printk(KERN_ERR "seq_fifo: before poll_wait\n");
+        printk("snd_seq_fifo_poll_wait: before poll_wait\n");
 	poll_wait(file, &f->input_sleep, wait);
-	printk(KERN_ERR "seq_fifo: after poll_wait\n");
+        printk("snd_seq_fifo_poll_wait: after poll_wait\n");
 	return (f->cells > 0);
 }
 

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang (tasklet_hi_schedule?)

[Fernando Lopez-Lezcano]

On Thu, 2008-11-13 at 14:56 -0800, Fernando Lopez-Lezcano wrote:
> On Thu, 2008-11-13 at 13:01 -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).
> > > 
> > > > ... 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.
> > 
> > Going back to this in the hope of a bit more data helping solve the
> > problem...
> > 
> > I don't understand what is going on (of course! :-)
> > 
> > Cards look like this:
> > 
> > $ cat /proc/asound/cards
> >  0 [Gina3G         ]: Echo_Echo3G - Gina3G
> >                       Gina3G rev.0 (DSP56361) at 0xfeb00000 irq 18
> >  1 [Intel          ]: HDA-Intel - HDA Intel
> >                       HDA Intel at 0xfe7f8000 irq 22
> >  2 [PCR            ]: USB-Audio - PCR
> >                       EDIROL PCR at usb-0000:00:1d.0-1, full speed
> > 
> > Here's what I do:
> >   - start aseqdump
> >   - aconnect 16:0 128:0
> >   - aseqdump receives one midi message (one byte active sensing msg)
> >   - aseqdump hangs forever (reboot needed)
> > 
> > This is what dmesg prints (patch attached which shows where the printk's
> > are located in the source for rawmidi.c and seq_midi.c):
> 
> More info with some more printk's (see attached patch for location):

I've been trying to follow the printk crumbs without much success.
AFAICT it all points to tasklet_hi_schedule ... the handling code is
being scheduled but never executes, right? (well, it executes _once_ and
then never again). And that leads to tasklet_common_schedule - as
Clemens pointed at the beginning of the thread this is eerily similar to
what happened before in 2006:

  http://lkml.org/lkml/2006/3/7/256

So, is tasklet_common_schedule just going through the "goto again;" loop
forever?:

   tasklet_trylock(t) is true
again:
-> test_bit(TASKLET_STATE_SCHED, &t->state) is false
-> !tasklet_tryunlock(t) is true
-> goto again

I don't know what it all _means_, I'm just trying to point a finger to
something in the hope that somebody will understand and say "aha!" (and
email a nice patch! :-)

As the code says, "this is subtle"...

-- Fernando

> after aseqdump startup:
> 
> snd_seq_fifo: before init
> snd_seq_fifo: after init
> snd_seq_fifo_poll_wait: before poll_wait
> snd_seq_fifo_poll_wait: after poll_wait
> 
> after aconnect:
> 
> snd_seq_fifo: before init
> snd_seq_fifo: after init
> rawmidi: before input ops trigger
> rawmidi: after input ops trigger
> rawmidi: before input ops trigger
> rawmidi: after input ops trigger
> snd_seq_fifo_event_in: before wake_up
> snd_seq_fifo_event_in: after wake_up
> snd_seq_fifo_poll_wait: before poll_wait
> snd_seq_fifo_poll_wait: after poll_wait
> snd_seq_fifo_cell_out: before spin_unlock
> snd_seq_fifo_cell_out: after spin_unlock
> snd_seq_fifo_poll_wait: before poll_wait
> snd_seq_fifo_poll_wait: after poll_wait
> rawmidi: before receive spinlock
> rawmidi: after receive spinlock
> rawmidi: about to run receive tasklet
> rawmidi: run receive tasklet
> rawmidi: before receive spin unlock
> rawmidi: after receive spin unlock
> rawmidi: about to run input tasklet
> seq: snd_midi_input_event called
> seq: seq_midi_input_event loop begin
> rawmidi: before input ops trigger
> rawmidi: after input ops trigger
> seq: snd_seq_kernel_client_dispatch called
> snd_seq_fifo_event_in: before wake_up
> snd_seq_fifo_event_in: after wake_up
> seq: snd_seq_kernel_client_dispatch returned
> snd_seq_fifo_poll_wait: before poll_wait
> snd_seq_fifo_poll_wait: after poll_wait
> seq: snd_midi_input_event exiting
> rawmidi: after running input tasklet
> snd_seq_fifo_cell_out: before spin_unlock
> snd_seq_fifo_cell_out: after spin_unlock
> snd_seq_fifo_poll_wait: before poll_wait
> snd_seq_fifo_poll_wait: after poll_wait
> rawmidi: before receive spinlock
> rawmidi: after receive spinlock
> rawmidi: about to run receive tasklet
> rawmidi: run receive tasklet
> rawmidi: before receive spin unlock
> rawmidi: after receive spin unlock
> rawmidi: before receive spinlock
> rawmidi: after receive spinlock
> rawmidi: about to run receive tasklet
> rawmidi: run receive tasklet
> rawmidi: before receive spin unlock
> rawmidi: after receive spin unlock
> rawmidi: before receive spinlock
> rawmidi: after receive spinlock
> rawmidi: about to run receive tasklet
> 
> Hangs here:
> 
> Nov 13 14:39:57 host kernel: aseqdump      S [f55762f0] f714dbe0     0
> 5360   5318
> Nov 13 14:39:57 host kernel:       f714dbd4 00200082 f628edc0 f714dbe0
> c042ab6d f55762f0 f5576584 c4847700 
> Nov 13 14:39:57 host kernel:       00000001 c4847700 098b418d 0000003d
> 00000000 00000000 00200246 f63980f4 
> Nov 13 14:39:57 host kernel:       f714dbc0 c06456c1 f63980f4 f714dc5c
> f714dbcc 00000000 7fffffff f714de98 
> Nov 13 14:39:57 host kernel: Call Trace:
> Nov 13 14:39:57 host kernel: [<c042ab6d>] ? vprintk+0x30e/0x331
> Nov 13 14:39:57 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
> Nov 13 14:39:57 host kernel: [<c0643ba5>] schedule+0xbf/0xd8
> Nov 13 14:39:57 host kernel: [<c0643c72>] schedule_timeout+0x17/0xbc
> Nov 13 14:39:57 host kernel: [<c0642de5>] ? printk+0xf/0x12
> Nov 13 14:39:57 host kernel: [<f8967c0c>] ? snd_seq_fifo_poll_wait
> +0x32/0x44 [snd_seq]
> Nov 13 14:39:57 host kernel: [<f8964fad>] ? snd_seq_poll+0x4d/0x9f
> [snd_seq]
> Nov 13 14:39:57 host kernel: [<c0495d92>] do_sys_poll+0x292/0x348
> Nov 13 14:39:57 host kernel: [<c0496be2>] ? __pollwait+0x0/0xb6
> Nov 13 14:39:57 host kernel: [<c0425c81>] ? default_wake_function
> +0x0/0x12
> Nov 13 14:39:57 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
> Nov 13 14:39:57 host kernel: [<c04752f7>] ? page_address+0x88/0xaa
> Nov 13 14:39:57 host kernel: [<c047596d>] ? kmap_high+0x421/0x42a
> Nov 13 14:39:57 host kernel: [<c04ff574>] ? radix_valid_always+0x0/0xa
> Nov 13 14:39:57 host kernel: [<c046430b>] ? __rcu_read_unlock+0x6d/0x72
> Nov 13 14:39:57 host kernel: [<c04699ec>] ? find_get_page+0xfa/0x120
> Nov 13 14:39:57 host kernel: [<c0440314>] ? getnstimeofday+0x3c/0xd6
> Nov 13 14:39:57 host kernel: [<c043e653>] ? ktime_get_ts+0x4a/0x4e
> Nov 13 14:39:57 host kernel: [<c043e66a>] ? ktime_get+0x13/0x2f
> Nov 13 14:39:57 host kernel: [<c0424060>] ? hrtick_start_fair
> +0x140/0x148
> Nov 13 14:39:57 host kernel: [<c041f87b>] ? task_rq_lock+0x44/0x6e
> Nov 13 14:39:57 host kernel: [<c0425c76>] ? try_to_wake_up+0x212/0x21d
> Nov 13 14:39:57 host kernel: [<c0425c91>] ? default_wake_function
> +0x10/0x12
> Nov 13 14:39:57 host kernel: [<c041ddd8>] ? __wake_up_common+0x35/0x5b
> Nov 13 14:39:57 host kernel: [<c0423172>] ? __wake_up+0x28/0x32
> Nov 13 14:39:57 host kernel: [<c0554f2e>] ? n_tty_receive_buf
> +0xfa9/0xff7
> Nov 13 14:39:57 host kernel: [<c0554f2e>] ? n_tty_receive_buf
> +0xfa9/0xff7
> Nov 13 14:39:57 host kernel: [<c05009a6>] ? rb_insert_color+0x56/0xc0
> Nov 13 14:39:57 host kernel: [<c043dbab>] ? enqueue_hrtimer+0x112/0x11e
> Nov 13 14:39:57 host kernel: [<c043e441>] ? hrtimer_start+0x133/0x162
> Nov 13 14:39:57 host kernel: [<c04249d0>] ? hrtick_set+0x97/0xe5
> Nov 13 14:39:57 host kernel: [<c06456c1>] ? __rt_spin_lock+0x24/0x61
> Nov 13 14:39:57 host kernel: [<c0645736>] ? rt_spin_lock+0x38/0x3b
> Nov 13 14:39:57 host kernel: [<f8967c68>] ? snd_seq_fifo_cell_out
> +0x4a/0x146 [snd_seq]
> Nov 13 14:39:57 host kernel: [<c0425c81>] ? default_wake_function
> +0x0/0x12
> Nov 13 14:39:57 host kernel: [<f8965041>] ? snd_seq_read+0x0/0x1d8
> [snd_seq]
> Nov 13 14:39:57 host kernel: [<f896511e>] ? snd_seq_read+0xdd/0x1d8
> [snd_seq]
> Nov 13 14:39:57 host kernel: [<c04d73d3>] ? security_file_permission
> +0xf/0x11
> Nov 13 14:39:57 host kernel: [<c045e231>] ? audit_syscall_entry
> +0xf9/0x123
> Nov 13 14:39:57 host kernel: [<c049606a>] sys_poll+0x3a/0x6a
> Nov 13 14:39:57 host kernel: [<c0404be6>] syscall_call+0x7/0xb
> Nov 13 14:39:57 host kernel: =======================
> 
> After I try to kill aseqdump:
> 
> snd_seq_fifo_poll_wait: before poll_wait
> snd_seq_fifo_poll_wait: after poll_wait
> rawmidi: before input ops trigger
> rawmidi: after input ops trigger
> rawmidi: about to kill input tasklet
> (definitely hangs there as well, never kills tasklet)
> 
> Help!
> What can I try next??
> -- Fernando
> 
> _______________________________________________
> Alsa-devel mailing list
> Alsa-devel@alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang (tasklet_hi_schedule?)

[Clemens Ladisch]

Fernando Lopez-Lezcano wrote:
> I've been trying to follow the printk crumbs without much success.
> AFAICT it all points to tasklet_hi_schedule ...

I don't have -rt, but if the error is similar to the old one you might
try replacing tasklet_hi_schedule with tasklet_schedule.


HTH
Clemens

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang (tasklet_hi_schedule?)

[Takashi Iwai]

At Fri, 14 Nov 2008 09:15:53 +0100,
Clemens Ladisch wrote:
> 
> Fernando Lopez-Lezcano wrote:
> > I've been trying to follow the printk crumbs without much success.
> > AFAICT it all points to tasklet_hi_schedule ...
> 
> I don't have -rt, but if the error is similar to the old one you might
> try replacing tasklet_hi_schedule with tasklet_schedule.

Hmm, I don't remember why we still keep tasklet_hi version...


Takashi

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang (tasklet_hi_schedule?)

[Fernando Lopez-Lezcano]

On Fri, 2008-11-14 at 09:15 +0100, Clemens Ladisch wrote:
> Fernando Lopez-Lezcano wrote:
> > I've been trying to follow the printk crumbs without much success.
> > AFAICT it all points to tasklet_hi_schedule ...
> 
> I don't have -rt, but if the error is similar to the old one you might
> try replacing tasklet_hi_schedule with tasklet_schedule.

YES YES!! __Thanks__ for the suggestion, it WORKED!!

Maybe the kernel rt gurus should look around and see _why_ the problem
was happening in the first place. There are not that many uses of
tasklet_hi_schedule in the kernel tree I'm working with:

./drivers/char/drm/drm_irq.c
./drivers/infiniband/hw/ehca/ehca_irq.c
./drivers/infiniband/hw/ipath/ipath_cq.c
./drivers/infiniband/hw/ipath/ipath_driver.c
./drivers/infiniband/hw/ipath/ipath_intr.c
./drivers/infiniband/hw/ipath/ipath_sdma.c
./drivers/media/video/vino.c
./drivers/mmc/host/omap.c
./drivers/mmc/host/wbsd.c
./drivers/net/chelsio/sge.c
./drivers/net/ehea/ehea_main.c
./drivers/net/smc91x.c
./drivers/s390/block/dasd.c
./drivers/s390/cio/qdio.c
./drivers/s390/net/ctcm_fsms.c
./drivers/s390/net/ctcm_mpc.c
./drivers/usb/c67x00/c67x00-sched.c
./drivers/usb/gadget/gmidi.c
./kernel/softirq.c
./sound/core/rtctimer.c
./sound/core/timer.c
./sound/drivers/vx/vx_core.c
./sound/drivers/vx/vx_pcm.c
./sound/pci/es1968.c
./sound/pci/maestro3.c
./sound/pci/mixart/mixart_core.c
./sound/pci/pcxhr/pcxhr.c
./sound/pci/pcxhr/pcxhr_core.c
./sound/pci/riptide/riptide.c
./sound/pci/rme9652/hdsp.c
./sound/pci/rme9652/hdspm.c
./sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
./sound/usb/usbmidi.c

Maybe other drivers are affected as well by the rt patch. 
What is the difference between tasklet_hi_schedule and tasklet_schedule?

Thanks again...
-- Fernando

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang (tasklet_hi_schedule?)

[Takashi Iwai]

At Fri, 14 Nov 2008 10:57:10 -0800,
Fernando Lopez-Lezcano wrote:
> 
> On Fri, 2008-11-14 at 09:15 +0100, Clemens Ladisch wrote:
> > Fernando Lopez-Lezcano wrote:
> > > I've been trying to follow the printk crumbs without much success.
> > > AFAICT it all points to tasklet_hi_schedule ...
> > 
> > I don't have -rt, but if the error is similar to the old one you might
> > try replacing tasklet_hi_schedule with tasklet_schedule.
> 
> YES YES!! __Thanks__ for the suggestion, it WORKED!!
> 
> Maybe the kernel rt gurus should look around and see _why_ the problem
> was happening in the first place. There are not that many uses of
> tasklet_hi_schedule in the kernel tree I'm working with:
(snip)
> Maybe other drivers are affected as well by the rt patch. 
> What is the difference between tasklet_hi_schedule and tasklet_schedule?

AFAIK, tasklet_hi_schedule() uses another softirq vector with the
highest priority (the first item to be scanned).

Regarding the ALSA codes, there is no big reason to use hi_* version.
Could you check the patch below and see whether you get any
regressions?


thanks,

Takashi

---
diff --git a/sound/core/rawmidi.c b/sound/core/rawmidi.c
index 39672f6..002777b 100644
--- a/sound/core/rawmidi.c
+++ b/sound/core/rawmidi.c
@@ -151,7 +151,7 @@ static inline void snd_rawmidi_output_trigger(struct snd_rawmidi_substream *subs
 	if (!substream->opened)
 		return;
 	if (up) {
-		tasklet_hi_schedule(&substream->runtime->tasklet);
+		tasklet_schedule(&substream->runtime->tasklet);
 	} else {
 		tasklet_kill(&substream->runtime->tasklet);
 		substream->ops->trigger(substream, 0);
@@ -908,7 +908,7 @@ int snd_rawmidi_receive(struct snd_rawmidi_substream *substream,
 	}
 	if (result > 0) {
 		if (runtime->event)
-			tasklet_hi_schedule(&runtime->tasklet);
+			tasklet_schedule(&runtime->tasklet);
 		else if (snd_rawmidi_ready(substream))
 			wake_up(&runtime->sleep);
 	}
diff --git a/sound/core/rtctimer.c b/sound/core/rtctimer.c
index 51e64e3..0851cd1 100644
--- a/sound/core/rtctimer.c
+++ b/sound/core/rtctimer.c
@@ -118,7 +118,7 @@ static void rtctimer_tasklet(unsigned long data)
  */
 static void rtctimer_interrupt(void *private_data)
 {
-	tasklet_hi_schedule(private_data);
+	tasklet_schedule(private_data);
 }
 
 
diff --git a/sound/core/timer.c b/sound/core/timer.c
index c584408..7965320 100644
--- a/sound/core/timer.c
+++ b/sound/core/timer.c
@@ -743,7 +743,7 @@ void snd_timer_interrupt(struct snd_timer * timer, unsigned long ticks_left)
 	spin_unlock_irqrestore(&timer->lock, flags);
 
 	if (use_tasklet)
-		tasklet_hi_schedule(&timer->task_queue);
+		tasklet_schedule(&timer->task_queue);
 }
 
 /*
diff --git a/sound/drivers/vx/vx_core.c b/sound/drivers/vx/vx_core.c
index 473b07f..14e3354 100644
--- a/sound/drivers/vx/vx_core.c
+++ b/sound/drivers/vx/vx_core.c
@@ -548,7 +548,7 @@ irqreturn_t snd_vx_irq_handler(int irq, void *dev)
 	    (chip->chip_status & VX_STAT_IS_STALE))
 		return IRQ_NONE;
 	if (! vx_test_and_ack(chip))
-		tasklet_hi_schedule(&chip->tq);
+		tasklet_schedule(&chip->tq);
 	return IRQ_HANDLED;
 }
 
diff --git a/sound/drivers/vx/vx_pcm.c b/sound/drivers/vx/vx_pcm.c
index 27de574..6644d00 100644
--- a/sound/drivers/vx/vx_pcm.c
+++ b/sound/drivers/vx/vx_pcm.c
@@ -823,7 +823,7 @@ static int vx_pcm_trigger(struct snd_pcm_substream *subs, int cmd)
 		 * we trigger the pipe using tasklet, so that the interrupts are
 		 * issued surely after the trigger is completed.
 		 */ 
-		tasklet_hi_schedule(&pipe->start_tq);
+		tasklet_schedule(&pipe->start_tq);
 		chip->pcm_running++;
 		pipe->running = 1;
 		break;
diff --git a/sound/pci/es1968.c b/sound/pci/es1968.c
index 20ee759..e9c3794 100644
--- a/sound/pci/es1968.c
+++ b/sound/pci/es1968.c
@@ -1953,7 +1953,7 @@ static irqreturn_t snd_es1968_interrupt(int irq, void *dev_id)
 	outw(inw(chip->io_port + 4) & 1, chip->io_port + 4);
 
 	if (event & ESM_HWVOL_IRQ)
-		tasklet_hi_schedule(&chip->hwvol_tq); /* we'll do this later */
+		tasklet_schedule(&chip->hwvol_tq); /* we'll do this later */
 
 	/* else ack 'em all, i imagine */
 	outb(0xFF, chip->io_port + 0x1A);
diff --git a/sound/pci/maestro3.c b/sound/pci/maestro3.c
index 9ff3f9e..59bbaf8 100644
--- a/sound/pci/maestro3.c
+++ b/sound/pci/maestro3.c
@@ -1670,7 +1670,7 @@ static irqreturn_t snd_m3_interrupt(int irq, void *dev_id)
 		return IRQ_NONE;
 
 	if (status & HV_INT_PENDING)
-		tasklet_hi_schedule(&chip->hwvol_tq);
+		tasklet_schedule(&chip->hwvol_tq);
 
 	/*
 	 * ack an assp int if its running
diff --git a/sound/pci/mixart/mixart_core.c b/sound/pci/mixart/mixart_core.c
index b9a06c2..d3350f3 100644
--- a/sound/pci/mixart/mixart_core.c
+++ b/sound/pci/mixart/mixart_core.c
@@ -550,7 +550,7 @@ irqreturn_t snd_mixart_interrupt(int irq, void *dev_id)
 				mgr->msg_fifo[mgr->msg_fifo_writeptr] = msg;
 				mgr->msg_fifo_writeptr++;
 				mgr->msg_fifo_writeptr %= MSG_FIFO_SIZE;
-				tasklet_hi_schedule(&mgr->msg_taskq);
+				tasklet_schedule(&mgr->msg_taskq);
 			}
 			spin_unlock(&mgr->msg_lock);
 			break;
diff --git a/sound/pci/pcxhr/pcxhr.c b/sound/pci/pcxhr/pcxhr.c
index 73de6e9..8309d44 100644
--- a/sound/pci/pcxhr/pcxhr.c
+++ b/sound/pci/pcxhr/pcxhr.c
@@ -653,7 +653,7 @@ static int pcxhr_trigger(struct snd_pcm_substream *subs, int cmd)
 					PCXHR_STREAM_STATUS_SCHEDULE_RUN;
 				snd_pcm_trigger_done(s, subs);
 			}
-			tasklet_hi_schedule(&chip->mgr->trigger_taskq);
+			tasklet_schedule(&chip->mgr->trigger_taskq);
 		} else {
 			stream = subs->runtime->private_data;
 			snd_printdd("Only one Substream %c %d\n",
diff --git a/sound/pci/pcxhr/pcxhr_core.c b/sound/pci/pcxhr/pcxhr_core.c
index 7143259..4a5481f 100644
--- a/sound/pci/pcxhr/pcxhr_core.c
+++ b/sound/pci/pcxhr/pcxhr_core.c
@@ -1213,7 +1213,7 @@ irqreturn_t pcxhr_interrupt(int irq, void *dev_id)
 		mgr->dsp_time_last = PCXHR_DSP_TIME_INVALID;
 		
 		mgr->src_it_dsp = reg;
-		tasklet_hi_schedule(&mgr->msg_taskq);
+		tasklet_schedule(&mgr->msg_taskq);
 	}
 #ifdef CONFIG_SND_DEBUG_VERBOSE
 	if (reg & PCXHR_FATAL_DSP_ERR)
diff --git a/sound/pci/riptide/riptide.c b/sound/pci/riptide/riptide.c
index e9f0706..1d0eeb1 100644
--- a/sound/pci/riptide/riptide.c
+++ b/sound/pci/riptide/riptide.c
@@ -1754,7 +1754,7 @@ snd_riptide_interrupt(int irq, void *dev_id)
 		if (IS_EOBIRQ(cif->hwport) || IS_EOSIRQ(cif->hwport) ||
 		    IS_EOCIRQ(cif->hwport)) {
 			chip->handled_irqs++;
-			tasklet_hi_schedule(&chip->riptide_tq);
+			tasklet_schedule(&chip->riptide_tq);
 		}
 		if (chip->rmidi && IS_MPUIRQ(cif->hwport)) {
 			chip->handled_irqs++;
diff --git a/sound/pci/rme9652/hdsp.c b/sound/pci/rme9652/hdsp.c
index fdd3be5..44d0c15 100644
--- a/sound/pci/rme9652/hdsp.c
+++ b/sound/pci/rme9652/hdsp.c
@@ -3750,7 +3750,7 @@ static irqreturn_t snd_hdsp_interrupt(int irq, void *dev_id)
 		}
 	}
 	if (hdsp->use_midi_tasklet && schedule)
-		tasklet_hi_schedule(&hdsp->midi_tasklet);
+		tasklet_schedule(&hdsp->midi_tasklet);
 	return IRQ_HANDLED;
 }
 
diff --git a/sound/pci/rme9652/hdspm.c b/sound/pci/rme9652/hdspm.c
index dc5c4ba..71231cf 100644
--- a/sound/pci/rme9652/hdspm.c
+++ b/sound/pci/rme9652/hdspm.c
@@ -3476,7 +3476,7 @@ static irqreturn_t snd_hdspm_interrupt(int irq, void *dev_id)
 		schedule = 1;
 	}
 	if (schedule)
-		tasklet_hi_schedule(&hdspm->midi_tasklet);
+		tasklet_schedule(&hdspm->midi_tasklet);
 	return IRQ_HANDLED;
 }
 
diff --git a/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c b/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
index fa4b113..ea903c8 100644
--- a/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
+++ b/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
@@ -41,7 +41,7 @@ irqreturn_t pdacf_interrupt(int irq, void *dev)
 		if (stat & PDAUDIOCF_IRQOVR)	/* should never happen */
 			snd_printk(KERN_ERR "PDAUDIOCF SRAM buffer overrun detected!\n");
 		if (chip->pcm_substream)
-			tasklet_hi_schedule(&chip->tq);
+			tasklet_schedule(&chip->tq);
 		if (!(stat & PDAUDIOCF_IRQAKM))
 			stat |= PDAUDIOCF_IRQAKM;	/* check rate */
 	}
diff --git a/sound/usb/usbmidi.c b/sound/usb/usbmidi.c
index 5962e4b..6d9f9b1 100644
--- a/sound/usb/usbmidi.c
+++ b/sound/usb/usbmidi.c
@@ -880,7 +880,7 @@ static void snd_usbmidi_output_trigger(struct snd_rawmidi_substream *substream,
 				snd_rawmidi_transmit_ack(substream, 1);
 			return;
 		}
-		tasklet_hi_schedule(&port->ep->tasklet);
+		tasklet_schedule(&port->ep->tasklet);
 	}
 }
 

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang (tasklet_hi_schedule?)

[Takashi Iwai]

At Wed, 19 Nov 2008 12:44:23 +0100,
I wrote:
> 
> At Fri, 14 Nov 2008 10:57:10 -0800,
> Fernando Lopez-Lezcano wrote:
> > 
> > On Fri, 2008-11-14 at 09:15 +0100, Clemens Ladisch wrote:
> > > Fernando Lopez-Lezcano wrote:
> > > > I've been trying to follow the printk crumbs without much success.
> > > > AFAICT it all points to tasklet_hi_schedule ...
> > > 
> > > I don't have -rt, but if the error is similar to the old one you might
> > > try replacing tasklet_hi_schedule with tasklet_schedule.
> > 
> > YES YES!! __Thanks__ for the suggestion, it WORKED!!
> > 
> > Maybe the kernel rt gurus should look around and see _why_ the problem
> > was happening in the first place. There are not that many uses of
> > tasklet_hi_schedule in the kernel tree I'm working with:
> (snip)
> > Maybe other drivers are affected as well by the rt patch. 
> > What is the difference between tasklet_hi_schedule and tasklet_schedule?
> 
> AFAIK, tasklet_hi_schedule() uses another softirq vector with the
> highest priority (the first item to be scanned).
> 
> Regarding the ALSA codes, there is no big reason to use hi_* version.
> Could you check the patch below and see whether you get any
> regressions?

Nando, any chance to test on your machines?


thanks,

Takashi

> 
> 
> thanks,
> 
> Takashi
> 
> ---
> diff --git a/sound/core/rawmidi.c b/sound/core/rawmidi.c
> index 39672f6..002777b 100644
> --- a/sound/core/rawmidi.c
> +++ b/sound/core/rawmidi.c
> @@ -151,7 +151,7 @@ static inline void snd_rawmidi_output_trigger(struct snd_rawmidi_substream *subs
>  	if (!substream->opened)
>  		return;
>  	if (up) {
> -		tasklet_hi_schedule(&substream->runtime->tasklet);
> +		tasklet_schedule(&substream->runtime->tasklet);
>  	} else {
>  		tasklet_kill(&substream->runtime->tasklet);
>  		substream->ops->trigger(substream, 0);
> @@ -908,7 +908,7 @@ int snd_rawmidi_receive(struct snd_rawmidi_substream *substream,
>  	}
>  	if (result > 0) {
>  		if (runtime->event)
> -			tasklet_hi_schedule(&runtime->tasklet);
> +			tasklet_schedule(&runtime->tasklet);
>  		else if (snd_rawmidi_ready(substream))
>  			wake_up(&runtime->sleep);
>  	}
> diff --git a/sound/core/rtctimer.c b/sound/core/rtctimer.c
> index 51e64e3..0851cd1 100644
> --- a/sound/core/rtctimer.c
> +++ b/sound/core/rtctimer.c
> @@ -118,7 +118,7 @@ static void rtctimer_tasklet(unsigned long data)
>   */
>  static void rtctimer_interrupt(void *private_data)
>  {
> -	tasklet_hi_schedule(private_data);
> +	tasklet_schedule(private_data);
>  }
>  
>  
> diff --git a/sound/core/timer.c b/sound/core/timer.c
> index c584408..7965320 100644
> --- a/sound/core/timer.c
> +++ b/sound/core/timer.c
> @@ -743,7 +743,7 @@ void snd_timer_interrupt(struct snd_timer * timer, unsigned long ticks_left)
>  	spin_unlock_irqrestore(&timer->lock, flags);
>  
>  	if (use_tasklet)
> -		tasklet_hi_schedule(&timer->task_queue);
> +		tasklet_schedule(&timer->task_queue);
>  }
>  
>  /*
> diff --git a/sound/drivers/vx/vx_core.c b/sound/drivers/vx/vx_core.c
> index 473b07f..14e3354 100644
> --- a/sound/drivers/vx/vx_core.c
> +++ b/sound/drivers/vx/vx_core.c
> @@ -548,7 +548,7 @@ irqreturn_t snd_vx_irq_handler(int irq, void *dev)
>  	    (chip->chip_status & VX_STAT_IS_STALE))
>  		return IRQ_NONE;
>  	if (! vx_test_and_ack(chip))
> -		tasklet_hi_schedule(&chip->tq);
> +		tasklet_schedule(&chip->tq);
>  	return IRQ_HANDLED;
>  }
>  
> diff --git a/sound/drivers/vx/vx_pcm.c b/sound/drivers/vx/vx_pcm.c
> index 27de574..6644d00 100644
> --- a/sound/drivers/vx/vx_pcm.c
> +++ b/sound/drivers/vx/vx_pcm.c
> @@ -823,7 +823,7 @@ static int vx_pcm_trigger(struct snd_pcm_substream *subs, int cmd)
>  		 * we trigger the pipe using tasklet, so that the interrupts are
>  		 * issued surely after the trigger is completed.
>  		 */ 
> -		tasklet_hi_schedule(&pipe->start_tq);
> +		tasklet_schedule(&pipe->start_tq);
>  		chip->pcm_running++;
>  		pipe->running = 1;
>  		break;
> diff --git a/sound/pci/es1968.c b/sound/pci/es1968.c
> index 20ee759..e9c3794 100644
> --- a/sound/pci/es1968.c
> +++ b/sound/pci/es1968.c
> @@ -1953,7 +1953,7 @@ static irqreturn_t snd_es1968_interrupt(int irq, void *dev_id)
>  	outw(inw(chip->io_port + 4) & 1, chip->io_port + 4);
>  
>  	if (event & ESM_HWVOL_IRQ)
> -		tasklet_hi_schedule(&chip->hwvol_tq); /* we'll do this later */
> +		tasklet_schedule(&chip->hwvol_tq); /* we'll do this later */
>  
>  	/* else ack 'em all, i imagine */
>  	outb(0xFF, chip->io_port + 0x1A);
> diff --git a/sound/pci/maestro3.c b/sound/pci/maestro3.c
> index 9ff3f9e..59bbaf8 100644
> --- a/sound/pci/maestro3.c
> +++ b/sound/pci/maestro3.c
> @@ -1670,7 +1670,7 @@ static irqreturn_t snd_m3_interrupt(int irq, void *dev_id)
>  		return IRQ_NONE;
>  
>  	if (status & HV_INT_PENDING)
> -		tasklet_hi_schedule(&chip->hwvol_tq);
> +		tasklet_schedule(&chip->hwvol_tq);
>  
>  	/*
>  	 * ack an assp int if its running
> diff --git a/sound/pci/mixart/mixart_core.c b/sound/pci/mixart/mixart_core.c
> index b9a06c2..d3350f3 100644
> --- a/sound/pci/mixart/mixart_core.c
> +++ b/sound/pci/mixart/mixart_core.c
> @@ -550,7 +550,7 @@ irqreturn_t snd_mixart_interrupt(int irq, void *dev_id)
>  				mgr->msg_fifo[mgr->msg_fifo_writeptr] = msg;
>  				mgr->msg_fifo_writeptr++;
>  				mgr->msg_fifo_writeptr %= MSG_FIFO_SIZE;
> -				tasklet_hi_schedule(&mgr->msg_taskq);
> +				tasklet_schedule(&mgr->msg_taskq);
>  			}
>  			spin_unlock(&mgr->msg_lock);
>  			break;
> diff --git a/sound/pci/pcxhr/pcxhr.c b/sound/pci/pcxhr/pcxhr.c
> index 73de6e9..8309d44 100644
> --- a/sound/pci/pcxhr/pcxhr.c
> +++ b/sound/pci/pcxhr/pcxhr.c
> @@ -653,7 +653,7 @@ static int pcxhr_trigger(struct snd_pcm_substream *subs, int cmd)
>  					PCXHR_STREAM_STATUS_SCHEDULE_RUN;
>  				snd_pcm_trigger_done(s, subs);
>  			}
> -			tasklet_hi_schedule(&chip->mgr->trigger_taskq);
> +			tasklet_schedule(&chip->mgr->trigger_taskq);
>  		} else {
>  			stream = subs->runtime->private_data;
>  			snd_printdd("Only one Substream %c %d\n",
> diff --git a/sound/pci/pcxhr/pcxhr_core.c b/sound/pci/pcxhr/pcxhr_core.c
> index 7143259..4a5481f 100644
> --- a/sound/pci/pcxhr/pcxhr_core.c
> +++ b/sound/pci/pcxhr/pcxhr_core.c
> @@ -1213,7 +1213,7 @@ irqreturn_t pcxhr_interrupt(int irq, void *dev_id)
>  		mgr->dsp_time_last = PCXHR_DSP_TIME_INVALID;
>  		
>  		mgr->src_it_dsp = reg;
> -		tasklet_hi_schedule(&mgr->msg_taskq);
> +		tasklet_schedule(&mgr->msg_taskq);
>  	}
>  #ifdef CONFIG_SND_DEBUG_VERBOSE
>  	if (reg & PCXHR_FATAL_DSP_ERR)
> diff --git a/sound/pci/riptide/riptide.c b/sound/pci/riptide/riptide.c
> index e9f0706..1d0eeb1 100644
> --- a/sound/pci/riptide/riptide.c
> +++ b/sound/pci/riptide/riptide.c
> @@ -1754,7 +1754,7 @@ snd_riptide_interrupt(int irq, void *dev_id)
>  		if (IS_EOBIRQ(cif->hwport) || IS_EOSIRQ(cif->hwport) ||
>  		    IS_EOCIRQ(cif->hwport)) {
>  			chip->handled_irqs++;
> -			tasklet_hi_schedule(&chip->riptide_tq);
> +			tasklet_schedule(&chip->riptide_tq);
>  		}
>  		if (chip->rmidi && IS_MPUIRQ(cif->hwport)) {
>  			chip->handled_irqs++;
> diff --git a/sound/pci/rme9652/hdsp.c b/sound/pci/rme9652/hdsp.c
> index fdd3be5..44d0c15 100644
> --- a/sound/pci/rme9652/hdsp.c
> +++ b/sound/pci/rme9652/hdsp.c
> @@ -3750,7 +3750,7 @@ static irqreturn_t snd_hdsp_interrupt(int irq, void *dev_id)
>  		}
>  	}
>  	if (hdsp->use_midi_tasklet && schedule)
> -		tasklet_hi_schedule(&hdsp->midi_tasklet);
> +		tasklet_schedule(&hdsp->midi_tasklet);
>  	return IRQ_HANDLED;
>  }
>  
> diff --git a/sound/pci/rme9652/hdspm.c b/sound/pci/rme9652/hdspm.c
> index dc5c4ba..71231cf 100644
> --- a/sound/pci/rme9652/hdspm.c
> +++ b/sound/pci/rme9652/hdspm.c
> @@ -3476,7 +3476,7 @@ static irqreturn_t snd_hdspm_interrupt(int irq, void *dev_id)
>  		schedule = 1;
>  	}
>  	if (schedule)
> -		tasklet_hi_schedule(&hdspm->midi_tasklet);
> +		tasklet_schedule(&hdspm->midi_tasklet);
>  	return IRQ_HANDLED;
>  }
>  
> diff --git a/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c b/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
> index fa4b113..ea903c8 100644
> --- a/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
> +++ b/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
> @@ -41,7 +41,7 @@ irqreturn_t pdacf_interrupt(int irq, void *dev)
>  		if (stat & PDAUDIOCF_IRQOVR)	/* should never happen */
>  			snd_printk(KERN_ERR "PDAUDIOCF SRAM buffer overrun detected!\n");
>  		if (chip->pcm_substream)
> -			tasklet_hi_schedule(&chip->tq);
> +			tasklet_schedule(&chip->tq);
>  		if (!(stat & PDAUDIOCF_IRQAKM))
>  			stat |= PDAUDIOCF_IRQAKM;	/* check rate */
>  	}
> diff --git a/sound/usb/usbmidi.c b/sound/usb/usbmidi.c
> index 5962e4b..6d9f9b1 100644
> --- a/sound/usb/usbmidi.c
> +++ b/sound/usb/usbmidi.c
> @@ -880,7 +880,7 @@ static void snd_usbmidi_output_trigger(struct snd_rawmidi_substream *substream,
>  				snd_rawmidi_transmit_ack(substream, 1);
>  			return;
>  		}
> -		tasklet_hi_schedule(&port->ep->tasklet);
> +		tasklet_schedule(&port->ep->tasklet);
>  	}
>  }
>  

Re: [alsa-devel] 2.6.26.[6|7]-rt11, alsa rawmidi, seq hang (tasklet_hi_schedule?)

[Takashi Iwai]

At Thu, 27 Nov 2008 17:50:52 +0100,
I wrote:
> 
> At Wed, 19 Nov 2008 12:44:23 +0100,
> I wrote:
> > 
> > At Fri, 14 Nov 2008 10:57:10 -0800,
> > Fernando Lopez-Lezcano wrote:
> > > 
> > > On Fri, 2008-11-14 at 09:15 +0100, Clemens Ladisch wrote:
> > > > Fernando Lopez-Lezcano wrote:
> > > > > I've been trying to follow the printk crumbs without much success.
> > > > > AFAICT it all points to tasklet_hi_schedule ...
> > > > 
> > > > I don't have -rt, but if the error is similar to the old one you might
> > > > try replacing tasklet_hi_schedule with tasklet_schedule.
> > > 
> > > YES YES!! __Thanks__ for the suggestion, it WORKED!!
> > > 
> > > Maybe the kernel rt gurus should look around and see _why_ the problem
> > > was happening in the first place. There are not that many uses of
> > > tasklet_hi_schedule in the kernel tree I'm working with:
> > (snip)
> > > Maybe other drivers are affected as well by the rt patch. 
> > > What is the difference between tasklet_hi_schedule and tasklet_schedule?
> > 
> > AFAIK, tasklet_hi_schedule() uses another softirq vector with the
> > highest priority (the first item to be scanned).
> > 
> > Regarding the ALSA codes, there is no big reason to use hi_* version.
> > Could you check the patch below and see whether you get any
> > regressions?
> 
> Nando, any chance to test on your machines?

Ping.


Takashi

> > 
> > 
> > thanks,
> > 
> > Takashi
> > 
> > ---
> > diff --git a/sound/core/rawmidi.c b/sound/core/rawmidi.c
> > index 39672f6..002777b 100644
> > --- a/sound/core/rawmidi.c
> > +++ b/sound/core/rawmidi.c
> > @@ -151,7 +151,7 @@ static inline void snd_rawmidi_output_trigger(struct snd_rawmidi_substream *subs
> >  	if (!substream->opened)
> >  		return;
> >  	if (up) {
> > -		tasklet_hi_schedule(&substream->runtime->tasklet);
> > +		tasklet_schedule(&substream->runtime->tasklet);
> >  	} else {
> >  		tasklet_kill(&substream->runtime->tasklet);
> >  		substream->ops->trigger(substream, 0);
> > @@ -908,7 +908,7 @@ int snd_rawmidi_receive(struct snd_rawmidi_substream *substream,
> >  	}
> >  	if (result > 0) {
> >  		if (runtime->event)
> > -			tasklet_hi_schedule(&runtime->tasklet);
> > +			tasklet_schedule(&runtime->tasklet);
> >  		else if (snd_rawmidi_ready(substream))
> >  			wake_up(&runtime->sleep);
> >  	}
> > diff --git a/sound/core/rtctimer.c b/sound/core/rtctimer.c
> > index 51e64e3..0851cd1 100644
> > --- a/sound/core/rtctimer.c
> > +++ b/sound/core/rtctimer.c
> > @@ -118,7 +118,7 @@ static void rtctimer_tasklet(unsigned long data)
> >   */
> >  static void rtctimer_interrupt(void *private_data)
> >  {
> > -	tasklet_hi_schedule(private_data);
> > +	tasklet_schedule(private_data);
> >  }
> >  
> >  
> > diff --git a/sound/core/timer.c b/sound/core/timer.c
> > index c584408..7965320 100644
> > --- a/sound/core/timer.c
> > +++ b/sound/core/timer.c
> > @@ -743,7 +743,7 @@ void snd_timer_interrupt(struct snd_timer * timer, unsigned long ticks_left)
> >  	spin_unlock_irqrestore(&timer->lock, flags);
> >  
> >  	if (use_tasklet)
> > -		tasklet_hi_schedule(&timer->task_queue);
> > +		tasklet_schedule(&timer->task_queue);
> >  }
> >  
> >  /*
> > diff --git a/sound/drivers/vx/vx_core.c b/sound/drivers/vx/vx_core.c
> > index 473b07f..14e3354 100644
> > --- a/sound/drivers/vx/vx_core.c
> > +++ b/sound/drivers/vx/vx_core.c
> > @@ -548,7 +548,7 @@ irqreturn_t snd_vx_irq_handler(int irq, void *dev)
> >  	    (chip->chip_status & VX_STAT_IS_STALE))
> >  		return IRQ_NONE;
> >  	if (! vx_test_and_ack(chip))
> > -		tasklet_hi_schedule(&chip->tq);
> > +		tasklet_schedule(&chip->tq);
> >  	return IRQ_HANDLED;
> >  }
> >  
> > diff --git a/sound/drivers/vx/vx_pcm.c b/sound/drivers/vx/vx_pcm.c
> > index 27de574..6644d00 100644
> > --- a/sound/drivers/vx/vx_pcm.c
> > +++ b/sound/drivers/vx/vx_pcm.c
> > @@ -823,7 +823,7 @@ static int vx_pcm_trigger(struct snd_pcm_substream *subs, int cmd)
> >  		 * we trigger the pipe using tasklet, so that the interrupts are
> >  		 * issued surely after the trigger is completed.
> >  		 */ 
> > -		tasklet_hi_schedule(&pipe->start_tq);
> > +		tasklet_schedule(&pipe->start_tq);
> >  		chip->pcm_running++;
> >  		pipe->running = 1;
> >  		break;
> > diff --git a/sound/pci/es1968.c b/sound/pci/es1968.c
> > index 20ee759..e9c3794 100644
> > --- a/sound/pci/es1968.c
> > +++ b/sound/pci/es1968.c
> > @@ -1953,7 +1953,7 @@ static irqreturn_t snd_es1968_interrupt(int irq, void *dev_id)
> >  	outw(inw(chip->io_port + 4) & 1, chip->io_port + 4);
> >  
> >  	if (event & ESM_HWVOL_IRQ)
> > -		tasklet_hi_schedule(&chip->hwvol_tq); /* we'll do this later */
> > +		tasklet_schedule(&chip->hwvol_tq); /* we'll do this later */
> >  
> >  	/* else ack 'em all, i imagine */
> >  	outb(0xFF, chip->io_port + 0x1A);
> > diff --git a/sound/pci/maestro3.c b/sound/pci/maestro3.c
> > index 9ff3f9e..59bbaf8 100644
> > --- a/sound/pci/maestro3.c
> > +++ b/sound/pci/maestro3.c
> > @@ -1670,7 +1670,7 @@ static irqreturn_t snd_m3_interrupt(int irq, void *dev_id)
> >  		return IRQ_NONE;
> >  
> >  	if (status & HV_INT_PENDING)
> > -		tasklet_hi_schedule(&chip->hwvol_tq);
> > +		tasklet_schedule(&chip->hwvol_tq);
> >  
> >  	/*
> >  	 * ack an assp int if its running
> > diff --git a/sound/pci/mixart/mixart_core.c b/sound/pci/mixart/mixart_core.c
> > index b9a06c2..d3350f3 100644
> > --- a/sound/pci/mixart/mixart_core.c
> > +++ b/sound/pci/mixart/mixart_core.c
> > @@ -550,7 +550,7 @@ irqreturn_t snd_mixart_interrupt(int irq, void *dev_id)
> >  				mgr->msg_fifo[mgr->msg_fifo_writeptr] = msg;
> >  				mgr->msg_fifo_writeptr++;
> >  				mgr->msg_fifo_writeptr %= MSG_FIFO_SIZE;
> > -				tasklet_hi_schedule(&mgr->msg_taskq);
> > +				tasklet_schedule(&mgr->msg_taskq);
> >  			}
> >  			spin_unlock(&mgr->msg_lock);
> >  			break;
> > diff --git a/sound/pci/pcxhr/pcxhr.c b/sound/pci/pcxhr/pcxhr.c
> > index 73de6e9..8309d44 100644
> > --- a/sound/pci/pcxhr/pcxhr.c
> > +++ b/sound/pci/pcxhr/pcxhr.c
> > @@ -653,7 +653,7 @@ static int pcxhr_trigger(struct snd_pcm_substream *subs, int cmd)
> >  					PCXHR_STREAM_STATUS_SCHEDULE_RUN;
> >  				snd_pcm_trigger_done(s, subs);
> >  			}
> > -			tasklet_hi_schedule(&chip->mgr->trigger_taskq);
> > +			tasklet_schedule(&chip->mgr->trigger_taskq);
> >  		} else {
> >  			stream = subs->runtime->private_data;
> >  			snd_printdd("Only one Substream %c %d\n",
> > diff --git a/sound/pci/pcxhr/pcxhr_core.c b/sound/pci/pcxhr/pcxhr_core.c
> > index 7143259..4a5481f 100644
> > --- a/sound/pci/pcxhr/pcxhr_core.c
> > +++ b/sound/pci/pcxhr/pcxhr_core.c
> > @@ -1213,7 +1213,7 @@ irqreturn_t pcxhr_interrupt(int irq, void *dev_id)
> >  		mgr->dsp_time_last = PCXHR_DSP_TIME_INVALID;
> >  		
> >  		mgr->src_it_dsp = reg;
> > -		tasklet_hi_schedule(&mgr->msg_taskq);
> > +		tasklet_schedule(&mgr->msg_taskq);
> >  	}
> >  #ifdef CONFIG_SND_DEBUG_VERBOSE
> >  	if (reg & PCXHR_FATAL_DSP_ERR)
> > diff --git a/sound/pci/riptide/riptide.c b/sound/pci/riptide/riptide.c
> > index e9f0706..1d0eeb1 100644
> > --- a/sound/pci/riptide/riptide.c
> > +++ b/sound/pci/riptide/riptide.c
> > @@ -1754,7 +1754,7 @@ snd_riptide_interrupt(int irq, void *dev_id)
> >  		if (IS_EOBIRQ(cif->hwport) || IS_EOSIRQ(cif->hwport) ||
> >  		    IS_EOCIRQ(cif->hwport)) {
> >  			chip->handled_irqs++;
> > -			tasklet_hi_schedule(&chip->riptide_tq);
> > +			tasklet_schedule(&chip->riptide_tq);
> >  		}
> >  		if (chip->rmidi && IS_MPUIRQ(cif->hwport)) {
> >  			chip->handled_irqs++;
> > diff --git a/sound/pci/rme9652/hdsp.c b/sound/pci/rme9652/hdsp.c
> > index fdd3be5..44d0c15 100644
> > --- a/sound/pci/rme9652/hdsp.c
> > +++ b/sound/pci/rme9652/hdsp.c
> > @@ -3750,7 +3750,7 @@ static irqreturn_t snd_hdsp_interrupt(int irq, void *dev_id)
> >  		}
> >  	}
> >  	if (hdsp->use_midi_tasklet && schedule)
> > -		tasklet_hi_schedule(&hdsp->midi_tasklet);
> > +		tasklet_schedule(&hdsp->midi_tasklet);
> >  	return IRQ_HANDLED;
> >  }
> >  
> > diff --git a/sound/pci/rme9652/hdspm.c b/sound/pci/rme9652/hdspm.c
> > index dc5c4ba..71231cf 100644
> > --- a/sound/pci/rme9652/hdspm.c
> > +++ b/sound/pci/rme9652/hdspm.c
> > @@ -3476,7 +3476,7 @@ static irqreturn_t snd_hdspm_interrupt(int irq, void *dev_id)
> >  		schedule = 1;
> >  	}
> >  	if (schedule)
> > -		tasklet_hi_schedule(&hdspm->midi_tasklet);
> > +		tasklet_schedule(&hdspm->midi_tasklet);
> >  	return IRQ_HANDLED;
> >  }
> >  
> > diff --git a/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c b/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
> > index fa4b113..ea903c8 100644
> > --- a/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
> > +++ b/sound/pcmcia/pdaudiocf/pdaudiocf_irq.c
> > @@ -41,7 +41,7 @@ irqreturn_t pdacf_interrupt(int irq, void *dev)
> >  		if (stat & PDAUDIOCF_IRQOVR)	/* should never happen */
> >  			snd_printk(KERN_ERR "PDAUDIOCF SRAM buffer overrun detected!\n");
> >  		if (chip->pcm_substream)
> > -			tasklet_hi_schedule(&chip->tq);
> > +			tasklet_schedule(&chip->tq);
> >  		if (!(stat & PDAUDIOCF_IRQAKM))
> >  			stat |= PDAUDIOCF_IRQAKM;	/* check rate */
> >  	}
> > diff --git a/sound/usb/usbmidi.c b/sound/usb/usbmidi.c
> > index 5962e4b..6d9f9b1 100644
> > --- a/sound/usb/usbmidi.c
> > +++ b/sound/usb/usbmidi.c
> > @@ -880,7 +880,7 @@ static void snd_usbmidi_output_trigger(struct snd_rawmidi_substream *substream,
> >  				snd_rawmidi_transmit_ack(substream, 1);
> >  			return;
> >  		}
> > -		tasklet_hi_schedule(&port->ep->tasklet);
> > +		tasklet_schedule(&port->ep->tasklet);
> >  	}
> >  }
> >