From mboxrd@z Thu Jan 1 00:00:00 1970 From: Clemens Ladisch Subject: Re: [PATCH 0/5] RFC v2 for snd-usb endpoint logic rework Date: Sun, 27 Nov 2011 21:32:47 +0100 Message-ID: <4ED29E6F.3010806@ladisch.de> References: <1321646744-13656-1-git-send-email-zonque@gmail.com> <4ED25CE2.4010706@gmail.com> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Return-path: Received: from out2.smtp.messagingengine.com (out2.smtp.messagingengine.com [66.111.4.26]) by alsa0.perex.cz (Postfix) with ESMTP id 5263110384A for ; Sun, 27 Nov 2011 21:33:02 +0100 (CET) Received: from compute6.internal (compute6.nyi.mail.srv.osa [10.202.2.46]) by gateway1.nyi.mail.srv.osa (Postfix) with ESMTP id 1DDD320CE3 for ; Sun, 27 Nov 2011 15:33:00 -0500 (EST) In-Reply-To: <4ED25CE2.4010706@gmail.com> List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: alsa-devel-bounces@alsa-project.org Errors-To: alsa-devel-bounces@alsa-project.org To: Daniel Mack Cc: tiwai@suse.de, blablack@gmail.com, alsa-devel@alsa-project.org, gdiffey@gmail.com, linuxaudio@showlabor.de List-Id: alsa-devel@alsa-project.org Daniel Mack wrote: > Did anyone find some time to test this, also with 'regular' USB devices? With an Edirol UA-1A (stereo, 16 bits, 44.1 kHz, adaptive), the first attempt to start playback fails (no sound), but the program can be exited: 5:1:1: add audio endpoint 0x1 5:2:1: add audio endpoint 0x82 usbcore: registered new interface driver snd-usb-audio Creating new playback data endpoint #1 snd_usb_add_endpoint() calling usb_set_interface() snd_usb_hw_params(): format changed stop_endpoints(ffff880212680018,0,1) -- data ffff880213470000 -- sync (null) is_playback? 1 impf 0, total_packs 24 urb_packs 8 ep ffff880213470000:: buffer_size 1536 maxsize 192 packets 8 ep ffff880213470000:: buffer_size 1536 maxsize 192 packets 8 ep ffff880213470000:: buffer_size 1536 maxsize 192 packets 8 Setting params for ep #1 (type 0, 3 urbs) -> 0 Returning from snd_usb_hw_params() with 0 activate_endpoints(ffff880212680018) snd_usb_endpoint_activate() calling usb_set_interface(1,1) Starting data EP @ffff880213470000 snd_usb_endpoint_start(): pipein? 0, impl? 0 Submmiting urb 0/3 (in? 0 buf ffff8800df822000 len 1408) ret (0) Submmiting urb 1/3 (in? 0 buf ffff8800df823000 len 1412) ret (0) Submmiting urb 2/3 (in? 0 buf ffff8800df824000 len 1412) ret (0) ================================= [ INFO: inconsistent lock state ] 3.2.0-rc2+ #319 --------------------------------- inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage. mplayer/1605 [HC1[1]:SC0[0]:HE0:SE1] takes: (&(&ep->lock)->rlock){?.+...}, at: [] prepare_outbound_urb_sizes+0x3f/0x9b [snd_usb_audio] {HARDIRQ-ON-W} state was registered at: [] __lock_acquire+0x6eb/0x8f7 [] lock_acquire+0x57/0x6d [] _raw_spin_lock+0x3b/0x4a [] snd_usb_endpoint_start+0x8d/0x3c4 [snd_usb_audio] [] start_endpoints+0x54/0xb9 [snd_usb_audio] [] snd_usb_pcm_prepare+0x13d/0x141 [snd_usb_audio] [] snd_pcm_do_prepare+0x16/0x28 [snd_pcm] [] snd_pcm_action_single+0x2e/0x65 [snd_pcm] [] snd_pcm_action_nonatomic+0x4a/0x63 [snd_pcm] [] snd_pcm_common_ioctl1+0x419/0xaf3 [snd_pcm] [] snd_pcm_playback_ioctl1+0x25c/0x279 [snd_pcm] [] snd_pcm_playback_ioctl+0x2a/0x2e [snd_pcm] [] do_vfs_ioctl+0x47f/0x4ce [] sys_ioctl+0x42/0x65 [] system_call_fastpath+0x16/0x1b irq event stamp: 109796 hardirqs last enabled at (109795): [] retint_swapgs+0xe/0x13 hardirqs last disabled at (109796): [] common_interrupt+0x6b/0x70 softirqs last enabled at (109792): [] __do_softirq+0x135/0x14b softirqs last disabled at (109787): [] call_softirq+0x1c/0x30 other info that might help us debug this: Possible unsafe locking scenario: CPU0 ---- lock(&(&ep->lock)->rlock); lock(&(&ep->lock)->rlock); *** DEADLOCK *** no locks held by mplayer/1605. stack backtrace: Pid: 1605, comm: mplayer Not tainted 3.2.0-rc2+ #319 Call Trace: [] ? console_unlock+0x1b2/0x200 [] print_usage_bug+0x296/0x2a7 [] ? save_stack_trace+0x2a/0x47 [] ? print_irq_inversion_bug+0x1d6/0x1d6 [] mark_lock+0x2f1/0x528 [] __lock_acquire+0x672/0x8f7 [] lock_acquire+0x57/0x6d [] ? prepare_outbound_urb_sizes+0x3f/0x9b [snd_usb_audio] [] _raw_spin_lock_irqsave+0x46/0x58 [] ? prepare_outbound_urb_sizes+0x3f/0x9b [snd_usb_audio] [] prepare_outbound_urb_sizes+0x3f/0x9b [snd_usb_audio] [] snd_complete_urb+0x1f3/0x209 [snd_usb_audio] [] usb_hcd_giveback_urb+0x8c/0xc0 [] ehci_urb_done+0xf7/0x10c [ehci_hcd] [] ehci_work+0x7e3/0x9c0 [ehci_hcd] [] ehci_irq+0x317/0x348 [ehci_hcd] [] ? trace_hardirqs_on+0xd/0xf [] ? _raw_spin_unlock_irq+0x2b/0x40 [] ? run_timer_softirq+0x288/0x29a [] ? __lock_acquire+0x886/0x8f7 [] ? sched_clock_local+0x1c/0x82 [] usb_hcd_irq+0x2f/0x7a [] handle_irq_event_percpu+0x29/0x124 [] handle_irq_event+0x3c/0x5c [] handle_edge_irq+0xc7/0xec [] handle_irq+0x83/0x8c [] do_IRQ+0x48/0xaf [] common_interrupt+0x70/0x70 [] ? retint_swapgs+0xe/0x13 cannot submit urb (err = -27) cannot submit urb (err = -27) cannot submit urb (err = -27) snd_usb_substream_playback_trigger(): cmd 1 START! snd_usb_substream_playback_trigger(): cmd 0 stop_endpoints(ffff880212680018,0,0) stop_endpoints(ffff880212680018,0,1) stop_endpoints(ffff880212680018,0,1) stop_endpoints(ffff880212680018,1,1) deactivate_endpoints(ffff880212680018) snd_usb_endpoint_deactivate() calling usb_set_interface(1,0) The following attempt succeeds at playing, but when I seek in the file (stop/prepare/start without hw_params), sound becomes somewhat corrupted (wrong packet sizes I'd guess), and the computer hangs when I attempt to exit the program: Re-using EP 1 in iface 1,1 @ffff880213470000 snd_usb_hw_params(): format changed stop_endpoints(ffff880212680018,0,1) -- data ffff880213470000 -- sync (null) is_playback? 1 impf 0, total_packs 24 urb_packs 8 ep ffff880213470000:: buffer_size 1536 maxsize 192 packets 8 ep ffff880213470000:: buffer_size 1536 maxsize 192 packets 8 ep ffff880213470000:: buffer_size 1536 maxsize 192 packets 8 Setting params for ep #1 (type 0, 3 urbs) -> 0 Returning from snd_usb_hw_params() with 0 activate_endpoints(ffff880212680018) snd_usb_endpoint_activate() calling usb_set_interface(1,1) Starting data EP @ffff880213470000 snd_usb_endpoint_start(): pipein? 0, impl? 0 Submmiting urb 0/3 (in? 0 buf ffff8800df85d000 len 1408) ret (0) Submmiting urb 1/3 (in? 0 buf ffff8800df85e000 len 1412) ret (0) Submmiting urb 2/3 (in? 0 buf ffff8800df85f000 len 1412) ret (0) snd_usb_substream_playback_trigger(): cmd 1 START! [...] INFO: rcu_sched detected stalls on CPUs/tasks: { 4 5} (detected by 2, t=15002 jiffies) Pid: 0, comm: kworker/0:1 Not tainted 3.2.0-rc2+ #319 Call Trace: [] __rcu_pending+0x228/0x34e [] ? tick_nohz_handler+0xcc/0xcc [] rcu_check_callbacks+0xbb/0xed [] update_process_times+0x3c/0x73 [] tick_sched_timer+0x6d/0x8d [] __run_hrtimer+0x75/0xd0 [] hrtimer_interrupt+0xdb/0x1b6 [] ? account_system_vtime+0x88/0x96 [] smp_apic_timer_interrupt+0x81/0x94 [] apic_timer_interrupt+0x70/0x80 [] ? tick_broadcast_oneshot_control+0x5f/0x10a [] ? clockevents_register_device+0xbb/0x138 [] ? default_idle+0x27/0x43 [] ? default_idle+0x29/0x43 [] ? default_idle+0x27/0x43 [] amd_e400_idle+0xcd/0xf4 [] cpu_idle+0x73/0xb3 [] start_secondary+0x225/0x227 Regards, Clemens