Bug 106525 - [CI][IGT] DRM-Tip 4.17-rc5 RIP: 0010:snd_hdac_display_power dmesg splat
Summary: [CI][IGT] DRM-Tip 4.17-rc5 RIP: 0010:snd_hdac_display_power dmesg splat
Status: REOPENED
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: unspecified
Hardware: x86-64 (AMD64) Linux (All)
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks:
 
Reported: 2018-05-15 09:32 UTC by Tomi Sarvela
Modified: 2018-12-09 09:35 UTC (History)
2 users (show)

See Also:
i915 platform: GLK
i915 features: display/audio


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Tomi Sarvela 2018-05-15 09:32:03 UTC
Starting around DRM-Tip 4.17-rc5 pull there has been audio issue on GLK:

[ 1074.839296] WARNING: CPU: 1 PID: 5719 at sound/hda/hdac_i915.c:92 snd_hdac_display_power+0xdc/0x100 [snd_hda_core]
[ 1074.839331] Modules linked in: snd_hda_intel i915 i2c_dev vgem btusb btrtl x86_pkg_temp_thermal btbcm intel_powerclamp coretemp btintel snd_hda_codec_hdmi crct10dif_pclmul crc32_pclmul snd_hda_codec_realtek ghash_clmulni_intel snd_hda_codec_generic bluetooth ecdh_generic r8169 mii i2c_hid snd_hda_codec snd_hwdep snd_hda_core snd_pcm mei_me pinctrl_geminilake pinctrl_intel mei prime_numbers [last unloaded: i915]
[ 1074.839421] CPU: 1 PID: 5719 Comm: drv_module_relo Tainted: G     U  W         4.17.0-rc5-CI-CI_DRM_4180+ #1
[ 1074.839424] Hardware name: Intel Corporation NUC7CJYH/NUC7JYB, BIOS JYGLKCPX.86A.0027.2018.0125.1347 01/25/2018
[ 1074.839431] RIP: 0010:snd_hdac_display_power+0xdc/0x100 [snd_hda_core]
[ 1074.839434] RSP: 0018:ffffc90000047c70 EFLAGS: 00010246
[ 1074.839440] RAX: 00000000ffffffff RBX: ffff880267e80008 RCX: 0000000000000000
[ 1074.839443] RDX: 0000000080000001 RSI: 0000000000000000 RDI: ffff880267e80008
[ 1074.839446] RBP: 0000000000000000 R08: 00000000c44ddc93 R09: 0000000000000000
[ 1074.839448] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 1074.839451] R13: ffff880273fc8198 R14: 0000000000000060 R15: ffff880271643878
[ 1074.839455] FS:  00007f8eb260a980(0000) GS:ffff88027fc80000(0000) knlGS:0000000000000000
[ 1074.839458] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1074.839461] CR2: 00007efe0c420618 CR3: 0000000175ec2000 CR4: 0000000000340ee0
[ 1074.839463] Call Trace:
[ 1074.839478]  snd_hda_codec_dev_free+0x1e/0x30 [snd_hda_codec]
[ 1074.839486]  __snd_device_free+0x4c/0x80
[ 1074.839491]  snd_device_free_all+0x26/0x40
[ 1074.839496]  release_card_device+0x14/0x70
[ 1074.839503]  device_release+0x2b/0x80
[ 1074.839509]  kobject_put+0x85/0x1a0
[ 1074.839514]  snd_card_free+0x60/0x90
[ 1074.839527]  pci_device_remove+0x36/0xb0
[ 1074.839534]  device_release_driver_internal+0x15d/0x220
[ 1074.839541]  unbind_store+0x7f/0x150
[ 1074.839549]  kernfs_fop_write+0x104/0x190
[ 1074.839557]  __vfs_write+0x31/0x160
[ 1074.839565]  ? rcu_read_lock_sched_held+0x6f/0x80
[ 1074.839570]  ? rcu_sync_lockdep_assert+0x29/0x50
[ 1074.839574]  ? __sb_start_write+0x152/0x1f0
[ 1074.839577]  ? __sb_start_write+0x168/0x1f0
[ 1074.839584]  vfs_write+0xbd/0x1a0
[ 1074.839591]  ksys_write+0x50/0xc0
[ 1074.839600]  do_syscall_64+0x55/0x190
[ 1074.839605]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 1074.839609] RIP: 0033:0x7f8eb1fa2281
[ 1074.839612] RSP: 002b:00007ffd2e243e28 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 1074.839617] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f8eb1fa2281
[ 1074.839620] RDX: 000000000000000c RSI: 000055d00d15865b RDI: 0000000000000003
[ 1074.839623] RBP: 00007ffd2e244f10 R08: 000055d00d15865b R09: 000000000000000c
[ 1074.839626] R10: 00000000fffffff4 R11: 0000000000000246 R12: 000055d00b4532f0
[ 1074.839629] R13: 00007ffd2e2450d0 R14: 0000000000000000 R15: 0000000000000000
[ 1074.839644] Code: 7d 00 48 8b 40 08 e8 a4 3e b9 e1 be 01 00 00 00 48 89 df e8 a7 fe ff ff 31 f6 48 89 df e8 9d fe ff ff 5b 89 e8 5d 41 5c 41 5d c3 <0f> 0b c7 83 50 05 00 00 ff ff ff ff eb e9 bd ed ff ff ff eb e2 
[ 1074.839806] irq event stamp: 113490
[ 1074.839811] hardirqs last  enabled at (113489): [<ffffffff8192fae4>] _raw_spin_unlock_irq+0x24/0x50
[ 1074.839815] hardirqs last disabled at (113490): [<ffffffff81a0111c>] error_entry+0x7c/0x100
[ 1074.839819] softirqs last  enabled at (113438): [<ffffffff817e49fc>] peernet2id+0x4c/0x70
[ 1074.839823] softirqs last disabled at (113436): [<ffffffff817e49dd>] peernet2id+0x2d/0x70
[ 1074.839830] WARNING: CPU: 1 PID: 5719 at sound/hda/hdac_i915.c:92 snd_hdac_display_power+0xdc/0x100 [snd_hda_core]
[ 1074.839832] ---[ end trace 5c2b8c3cccbaf58d ]---
[ 1074.860525] WARNING: CPU: 1 PID: 5719 at sound/hda/hdac_i915.c:429 snd_hdac_i915_exit+0x54/0x80 [snd_hda_core]
[ 1074.860529] Modules linked in: snd_hda_intel i915 i2c_dev vgem btusb btrtl x86_pkg_temp_thermal btbcm intel_powerclamp coretemp btintel snd_hda_codec_hdmi crct10dif_pclmul crc32_pclmul snd_hda_codec_realtek ghash_clmulni_intel snd_hda_codec_generic bluetooth ecdh_generic r8169 mii i2c_hid snd_hda_codec snd_hwdep snd_hda_core snd_pcm mei_me pinctrl_geminilake pinctrl_intel mei prime_numbers [last unloaded: i915]
[ 1074.860620] CPU: 1 PID: 5719 Comm: drv_module_relo Tainted: G     U  W         4.17.0-rc5-CI-CI_DRM_4180+ #1
[ 1074.860623] Hardware name: Intel Corporation NUC7CJYH/NUC7JYB, BIOS JYGLKCPX.86A.0027.2018.0125.1347 01/25/2018
[ 1074.860631] RIP: 0010:snd_hdac_i915_exit+0x54/0x80 [snd_hda_core]
[ 1074.860634] RSP: 0018:ffffc90000047c70 EFLAGS: 00010286
[ 1074.860639] RAX: 00000000ffffffff RBX: ffff880267e80008 RCX: dda7912200000000
[ 1074.860642] RDX: 0000000000000000 RSI: 00000000a53e3294 RDI: ffff880267e80008
[ 1074.860645] RBP: ffff880273fc8198 R08: 00000000c44ddc93 R09: 0000000000000001
[ 1074.860648] R10: 0000000000000000 R11: 0000000000000000 R12: ffff880275dca348
[ 1074.860651] R13: ffffffffa0086210 R14: 0000000000000060 R15: ffff880271643878
[ 1074.860654] FS:  00007f8eb260a980(0000) GS:ffff88027fc80000(0000) knlGS:0000000000000000
[ 1074.860657] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1074.860660] CR2: 00007efe0c5934f0 CR3: 0000000175ec2000 CR4: 0000000000340ee0
[ 1074.860663] Call Trace:
[ 1074.860672]  azx_free+0x100/0x170 [snd_hda_intel]
[ 1074.860681]  __snd_device_free+0x4c/0x80
[ 1074.860686]  snd_device_free_all+0x26/0x40
[ 1074.860691]  release_card_device+0x14/0x70
[ 1074.860698]  device_release+0x2b/0x80
[ 1074.860704]  kobject_put+0x85/0x1a0
[ 1074.860710]  snd_card_free+0x60/0x90
[ 1074.860723]  pci_device_remove+0x36/0xb0
[ 1074.860730]  device_release_driver_internal+0x15d/0x220
[ 1074.860737]  unbind_store+0x7f/0x150
[ 1074.860745]  kernfs_fop_write+0x104/0x190
[ 1074.860753]  __vfs_write+0x31/0x160
[ 1074.860762]  ? rcu_read_lock_sched_held+0x6f/0x80
[ 1074.860766]  ? rcu_sync_lockdep_assert+0x29/0x50
[ 1074.860770]  ? __sb_start_write+0x152/0x1f0
[ 1074.860774]  ? __sb_start_write+0x168/0x1f0
[ 1074.860781]  vfs_write+0xbd/0x1a0
[ 1074.860787]  ksys_write+0x50/0xc0
[ 1074.860796]  do_syscall_64+0x55/0x190
[ 1074.860802]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 1074.860806] RIP: 0033:0x7f8eb1fa2281
[ 1074.860809] RSP: 002b:00007ffd2e243e28 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 1074.860814] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f8eb1fa2281
[ 1074.860817] RDX: 000000000000000c RSI: 000055d00d15865b RDI: 0000000000000003
[ 1074.860820] RBP: 00007ffd2e244f10 R08: 000055d00d15865b R09: 000000000000000c
[ 1074.860823] R10: 00000000fffffff4 R11: 0000000000000246 R12: 000055d00b4532f0
[ 1074.860825] R13: 00007ffd2e2450d0 R14: 0000000000000000 R15: 0000000000000000
[ 1074.860841] Code: e7 e8 31 02 5b e1 48 89 ef e8 49 8a 18 e1 48 c7 83 48 05 00 00 00 00 00 00 48 c7 05 e3 9b 00 00 00 00 00 00 5b 31 c0 5d 41 5c c3 <0f> 0b 85 c0 7e c6 48 8b 45 20 48 85 c0 74 bd 48 8b 40 10 48 8b 
[ 1074.861003] irq event stamp: 128048
[ 1074.861007] hardirqs last  enabled at (128047): [<ffffffff8110b4dd>] __call_rcu.constprop.52+0x11d/0x250
[ 1074.861011] hardirqs last disabled at (128048): [<ffffffff81a0111c>] error_entry+0x7c/0x100
[ 1074.861015] softirqs last  enabled at (126250): [<ffffffff81c0032b>] __do_softirq+0x32b/0x4e1
[ 1074.861021] softirqs last disabled at (126243): [<ffffffff8108b954>] irq_exit+0xa4/0xb0
[ 1074.861028] WARNING: CPU: 1 PID: 5719 at sound/hda/hdac_i915.c:429 snd_hdac_i915_exit+0x54/0x80 [snd_hda_core]
[ 1074.861031] ---[ end trace 5c2b8c3cccbaf58e ]---
[ 1075.309072] [drm] GuC: No firmware known for this platform!
[ 1075.309092] [drm] HuC: No firmware known for this platform!
[ 1075.684387] Setting dangerous option reset - tainting kernel
[ 1076.419213] [drm] GuC: No firmware known for this platform!
[ 1076.419232] [drm] HuC: No firmware known for this platform!
[ 1076.857264] Setting dangerous option reset - tainting kernel
Comment 1 Martin Peres 2018-06-15 09:05:23 UTC
Seen twice with 4 runs in between, then nothing since CI_DRM_4182_full (1 month / 583 runs ago). Closing now!
Comment 2 Jani Saarinen 2018-06-19 14:25:48 UTC
Closing, thanks.
Comment 3 Martin Peres 2018-07-16 13:00:46 UTC
And it's back! 

https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4545/shard-glk6/igt@drv_module_reload@basic-reload-inject.html

[ 1908.592041] WARNING: CPU: 0 PID: 25958 at sound/hda/hdac_i915.c:92 snd_hdac_display_power+0xdc/0x100 [snd_hda_core]
[ 1908.592064] Modules linked in: vgem snd_hda_intel i915 btusb btrtl btbcm btintel x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul bluetooth ghash_clmulni_intel snd_hda_codec_hdmi ecdh_generic snd_hda_codec_realtek snd_hda_codec_generic r8169 mii i2c_hid snd_hda_codec snd_hwdep snd_hda_core snd_pcm mei_me pinctrl_geminilake mei pinctrl_intel prime_numbers [last unloaded: test_drm_mm]
[ 1908.592154] CPU: 0 PID: 25958 Comm: drv_module_relo Tainted: G     U  W         4.18.0-rc4-CI-CI_DRM_4463+ #1
[ 1908.592170] Hardware name: Intel Corporation NUC7CJYH/NUC7JYB, BIOS JYGLKCPX.86A.0027.2018.0125.1347 01/25/2018
[ 1908.592189] RIP: 0010:snd_hdac_display_power+0xdc/0x100 [snd_hda_core]
[ 1908.592200] Code: 00 48 8b 40 08 e8 54 3e bb e1 be 01 00 00 00 48 89 df e8 a7 fe ff ff 31 f6 48 89 df e8 9d fe ff ff 5b 89 e8 5d 41 5c 41 5d c3 <0f> 0b c7 83 58 05 00 00 ff ff ff ff eb e9 bd ed ff ff ff eb e2 0f 
[ 1908.592293] RSP: 0018:ffffc90000453c68 EFLAGS: 00010246
[ 1908.592304] RAX: 00000000ffffffff RBX: ffff880463c9a2a8 RCX: dead000000000200
[ 1908.592315] RDX: ffff88045c347778 RSI: 0000000000000000 RDI: ffff880463c9a2a8
[ 1908.592327] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[ 1908.592338] R10: ffffc900004539f0 R11: ffffffff822463e0 R12: 0000000000000000
[ 1908.592349] R13: ffff88045c346198 R14: 0000000000000060 R15: ffff880466948d68
[ 1908.592361] FS:  00007f61a9dd3980(0000) GS:ffff88047fc00000(0000) knlGS:0000000000000000
[ 1908.592374] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1908.592384] CR2: 00007f4c85619cb0 CR3: 000000045af9a000 CR4: 0000000000340ef0
[ 1908.592395] Call Trace:
[ 1908.592411]  snd_hda_codec_dev_free+0x1e/0x30 [snd_hda_codec]
[ 1908.592427]  __snd_device_free+0x4c/0x80
[ 1908.592436]  snd_device_free_all+0x36/0x80
[ 1908.592447]  release_card_device+0x14/0x70
[ 1908.592458]  device_release+0x2b/0x80
[ 1908.592468]  kobject_put+0x85/0x1a0
[ 1908.592477]  snd_card_free+0x60/0x90
[ 1908.592490]  pci_device_remove+0x36/0xb0
[ 1908.592500]  device_release_driver_internal+0x185/0x250
[ 1908.592511]  unbind_store+0xaf/0x180
[ 1908.592522]  kernfs_fop_write+0x104/0x190
[ 1908.592534]  __vfs_write+0x31/0x180
[ 1908.592545]  ? rcu_sync_lockdep_assert+0x9/0x50
[ 1908.592554]  ? __sb_start_write+0x152/0x1f0
[ 1908.592563]  ? __sb_start_write+0x168/0x1f0
[ 1908.592573]  vfs_write+0xbd/0x1a0
[ 1908.592582]  ksys_write+0x50/0xc0
[ 1908.592592]  do_syscall_64+0x55/0x190
[ 1908.592603]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 1908.592613] RIP: 0033:0x7f61a9768281
[ 1908.592619] Code: c3 0f 1f 84 00 00 00 00 00 48 8b 05 59 8d 20 00 c3 0f 1f 84 00 00 00 00 00 8b 05 8a d1 20 00 85 c0 75 16 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 57 f3 c3 0f 1f 44 00 00 41 54 55 49 89 d4 53 
[ 1908.592713] RSP: 002b:00007ffcba509ed8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 1908.592726] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f61a9768281
[ 1908.592738] RDX: 000000000000000c RSI: 000055c1c48ec5cb RDI: 0000000000000003
[ 1908.592749] RBP: 00007ffcba50afc0 R08: 000055c1c48ec5cb R09: 000000000000000c
[ 1908.592760] R10: 00000000fffffff4 R11: 0000000000000246 R12: 000055c1c2b2d2f0
[ 1908.592772] R13: 00007ffcba50b180 R14: 0000000000000000 R15: 0000000000000000
[ 1908.592788] irq event stamp: 0
[ 1908.592795] hardirqs last  enabled at (0): [<0000000000000000>]           (null)
[ 1908.592809] hardirqs last disabled at (0): [<ffffffff810821f2>] copy_process.part.7+0x322/0x1db0
[ 1908.592824] softirqs last  enabled at (0): [<ffffffff810821f2>] copy_process.part.7+0x322/0x1db0
[ 1908.592837] softirqs last disabled at (0): [<0000000000000000>]           (null)
[ 1908.592854] WARNING: CPU: 0 PID: 25958 at sound/hda/hdac_i915.c:92 snd_hdac_display_power+0xdc/0x100 [snd_hda_core]
[ 1908.592869] ---[ end trace 6a4649e26d94cfa2 ]---
[ 1908.602549] WARNING: CPU: 0 PID: 25958 at sound/hda/hdac_i915.c:429 snd_hdac_i915_exit+0x54/0x80 [snd_hda_core]
[ 1908.602571] Modules linked in: vgem snd_hda_intel i915 btusb btrtl btbcm btintel x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul bluetooth ghash_clmulni_intel snd_hda_codec_hdmi ecdh_generic snd_hda_codec_realtek snd_hda_codec_generic r8169 mii i2c_hid snd_hda_codec snd_hwdep snd_hda_core snd_pcm mei_me pinctrl_geminilake mei pinctrl_intel prime_numbers [last unloaded: test_drm_mm]
[ 1908.602662] CPU: 0 PID: 25958 Comm: drv_module_relo Tainted: G     U  W         4.18.0-rc4-CI-CI_DRM_4463+ #1
[ 1908.602677] Hardware name: Intel Corporation NUC7CJYH/NUC7JYB, BIOS JYGLKCPX.86A.0027.2018.0125.1347 01/25/2018
[ 1908.602697] RIP: 0010:snd_hdac_i915_exit+0x54/0x80 [snd_hda_core]
[ 1908.602707] Code: e8 91 6e 5d e1 48 89 ef e8 c9 c0 1a e1 48 c7 83 50 05 00 00 00 00 00 00 48 c7 05 93 9b 00 00 00 00 00 00 5b 31 c0 5d 41 5c c3 <0f> 0b 85 c0 7e c6 48 8b 45 20 48 85 c0 74 bd 48 8b 40 10 48 8b 7d 
[ 1908.602799] RSP: 0018:ffffc90000453c68 EFLAGS: 00010286
[ 1908.602810] RAX: 00000000ffffffff RBX: ffff880463c9a2a8 RCX: 00000000ffffffe6
[ 1908.602821] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff880463c9a2a8
[ 1908.602832] RBP: ffff88045c346198 R08: 0000000000000000 R09: 0000000000000000
[ 1908.602844] R10: 0000000000000000 R11: ffffffff837482c0 R12: ffff88046ce22348
[ 1908.602855] R13: ffff880463c9e7e8 R14: 0000000000000060 R15: ffff880466948d68
[ 1908.602867] FS:  00007f61a9dd3980(0000) GS:ffff88047fc00000(0000) knlGS:0000000000000000
[ 1908.602880] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1908.602890] CR2: 000055ab55e5a35f CR3: 000000045af9a000 CR4: 0000000000340ef0
[ 1908.602901] Call Trace:
[ 1908.602912]  azx_free+0x100/0x170 [snd_hda_intel]
[ 1908.602926]  __snd_device_free+0x4c/0x80
[ 1908.602935]  snd_device_free_all+0x5a/0x80
[ 1908.602946]  release_card_device+0x14/0x70
[ 1908.602956]  device_release+0x2b/0x80
[ 1908.602967]  kobject_put+0x85/0x1a0
[ 1908.602976]  snd_card_free+0x60/0x90
[ 1908.602988]  pci_device_remove+0x36/0xb0
[ 1908.602999]  device_release_driver_internal+0x185/0x250
[ 1908.603010]  unbind_store+0xaf/0x180
[ 1908.603021]  kernfs_fop_write+0x104/0x190
[ 1908.603032]  __vfs_write+0x31/0x180
[ 1908.603043]  ? rcu_sync_lockdep_assert+0x9/0x50
[ 1908.603053]  ? __sb_start_write+0x152/0x1f0
[ 1908.603062]  ? __sb_start_write+0x168/0x1f0
[ 1908.603071]  vfs_write+0xbd/0x1a0
[ 1908.603080]  ksys_write+0x50/0xc0
[ 1908.603091]  do_syscall_64+0x55/0x190
[ 1908.603101]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 1908.603110] RIP: 0033:0x7f61a9768281
[ 1908.603117] Code: c3 0f 1f 84 00 00 00 00 00 48 8b 05 59 8d 20 00 c3 0f 1f 84 00 00 00 00 00 8b 05 8a d1 20 00 85 c0 75 16 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 57 f3 c3 0f 1f 44 00 00 41 54 55 49 89 d4 53 
[ 1908.603210] RSP: 002b:00007ffcba509ed8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 1908.603224] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f61a9768281
[ 1908.603235] RDX: 000000000000000c RSI: 000055c1c48ec5cb RDI: 0000000000000003
[ 1908.603247] RBP: 00007ffcba50afc0 R08: 000055c1c48ec5cb R09: 000000000000000c
[ 1908.603258] R10: 00000000fffffff4 R11: 0000000000000246 R12: 000055c1c2b2d2f0
[ 1908.603269] R13: 00007ffcba50b180 R14: 0000000000000000 R15: 0000000000000000
[ 1908.603285] irq event stamp: 0
[ 1908.603293] hardirqs last  enabled at (0): [<0000000000000000>]           (null)
[ 1908.603307] hardirqs last disabled at (0): [<ffffffff810821f2>] copy_process.part.7+0x322/0x1db0
[ 1908.603321] softirqs last  enabled at (0): [<ffffffff810821f2>] copy_process.part.7+0x322/0x1db0
[ 1908.603335] softirqs last disabled at (0): [<0000000000000000>]           (null)
[ 1908.603351] WARNING: CPU: 0 PID: 25958 at sound/hda/hdac_i915.c:429 snd_hdac_i915_exit+0x54/0x80 [snd_hda_core]
[ 1908.603367] ---[ end trace 6a4649e26d94cfa3 ]---
Comment 4 Martin Peres 2018-09-12 09:54:18 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4640/shard-glk1/igt@pm_rpm@dpms-non-lpsp.html

https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4640/shard-glk1/igt@pm_rpm@gem-evict-pwrite.html

https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4640/shard-glk1/igt@perf_pmu@rc6-runtime-pm-long.html

https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4640/shard-glk1/igt@pm_rpm@gem-pread.html

[  912.357709] WARNING: CPU: 0 PID: 6649 at sound/hda/hdac_component.c:85 snd_hdac_display_power+0xe6/0x100 [snd_hda_core]
[  912.357724] Modules linked in: vgem snd_hda_intel i915 snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic btusb btrtl btbcm x86_pkg_temp_thermal coretemp btintel crct10dif_pclmul crc32_pclmul ghash_clmulni_intel bluetooth ecdh_generic i2c_hid snd_hda_codec snd_hwdep snd_hda_core snd_pcm pinctrl_geminilake pinctrl_intel r8169 mei_me mei prime_numbers [last unloaded: test_drm_mm]
[  912.357830] CPU: 0 PID: 6649 Comm: kworker/0:0 Tainted: G     U  W         4.19.0-rc3-CI-CI_DRM_4807+ #1
[  912.357837] Hardware name: Intel Corporation NUC7CJYH/NUC7JYB, BIOS JYGLKCPX.86A.0027.2018.0125.1347 01/25/2018
[  912.357851] Workqueue: pm pm_runtime_work
[  912.357872] RIP: 0010:snd_hdac_display_power+0xe6/0x100 [snd_hda_core]
[  912.357881] Code: 09 49 8b 7d 00 e8 0a 33 b4 e1 be 01 00 00 00 48 89 df e8 ad fe ff ff 31 f6 48 89 df e8 a3 fe ff ff 5b 89 e8 5d 41 5c 41 5d c3 <0f> 0b c7 83 58 05 00 00 ff ff ff ff eb e9 bd ed ff ff ff eb e2 0f
[  912.357888] RSP: 0018:ffffc9000038bd10 EFLAGS: 00010246
[  912.357898] RAX: 00000000ffffffff RBX: ffff88026cf01158 RCX: ffffc9000059c000
[  912.357904] RDX: ffff88026cf011b8 RSI: 0000000000000000 RDI: ffff88026cf01158
[  912.357911] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[  912.357917] R10: ffffc9000038bc40 R11: ffff880277e21598 R12: 0000000000000000
[  912.357924] R13: ffff8802653d2da0 R14: ffffffff815072e0 R15: ffff880275dd2350
[  912.357931] FS:  0000000000000000(0000) GS:ffff880277e00000(0000) knlGS:0000000000000000
[  912.357938] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  912.357945] CR2: 00007ff50cb2a210 CR3: 0000000005210000 CR4: 0000000000340ef0
[  912.357951] Call Trace:
[  912.357971]  ? pci_azx_readl+0x10/0x10 [snd_hda_intel]
[  912.357982]  azx_runtime_resume+0x1e7/0x240 [snd_hda_intel]
[  912.357998]  pci_pm_runtime_resume+0x73/0xa0
[  912.358009]  __rpm_callback+0xb3/0x1b0
[  912.358021]  rpm_callback+0x1a/0x70
[  912.358031]  ? pci_restore_standard_config+0x40/0x40
[  912.358040]  rpm_resume+0x533/0x830
[  912.358056]  pm_runtime_work+0x5a/0xb0
[  912.358069]  process_one_work+0x245/0x610
[  912.358087]  worker_thread+0x37/0x380
[  912.358099]  ? process_one_work+0x610/0x610
[  912.358108]  kthread+0x119/0x130
[  912.358117]  ? kthread_park+0x80/0x80
[  912.358131]  ret_from_fork+0x24/0x50
[  912.358152] irq event stamp: 0
[  912.358160] hardirqs last  enabled at (0): [<0000000000000000>]           (null)
[  912.358169] hardirqs last disabled at (0): [<ffffffff81081f59>] copy_process.part.6+0x409/0x2010
[  912.358177] softirqs last  enabled at (0): [<ffffffff81081f59>] copy_process.part.6+0x409/0x2010
[  912.358184] softirqs last disabled at (0): [<0000000000000000>]           (null)
[  912.358200] WARNING: CPU: 0 PID: 6649 at sound/hda/hdac_component.c:85 snd_hdac_display_power+0xe6/0x100 [snd_hda_core]
[  912.358207] ---[ end trace 4d4018d143c2f333 ]---
Comment 5 Imre Deak 2018-09-13 10:53:05 UTC
Looks like a refcounting bug in the HDA driver:
WARN_ON(!bus->drm_power_refcount);

Takashi, is there a bugzilla for the HDA driver we could we move this ticket to?
Comment 6 Takashi Iwai 2018-09-13 14:23:09 UTC
(In reply to Imre Deak from comment #5)
> Looks like a refcounting bug in the HDA driver:
> WARN_ON(!bus->drm_power_refcount);

Hm, the device free gets called during it being suspended.
A shot in the dark:

--- a/sound/pci/hda/hda_codec.c
+++ b/sound/pci/hda/hda_codec.c
@@ -834,7 +834,8 @@ static int snd_hda_codec_dev_free(struct snd_device *device)
 
        codec->in_freeing = 1;
        snd_hdac_device_unregister(&codec->core);
-       snd_hdac_link_power(&codec->core, false);
+       if (pm_runtime_active(hda_codec_dev(codec)))
+               snd_hdac_link_power(&codec->core, false);
        put_device(hda_codec_dev(codec));
        return 0;
 }


> Takashi, is there a bugzilla for the HDA driver we could we move this ticket
> to?

Feel free to move to bugzilla.kernel.org.  Thanks.
Comment 7 Martin Peres 2018-11-01 14:58:16 UTC
(In reply to Takashi Iwai from comment #6)
> (In reply to Imre Deak from comment #5)
> > Looks like a refcounting bug in the HDA driver:
> > WARN_ON(!bus->drm_power_refcount);
> 
> Hm, the device free gets called during it being suspended.
> A shot in the dark:
> 
> --- a/sound/pci/hda/hda_codec.c
> +++ b/sound/pci/hda/hda_codec.c
> @@ -834,7 +834,8 @@ static int snd_hda_codec_dev_free(struct snd_device
> *device)
>  
>         codec->in_freeing = 1;
>         snd_hdac_device_unregister(&codec->core);
> -       snd_hdac_link_power(&codec->core, false);
> +       if (pm_runtime_active(hda_codec_dev(codec)))
> +               snd_hdac_link_power(&codec->core, false);
>         put_device(hda_codec_dev(codec));
>         return 0;
>  }
> 
> 
> > Takashi, is there a bugzilla for the HDA driver we could we move this ticket
> > to?
> 
> Feel free to move to bugzilla.kernel.org.  Thanks.

Sorry for the delay, too many bugs to track...

Has a bug on bugzilla.kernel.org been written or a patch been made for this issue?

It seems to happen every 1.5 months. Last time it was seen was 1.5 months ago, so I guess we'll soon see if progress has been made!
Comment 8 Takashi Iwai 2018-11-02 14:29:05 UTC
(In reply to Martin Peres from comment #7)
> Has a bug on bugzilla.kernel.org been written or a patch been made for this
> issue?

Nothing I know of, so far.

> It seems to happen every 1.5 months. Last time it was seen was 1.5 months
> ago, so I guess we'll soon see if progress has been made!

Heh, 6 times per year isn't a bad bet :)
Comment 9 Martin Peres 2018-12-05 14:05:18 UTC
Also seen on BSW, https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5259/fi-bsw-cyan/igt@i915_selftest@live_sanitycheck.html

<4> [478.306426] WARNING: CPU: 3 PID: 3838 at sound/hda/hdac_component.c:85 snd_hdac_display_power+0xe6/0x100 [snd_hda_core]
<4> [478.306488] Modules linked in: snd_hda_intel i915 amdgpu chash gpu_sched ttm vgem snd_hda_codec_hdmi coretemp crct10dif_pclmul btusb crc32_pclmul btrtl btbcm btintel ghash_clmulni_intel cdc_ether usbnet bluetooth r8152 mii ecdh_generic snd_hda_codec snd_hwdep snd_hda_core snd_pcm pinctrl_cherryview lpc_ich prime_numbers [last unloaded: i915]
<4> [478.306538] CPU: 3 PID: 3838 Comm: i915_selftest Tainted: G     U            4.20.0-rc5-CI-CI_DRM_5259+ #1
<4> [478.306544] Hardware name: GOOGLE Cyan/Cyan, BIOS MrChromebox 02/15/2018
<4> [478.306557] RIP: 0010:snd_hdac_display_power+0xe6/0x100 [snd_hda_core]
<4> [478.306564] Code: 09 49 8b 7d 00 e8 2a ca b7 e1 be 01 00 00 00 48 89 df e8 ad fe ff ff 31 f6 48 89 df e8 a3 fe ff ff 5b 89 e8 5d 41 5c 41 5d c3 <0f> 0b c7 83 58 05 00 00 ff ff ff ff eb e9 bd ed ff ff ff eb e2 0f
<4> [478.306570] RSP: 0018:ffffc900005d3c68 EFLAGS: 00010246
<4> [478.306578] RAX: 00000000ffffffff RBX: ffff888076b91158 RCX: 0000000000000000
<4> [478.306584] RDX: 0000000000000006 RSI: 0000000000000000 RDI: ffff888076b91158
<4> [478.306589] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
<4> [478.306594] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
<4> [478.306600] R13: ffff8880744afcd0 R14: 0000000000000060 R15: ffff888075e1a7e8
<4> [478.306607] FS:  00007fd2e27f9980(0000) GS:ffff888079980000(0000) knlGS:0000000000000000
<4> [478.306612] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [478.306618] CR2: 00007f33b20ecd29 CR3: 00000000620ee000 CR4: 00000000001006e0
<4> [478.306623] Call Trace:
<4> [478.306652]  snd_hda_codec_dev_free+0x1e/0x30 [snd_hda_codec]
<4> [478.306666]  __snd_device_free+0x4c/0x80
<4> [478.306674]  snd_device_free_all+0x36/0x80
<4> [478.306688]  release_card_device+0x14/0x70
<4> [478.306699]  device_release+0x2b/0x80
<4> [478.306711]  kobject_put+0x85/0x1a0
<4> [478.306722]  snd_card_free+0x60/0x90
<4> [478.306745]  pci_device_remove+0x36/0xb0
<4> [478.306757]  device_release_driver_internal+0x185/0x240
<4> [478.306771]  unbind_store+0xaf/0x180
<4> [478.306784]  kernfs_fop_write+0x104/0x190
<4> [478.306799]  __vfs_write+0x31/0x180
<4> [478.306812]  ? rcu_read_lock_sched_held+0x6f/0x80
<4> [478.306819]  ? rcu_sync_lockdep_assert+0x29/0x50
<4> [478.306827]  ? __sb_start_write+0x152/0x1f0
<4> [478.306833]  ? __sb_start_write+0x163/0x1f0
<4> [478.306846]  vfs_write+0xbd/0x1b0
<4> [478.306858]  ksys_write+0x50/0xc0
<4> [478.306873]  do_syscall_64+0x55/0x190
<4> [478.306884]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [478.306891] RIP: 0033:0x7fd2e20b6154
<4> [478.306898] Code: 89 02 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 8d 05 b1 07 2e 00 8b 00 85 c0 75 13 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 54 f3 c3 66 90 41 54 55 49 89 d4 53 48 89 f5
<4> [478.306904] RSP: 002b:00007fffc158d408 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
<4> [478.306911] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fd2e20b6154
<4> [478.306917] RDX: 000000000000000c RSI: 000055fa56a0532b RDI: 0000000000000005
<4> [478.306922] RBP: 00007fffc158e4f0 R08: 0000000000000000 R09: 0000000000000000
<4> [478.306928] R10: 00007fd2e2112560 R11: 0000000000000246 R12: 000055fa5560b750
<4> [478.306933] R13: 00007fffc158e7d0 R14: 0000000000000000 R15: 0000000000000000
<4> [478.306961] irq event stamp: 76936
<4> [478.306971] hardirqs last  enabled at (76935): [<ffffffff810a59fb>] __flush_work+0x2bb/0x310
<4> [478.306977] hardirqs last disabled at (76936): [<ffffffff810019b0>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [478.306986] softirqs last  enabled at (76898): [<ffffffff817fab8c>] peernet2id+0x4c/0x70
<4> [478.306992] softirqs last disabled at (76896): [<ffffffff817fab6d>] peernet2id+0x2d/0x70
<4> [478.307006] WARNING: CPU: 3 PID: 3838 at sound/hda/hdac_component.c:85 snd_hdac_display_power+0xe6/0x100 [snd_hda_core]
<4> [478.307012] ---[ end trace 086147dd2631bdcd ]---
<4> [478.340648] WARNING: CPU: 3 PID: 3838 at sound/hda/hdac_component.c:324 snd_hdac_acomp_exit+0x53/0x70 [snd_hda_core]
<4> [478.340658] Modules linked in: snd_hda_intel i915 amdgpu chash gpu_sched ttm vgem snd_hda_codec_hdmi coretemp crct10dif_pclmul btusb crc32_pclmul btrtl btbcm btintel ghash_clmulni_intel cdc_ether usbnet bluetooth r8152 mii ecdh_generic snd_hda_codec snd_hwdep snd_hda_core snd_pcm pinctrl_cherryview lpc_ich prime_numbers [last unloaded: i915]
<4> [478.340707] CPU: 3 PID: 3838 Comm: i915_selftest Tainted: G     U  W         4.20.0-rc5-CI-CI_DRM_5259+ #1
<4> [478.340713] Hardware name: GOOGLE Cyan/Cyan, BIOS MrChromebox 02/15/2018
<4> [478.340725] RIP: 0010:snd_hdac_acomp_exit+0x53/0x70 [snd_hda_core]
<4> [478.340732] Code: d3 c6 5a e1 48 c7 83 50 05 00 00 00 00 00 00 48 89 ef 31 c9 31 d2 48 c7 c6 60 4a 08 a0 e8 b5 73 5b e1 31 c0 5b 5d c3 31 c0 c3 <0f> 0b 85 d2 7e c5 48 8b 50 08 48 85 d2 74 bc 48 8b 52 10 48 8b 38
<4> [478.340738] RSP: 0018:ffffc900005d3c70 EFLAGS: 00010286
<4> [478.340745] RAX: ffff8880744afcd0 RBX: ffff888076b91158 RCX: a77cd00700000000
<4> [478.340751] RDX: 00000000ffffffff RSI: 000000007aabcc49 RDI: ffff888076b91158
<4> [478.340756] RBP: ffff888078055748 R08: 00000000ccaf10e7 R09: 0000000000000001
<4> [478.340762] R10: 0000000000000000 R11: ffffffff82233340 R12: ffff888075e52448
<4> [478.340768] R13: ffff888075e522a8 R14: 0000000000000060 R15: ffff888075e1a7e8
<4> [478.340774] FS:  00007fd2e27f9980(0000) GS:ffff888079980000(0000) knlGS:0000000000000000
<4> [478.340779] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [478.340785] CR2: 00007f33b20ecd29 CR3: 00000000620ee000 CR4: 00000000001006e0
<4> [478.340790] Call Trace:
<4> [478.340807]  azx_free+0x107/0x180 [snd_hda_intel]
<4> [478.340820]  __snd_device_free+0x4c/0x80
<4> [478.340828]  snd_device_free_all+0x5a/0x80
<4> [478.340841]  release_card_device+0x14/0x70
<4> [478.340851]  device_release+0x2b/0x80
<4> [478.340864]  kobject_put+0x85/0x1a0
<4> [478.340874]  snd_card_free+0x60/0x90
<4> [478.340897]  pci_device_remove+0x36/0xb0
<4> [478.340908]  device_release_driver_internal+0x185/0x240
<4> [478.340921]  unbind_store+0xaf/0x180
<4> [478.340934]  kernfs_fop_write+0x104/0x190
<4> [478.340949]  __vfs_write+0x31/0x180
<4> [478.340963]  ? rcu_read_lock_sched_held+0x6f/0x80
<4> [478.340969]  ? rcu_sync_lockdep_assert+0x29/0x50
<4> [478.340978]  ? __sb_start_write+0x152/0x1f0
<4> [478.340984]  ? __sb_start_write+0x163/0x1f0
<4> [478.340997]  vfs_write+0xbd/0x1b0
<4> [478.341009]  ksys_write+0x50/0xc0
<4> [478.341024]  do_syscall_64+0x55/0x190
<4> [478.341035]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [478.341042] RIP: 0033:0x7fd2e20b6154
<4> [478.341049] Code: 89 02 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 8d 05 b1 07 2e 00 8b 00 85 c0 75 13 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 54 f3 c3 66 90 41 54 55 49 89 d4 53 48 89 f5
<4> [478.341054] RSP: 002b:00007fffc158d408 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
<4> [478.341062] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fd2e20b6154
<4> [478.341067] RDX: 000000000000000c RSI: 000055fa56a0532b RDI: 0000000000000005
<4> [478.341073] RBP: 00007fffc158e4f0 R08: 0000000000000000 R09: 0000000000000000
<4> [478.341078] R10: 00007fd2e2112560 R11: 0000000000000246 R12: 000055fa5560b750
<4> [478.341083] R13: 00007fffc158e7d0 R14: 0000000000000000 R15: 0000000000000000
<4> [478.341111] irq event stamp: 89460
<4> [478.341119] hardirqs last  enabled at (89459): [<ffffffff81200088>] __slab_free+0x3e8/0x510
<4> [478.341126] hardirqs last disabled at (89460): [<ffffffff810019b0>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [478.341133] softirqs last  enabled at (89074): [<ffffffff81c0033a>] __do_softirq+0x33a/0x4b9
<4> [478.341141] softirqs last disabled at (89067): [<ffffffff8108e6a9>] irq_exit+0xa9/0xc0
<4> [478.341153] WARNING: CPU: 3 PID: 3838 at sound/hda/hdac_component.c:324 snd_hdac_acomp_exit+0x53/0x70 [snd_hda_core]
<4> [478.341159] ---[ end trace 086147dd2631bdce ]---

(In reply to Takashi Iwai from comment #8)
> (In reply to Martin Peres from comment #7)
> > Has a bug on bugzilla.kernel.org been written or a patch been made for this
> > issue?
> 
> Nothing I know of, so far.

ok, thanks! We'll do so :)

> 
> > It seems to happen every 1.5 months. Last time it was seen was 1.5 months
> > ago, so I guess we'll soon see if progress has been made!
> 
> Heh, 6 times per year isn't a bad bet :)

New statistics is indeed once every 2 months... It isn't too bad, but that probably means we should write tests to better catch these sorts of issues.

If all goes well, we should soon reach the point where audio would become the next obvious thing to improve testing for anyway, so let's see what we can do :)
Comment 10 Takashi Iwai 2018-12-05 15:10:29 UTC
Is the fix mentioned in comment 6 applied to the test tree?

If it's not included, I'll apply it to for-next branch of sound git tree.
It's no urgent bug to be fixed in for-linus branch, as it seems.
Comment 11 Takashi Iwai 2018-12-09 09:35:25 UTC
(In reply to Takashi Iwai from comment #10)
> Is the fix mentioned in comment 6 applied to the test tree?
> 
> If it's not included, I'll apply it to for-next branch of sound git tree.
> It's no urgent bug to be fixed in for-linus branch, as it seems.
Scratch this, it turned out to be incorrect.

I worked on refactoring / fixes of the whole display PM in the HD-audio side and submitted the fix patchset.  It'll be included in for-next branch later, targeted for 4.21.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.