From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751639AbdAYM2V (ORCPT ); Wed, 25 Jan 2017 07:28:21 -0500 Received: from mx2.suse.de ([195.135.220.15]:43556 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751611AbdAYM2T (ORCPT ); Wed, 25 Jan 2017 07:28:19 -0500 To: Jaroslav Kysela , Takashi Iwai Cc: alsa-devel@alsa-project.org, LKML From: Vlastimil Babka Subject: workqueue lockup due to process_unsol_events stuck in azx_rirb_get_response Message-ID: <855fe8a9-4167-e193-d3d1-45e9d39630b1@suse.cz> Date: Wed, 25 Jan 2017 13:28:11 +0100 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.6.0 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hi, my desktop randomly experiences workqueue lockups on boot with openSUSE Tumbleweed kernels 4.9.x, installed around Christmas. Previously I had a (badly maintained) Gentoo installation with 4.4 IIRC, so I can't say if the kernel has regressed, or the major userspace changes exposed different timing of stuff. This is how the workqueue lockup looks like: kernel: BUG: workqueue lockup - pool cpus=3 node=0 flags=0x0 nice=0 stuck for 173s! kernel: Showing busy workqueues and worker pools: kernel: workqueue events: flags=0x0 kernel: pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=9/256 kernel: in-flight: 60:process_unsol_events [snd_hda_core] process_unsol_events [snd_hda_core] kernel: pending: dbs_work_handler, push_to_pool, vmstat_shepherd, cache_reap, console_callback, sysrq_reinject_alt_sysrq, check_corrup kernel: workqueue events_power_efficient: flags=0x80 kernel: pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256 kernel: pending: neigh_periodic_work kernel: workqueue lru-add-drain: flags=0x8 kernel: pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256 kernel: pending: lru_add_drain_per_cpu BAR(1161) kernel: workqueue vmstat: flags=0xc kernel: pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256 kernel: pending: vmstat_update kernel: workqueue ipv6_addrconf: flags=0x40008 kernel: pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/1 kernel: pending: addrconf_verify_work kernel: pool 6: cpus=3 node=0 flags=0x0 nice=0 hung=173s workers=4 idle: 134 373 30 This prevented me from getting a login prompt, as systemd is waiting for wicked. I have used sysrq to list the stuck tasks: kernel: sysrq: SysRq : Show Blocked State kernel: task PC stack pid father kernel: wickedd-nanny D 0 1161 1 0x00000000 kernel: ffff9f88e3ebc000 0000000000000000 ffff9f88e3506040 ffff9f88efd59780 kernel: ffff9f883ee90100 ffffb2dc81117d28 ffffffffa9715ff6 ffff9f88efd59780 kernel: 00ffb2dc81117d20 ffff9f88efd59780 ffff9f88def44000 ffff9f88e3506040 kernel: Call Trace: kernel: [] ? __schedule+0x236/0x700 kernel: [] schedule+0x3d/0x90 kernel: [] schedule_timeout+0x22e/0x410 kernel: [] ? finish_task_switch+0x78/0x1f0 kernel: [] ? try_to_wake_up+0x4a/0x3d0 kernel: [] wait_for_completion+0x97/0x100 kernel: [] ? wake_up_q+0x80/0x80 kernel: [] flush_work+0xf7/0x190 kernel: [] ? flush_workqueue_prep_pwqs+0x1a0/0x1a0 kernel: [] lru_add_drain_all+0x121/0x160 kernel: [] do_mlock+0x45/0x230 kernel: [] SyS_mlock+0x13/0x20 kernel: [] entry_SYSCALL_64_fastpath+0x1e/0xad Yep, stuck waiting for work item completion, but workqueue processing on cpu 3 is stuck (and contains such item). Then I listed backtraces of all active CPU's: kernel: sysrq: SysRq : Show backtrace of all active CPUs kernel: NMI backtrace for cpu 3 kernel: CPU: 3 PID: 60 Comm: kworker/3:1 Not tainted 4.9.3-1-default #1 kernel: Hardware name: Gigabyte Technology Co., Ltd. GA-870A-UD3/GA-870A-UD3, BIOS F5 08/01/2011 kernel: Workqueue: events process_unsol_events [snd_hda_core] kernel: ffff9f88efcc3a90 ffffffffa93c4f70 0000000000000000 0000000000000003 kernel: ffff9f88efcc3ac0 ffffffffa93c8e44 ffffffffa9055c80 0000000000000003 kernel: 0000000000000001 ffffffffa9cc43c0 ffff9f88efcc3ae0 ffffffffa93c8f66 kernel: Call Trace: kernel: kernel: [] dump_stack+0x63/0x83 kernel: [] nmi_cpu_backtrace+0x94/0xa0 kernel: [] ? irq_force_complete_move+0x150/0x150 kernel: [] nmi_trigger_cpumask_backtrace+0x116/0x150 kernel: [] arch_trigger_cpumask_backtrace+0x19/0x20 kernel: [] sysrq_handle_showallcpus+0x17/0x20 kernel: [] __handle_sysrq+0xfb/0x150 [ snip keyboard event processing ] kernel: [] handle_irq+0x1d/0x30 kernel: [] do_IRQ+0x4b/0xd0 kernel: [] common_interrupt+0x82/0x82 kernel: kernel: [] ? delay_tsc+0x43/0x90 kernel: [] __const_udelay+0x2d/0x30 kernel: [] azx_rirb_get_response+0xb3/0x280 [snd_hda_codec] kernel: [] azx_get_response+0x33/0x40 [snd_hda_codec] kernel: [] snd_hdac_bus_exec_verb_unlocked+0x83/0x170 [snd_hda_core] kernel: [] ? __pm_runtime_resume+0x4c/0x60 kernel: [] codec_exec_verb+0x8a/0x110 [snd_hda_codec] kernel: [] snd_hdac_exec_verb+0x17/0x40 [snd_hda_core] kernel: [] snd_hdac_codec_read+0x34/0x50 [snd_hda_core] kernel: [] dspio_read+0x51/0x70 [snd_hda_codec_ca0132] kernel: [] ca0132_process_dsp_response+0x46/0x160 [snd_hda_codec_ca0132] kernel: [] call_jack_callback.isra.1+0x25/0xa0 [snd_hda_codec] kernel: [] snd_hda_jack_unsol_event+0x66/0x80 [snd_hda_codec] kernel: [] hda_codec_unsol_event+0x17/0x20 [snd_hda_codec] kernel: [] process_unsol_events+0x63/0x70 [snd_hda_core] kernel: [] process_one_work+0x1f3/0x4d0 kernel: [] worker_thread+0x48/0x4e0 kernel: [] ? process_one_work+0x4d0/0x4d0 kernel: [] ? process_one_work+0x4d0/0x4d0 kernel: [] kthread+0xca/0xe0 kernel: [] ? kthread_park+0x60/0x60 kernel: [] ret_from_fork+0x25/0x30 This backtrace looks stable on multiple retries. I've rebooted and added module_blacklist=snd_hda_core on the command line to work around this for now. Here's the relevant lspci. The card I use right now is an onboard audio with 3 output jacks for 5.1. The Creative Audigy is currently unused, as should be the HDMI stuff. 00:14.2 Audio device: Advanced Micro Devices, Inc. [AMD/ATI] SBx00 Azalia (Intel HDA) (rev 40) Subsystem: Gigabyte Technology Co., Ltd Device a102 Flags: bus master, slow devsel, latency 32, IRQ 7, NUMA node 0 Memory at fe024000 (64-bit, non-prefetchable) [size=16K] Capabilities: [50] Power Management version 2 Kernel modules: snd_hda_intel 01:00.1 Audio device: Advanced Micro Devices, Inc. [AMD/ATI] Cape Verde/Pitcairn HDMI Audio [Radeon HD 7700/7800 Series] Subsystem: PC Partner Limited / Sapphire Technology Device aab0 Flags: bus master, fast devsel, latency 0, IRQ 10, NUMA node 0 Memory at fd4fc000 (64-bit, non-prefetchable) [size=16K] Capabilities: [48] Vendor Specific Information: Len=08 Capabilities: [50] Power Management version 3 Capabilities: [58] Express Legacy Endpoint, MSI 00 Capabilities: [a0] MSI: Enable- Count=1/1 Maskable- 64bit+ Capabilities: [100] Vendor Specific Information: ID=0001 Rev=1 Len=010 Capabilities: [150] Advanced Error Reporting Kernel modules: snd_hda_intel 02:00.0 Audio device: Creative Labs Sound Core3D [Sound Blaster Recon3D / Z-Series] (rev 01) Subsystem: Creative Labs SB1570 SB Audigy Fx Flags: bus master, fast devsel, latency 0, IRQ 10, NUMA node 0 Memory at fd3fc000 (64-bit, non-prefetchable) [size=16K] Memory at fd3f8000 (64-bit, non-prefetchable) [size=16K] Capabilities: [40] Power Management version 3 Capabilities: [50] MSI: Enable- Count=1/1 Maskable+ 64bit+ Capabilities: [70] Express Endpoint, MSI 00 Capabilities: [100] Advanced Error Reporting Capabilities: [140] Virtual Channel Capabilities: [170] Device Serial Number 00-00-00-00-00-00-00-00 Capabilities: [180] Power Budgeting Kernel modules: snd_hda_intel Let me know what else to dump or try. Thanks, Vlastimil