Re: ✗ Fi.CI.BAT: failure for i915 PMU and engine busy stats (rev18)

Chris Wilson
2017-10-17T11:21:56Z

Quoting Patchwork (2017-10-17 12:12:55)
> == Series Details ==
>
> Series: i915 PMU and engine busy stats (rev18)
> URL : https://patchwork.freedesktop.org/series/27488/
> State : failure
>
> == Summary ==
>
> Series 27488v18 i915 PMU and engine busy stats
> https://patchwork.freedesktop.org/api/1.0/series/27488/revisions/18/mbox/
>
> Test gem_exec_suspend:
> Subgroup basic-s3:
> pass -> INCOMPLETE (fi-pnv-d510)
> pass -> INCOMPLETE (fi-byt-j1900)
> pass -> INCOMPLETE (fi-glk-1)

At least glk had pstore!

<6>[ 251.557743] Disabling non-boot CPUs ...
<4>[ 251.576367] IRQ 127: no longer affine to CPU1
<6>[ 251.578495] smpboot: CPU 1 is now offline
<4>[ 251.599991] IRQ 121: no longer affine to CPU2
<6>[ 251.602337] smpboot: CPU 2 is now offline
<4>[ 251.618470] INFO: trying to register non-static key.
<4>[ 251.618472] the code is fine but needs lockdep annotation.
<4>[ 251.618473] turning off the locking correctness validator.
<4>[ 251.618481] CPU: 3 PID: 26 Comm: cpuhp/3 Tainted: G U 4.14.0-rc5-CI-Patchwork_6068+ #1
<4>[ 251.618483] Hardware name: Intel Corp. Geminilake/GLK RVP2 LP4SD (07), BIOS GELKRVPA.X64.0062.B30.1708222146 08/22/2017
<4>[ 251.618486] Call Trace:
<4>[ 251.618500] dump_stack+0x68/0x9f
<4>[ 251.618507] register_lock_class+0x3fd/0x580
<4>[ 251.618515] ? __save_stack_trace+0x73/0xd0
<4>[ 251.618522] __lock_acquire+0xa4/0x1b00
<4>[ 251.618527] ? padata_cpu_prep_down+0x35/0x60
<4>[ 251.618534] ? __slab_free+0x3b4/0x540
<4>[ 251.618539] ? __this_cpu_preempt_check+0x13/0x20
<4>[ 251.618545] lock_acquire+0xb0/0x200
<4>[ 251.618548] ? lock_acquire+0xb0/0x200
<4>[ 251.618552] ? padata_cpu_prep_down+0x35/0x60
<4>[ 251.618559] __mutex_lock+0x86/0x9b0
<4>[ 251.618562] ? padata_cpu_prep_down+0x35/0x60
<4>[ 251.618566] ? padata_cpu_prep_down+0x35/0x60
<4>[ 251.618570] ? __lock_acquire+0x4ab/0x1b00
<4>[ 251.618577] mutex_lock_nested+0x1b/0x20
<4>[ 251.618581] ? mutex_lock_nested+0x1b/0x20
<4>[ 251.618584] padata_cpu_prep_down+0x35/0x60
<4>[ 251.618590] cpuhp_invoke_callback+0x161/0xbf0
<4>[ 251.618594] ? cpuhp_thread_fun+0x41/0x240
<4>[ 251.618597] ? padata_remove_cpu+0x80/0x80
<4>[ 251.618602] cpuhp_thread_fun+0x17b/0x240
<4>[ 251.618609] ? smpboot_thread_fn+0x2d/0x280
<4>[ 251.618613] smpboot_thread_fn+0x18a/0x280
<4>[ 251.618617] kthread+0x114/0x150
<4>[ 251.618621] ? sort_range+0x30/0x30
<4>[ 251.618624] ? kthread_create_on_node+0x40/0x40
<4>[ 251.618630] ret_from_fork+0x27/0x40
<3>[ 251.618696] ODEBUG: assert_init not available (active state 0) object type: timer_list hint: ONEf+0x1741e/0xba963
<4>[ 251.618737] ------------[ cut here ]------------
<4>[ 251.618743] WARNING: CPU: 3 PID: 26 at lib/debugobjects.c:291 debug_print_object+0x76/0x80
<4>[ 251.618746] Modules linked in: snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core snd_pcm mei_me r8169 prime_numbers mii mei i2c_hid pinctrl_geminilake pinctrl_intel
<4>[ 251.618809] CPU: 3 PID: 26 Comm: cpuhp/3 Tainted: G U 4.14.0-rc5-CI-Patchwork_6068+ #1
<4>[ 251.618812] Hardware name: Intel Corp. Geminilake/GLK RVP2 LP4SD (07), BIOS GELKRVPA.X64.0062.B30.1708222146 08/22/2017
<4>[ 251.618816] task: ffff88017ab5cec0 task.stack: ffffc90000140000
<4>[ 251.618821] RIP: 0010:debug_print_object+0x76/0x80
<4>[ 251.618825] RSP: 0018:ffffc90000143c78 EFLAGS: 00010296
<4>[ 251.618830] RAX: 0000000000000065 RBX: ffffc90000143ca0 RCX: 0000000000000000
<4>[ 251.618833] RDX: 0000000080000001 RSI: 0000000000000001 RDI: ffffffff810ee876
<4>[ 251.618836] RBP: ffffc90000143c90 R08: 0000000000000001 R09: 0000000000000000
<4>[ 251.618839] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff81e4f5e0
<4>[ 251.618843] R13: ffffffff81cc1c4b R14: ffffffff82d63ba8 R15: 0000000000000000
<4>[ 251.618847] FS: 0000000000000000(0000) GS:ffff88017fd80000(0000) knlGS:0000000000000000
<4>[ 251.618850] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[ 251.618854] CR2: 00007f830b4ddd70 CR3: 00000001733f7000 CR4: 00000000003406e0
<4>[ 251.618857] Call Trace:
<4>[ 251.618865] debug_object_assert_init+0x129/0x140
<4>[ 251.618873] ? del_timer_sync+0x5/0xb0
<4>[ 251.618880] try_to_del_timer_sync+0x1f/0x70
<4>[ 251.618884] ? try_to_del_timer_sync+0x1f/0x70
<4>[ 251.618889] del_timer_sync+0x8c/0xb0
<4>[ 251.618895] padata_flush_queues+0x5a/0xc0
<4>[ 251.618901] padata_replace+0x58/0x110
<4>[ 251.618907] __padata_remove_cpu+0x82/0xb0
<4>[ 251.618913] padata_cpu_prep_down+0x40/0x60
<4>[ 251.618919] cpuhp_invoke_callback+0x161/0xbf0
<4>[ 251.618925] ? cpuhp_thread_fun+0x41/0x240
<4>[ 251.618929] ? padata_remove_cpu+0x80/0x80
<4>[ 251.618937] cpuhp_thread_fun+0x17b/0x240
<4>[ 251.618944] ? smpboot_thread_fn+0x2d/0x280
<4>[ 251.618950] smpboot_thread_fn+0x18a/0x280
<4>[ 251.618956] kthread+0x114/0x150
<4>[ 251.618961] ? sort_range+0x30/0x30
<4>[ 251.618965] ? kthread_create_on_node+0x40/0x40
<4>[ 251.618973] ret_from_fork+0x27/0x40
<4>[ 251.618983] Code: 49 89 c1 8b 43 10 8b 4b 14 4c 89 ee 4d 8b 04 24 48 c7 c7 68 1a cc 81 83 05 1f 4e 87 01 01 48 8b 14 c5 80 c8 a6 81 e8 db ee c5 ff <0f> ff eb a5 45 31 c9 eb cf 90 55 48 89 e5 41 57 41 56 41 55 41
<4>[ 251.619153] ---[ end trace b31bdc7f94776dac ]---
<4>[ 251.619178] ------------[ cut here ]------------
<4>[ 251.619186] WARNING: CPU: 3 PID: 26 at mm/vmalloc.c:245 vmalloc_to_page+0x137/0x140
<4>[ 251.619189] Modules linked in: snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core snd_pcm mei_me r8169 prime_numbers mii mei i2c_hid pinctrl_geminilake pinctrl_intel
<4>[ 251.619242] CPU: 3 PID: 26 Comm: cpuhp/3 Tainted: G U W 4.14.0-rc5-CI-Patchwork_6068+ #1
<4>[ 251.619245] Hardware name: Intel Corp. Geminilake/GLK RVP2 LP4SD (07), BIOS GELKRVPA.X64.0062.B30.1708222146 08/22/2017
<4>[ 251.619248] task: ffff88017ab5cec0 task.stack: ffffc90000140000
<4>[ 251.619253] RIP: 0010:vmalloc_to_page+0x137/0x140
<4>[ 251.619257] RSP: 0018:ffffc90000143d48 EFLAGS: 00010082
<4>[ 251.619262] RAX: 8000000101a001e3 RBX: ffff88017fff9a00 RCX: 8000000101a001e3
<4>[ 251.619265] RDX: 00003fffffe00000 RSI: ffff880000000000 RDI: ffff880101be3c00
<4>[ 251.619268] RBP: ffffc90000143d48 R08: 80000000000001e3 R09: ffffc000001fffff
<4>[ 251.619271] R10: 000000010f11e000 R11: ffffffff811bd999 R12: ffff880101a63c00
<4>[ 251.619274] R13: ffffffff81e63c00 R14: 0000000000000287 R15: 0000000000000000
<4>[ 251.619278] FS: 0000000000000000(0000) GS:ffff88017fd80000(0000) knlGS:0000000000000000
<4>[ 251.619282] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[ 251.619285] CR2: 00007f830b4ddd70 CR3: 00000001733f7000 CR4: 00000000003406e0
<4>[ 251.619287] Call Trace:
<4>[ 251.619299] free_percpu+0x120/0x290
<4>[ 251.619306] padata_replace+0x62/0x110
<4>[ 251.619312] __padata_remove_cpu+0x82/0xb0
<4>[ 251.619317] padata_cpu_prep_down+0x40/0x60
<4>[ 251.619324] cpuhp_invoke_callback+0x161/0xbf0
<4>[ 251.619329] ? cpuhp_thread_fun+0x41/0x240
<4>[ 251.619334] ? padata_remove_cpu+0x80/0x80
<4>[ 251.619341] cpuhp_thread_fun+0x17b/0x240
<4>[ 251.619348] ? smpboot_thread_fn+0x2d/0x280
<4>[ 251.619353] smpboot_thread_fn+0x18a/0x280
<4>[ 251.619359] kthread+0x114/0x150
<4>[ 251.619364] ? sort_range+0x30/0x30
<4>[ 251.619368] ? kthread_create_on_node+0x40/0x40
<4>[ 251.619376] ret_from_fork+0x27/0x40
<4>[ 251.619386] Code: 01 01 00 00 74 1b 48 c1 e0 12 48 ba 00 00 00 00 00 ea ff ff 48 c1 e8 1e 48 c1 e0 06 48 01 d0 5d c3 31 c0 5d c3 0f ff 31 c0 5d c3 <0f> ff 31 c0 5d c3 0f 1f 00 0f 1f 44 00 00 55 48 89 e5 e8 b2 fe
<4>[ 251.619529] ---[ end trace b31bdc7f94776dad ]---
<1>[ 251.619540] BUG: unable to handle kernel NULL pointer dereference at 0000000000000010
<1>[ 251.619550] IP: free_percpu+0x120/0x290
<6>[ 251.619554] PGD 0 P4D 0
<4>[ 251.619562] Oops: 0000 [#1] PREEMPT SMP
<4>[ 251.619565] Modules linked in: snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core snd_pcm mei_me r8169 prime_numbers mii mei i2c_hid pinctrl_geminilake pinctrl_intel
<4>[ 251.619617] CPU: 3 PID: 26 Comm: cpuhp/3 Tainted: G U W 4.14.0-rc5-CI-Patchwork_6068+ #1
<4>[ 251.619620] Hardware name: Intel Corp. Geminilake/GLK RVP2 LP4SD (07), BIOS GELKRVPA.X64.0062.B30.1708222146 08/22/2017
<4>[ 251.619623] task: ffff88017ab5cec0 task.stack: ffffc90000140000
<4>[ 251.619628] RIP: 0010:free_percpu+0x120/0x290
<4>[ 251.619631] RSP: 0018:ffffc90000143d58 EFLAGS: 00010046
<4>[ 251.619637] RAX: 0000000000000000 RBX: ffff88017fff9a00 RCX: 8000000101a001e3
<4>[ 251.619640] RDX: 00003fffffe00000 RSI: ffff880000000000 RDI: ffff880101be3c00
<4>[ 251.619643] RBP: ffffc90000143d80 R08: 80000000000001e3 R09: ffffc000001fffff
<4>[ 251.619646] R10: 000000010f11e000 R11: ffffffff811bd999 R12: ffff880101a63c00
<4>[ 251.619649] R13: ffffffff81e63c00 R14: 0000000000000287 R15: 0000000000000000
<4>[ 251.619653] FS: 0000000000000000(0000) GS:ffff88017fd80000(0000) knlGS:0000000000000000
<4>[ 251.619656] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[ 251.619659] CR2: 0000000000000010 CR3: 00000001733f7000 CR4: 00000000003406e0
<4>[ 251.619662] Call Trace:
<4>[ 251.619669] padata_replace+0x62/0x110
<4>[ 251.619675] __padata_remove_cpu+0x82/0xb0
<4>[ 251.619681] padata_cpu_prep_down+0x40/0x60
<4>[ 251.619687] cpuhp_invoke_callback+0x161/0xbf0
<4>[ 251.619692] ? cpuhp_thread_fun+0x41/0x240
<4>[ 251.619697] ? padata_remove_cpu+0x80/0x80
<4>[ 251.619704] cpuhp_thread_fun+0x17b/0x240
<4>[ 251.619711] ? smpboot_thread_fn+0x2d/0x280
<4>[ 251.619716] smpboot_thread_fn+0x18a/0x280
<4>[ 251.619722] kthread+0x114/0x150
<4>[ 251.619727] ? sort_range+0x30/0x30
<4>[ 251.619731] ? kthread_create_on_node+0x40/0x40
<4>[ 251.619739] ret_from_fork+0x27/0x40
<4>[ 251.619749] Code: 63 43 50 48 01 d0 49 39 c4 0f 83 72 ff ff ff 48 8b 15 bd 51 b7 00 4c 89 e7 65 8b 05 b3 c6 e4 7e 48 98 48 03 3c c2 e8 a0 2a 02 00 <48> 8b 58 10 48 8b 53 20 e9 49 ff ff ff 65 8b 05 94 c6 e4 7e 89
<1>[ 251.619894] RIP: free_percpu+0x120/0x290 RSP: ffffc90000143d58
<4>[ 251.619897] CR2: 0000000000000010
<4>[ 251.619903] ---[ end trace b31bdc7f94776dae ]---
<3>[ 251.729960] BUG: sleeping function called from invalid context at ./include/linux/percpu-rwsem.h:33
<3>[ 251.729963] in_atomic(): 1, irqs_disabled(): 1, pid: 26, name: cpuhp/3
<4>[ 251.729964] INFO: lockdep is turned off.
<4>[ 251.729965] irq event stamp: 2999
<4>[ 251.729970] hardirqs last enabled at (2999): [<ffffffff811fd794>] __slab_free+0x3b4/0x540
<4>[ 251.729972] hardirqs last disabled at (2998): [<ffffffff811fd4f4>] __slab_free+0x114/0x540
<4>[ 251.729975] softirqs last enabled at (2752): [<ffffffff819122d6>] __do_softirq+0x3a6/0x4ae
<4>[ 251.729978] softirqs last disabled at (2727): [<ffffffff8108619e>] irq_exit+0xae/0xc0
<3>[ 251.729979] Preemption disabled at:
<4>[ 251.729983] [<ffffffff811bd999>] free_percpu+0x39/0x290
<4>[ 251.729987] CPU: 3 PID: 26 Comm: cpuhp/3 Tainted: G UD W 4.14.0-rc5-CI-Patchwork_6068+ #1
<4>[ 251.729988] Hardware name: Intel Corp. Geminilake/GLK RVP2 LP4SD (07), BIOS GELKRVPA.X64.0062.B30.1708222146 08/22/2017
<4>[ 251.729989] Call Trace:
<4>[ 251.729997] dump_stack+0x68/0x9f
<4>[ 251.729999] ___might_sleep+0x1e5/0x240
<4>[ 251.730001] __might_sleep+0x4a/0x80
<4>[ 251.730005] exit_signals+0x24/0x2a0
<4>[ 251.730008] ? smpboot_thread_fn+0x18a/0x280
<4>[ 251.730009] do_exit+0x9a/0xca0
<4>[ 251.730011] ? kthread+0x114/0x150
<4>[ 251.730013] ? sort_range+0x30/0x30
<4>[ 251.730015] rewind_stack_do_exit+0x17/0x20
<6>[ 251.730092] note: cpuhp/3[26] exited with preempt_count 1
<2>[ 337.964669] softdog: Initiating panic
<0>[ 337.964674] Kernel panic - not syncing: Software Watchdog Timer expired
<0>[ 337.964698] Kernel Offset: disabled

All look like a bug you may have tickled rather than caused. Though I'd
kasan for a use-after-free. But an odd mixtures of Atoms; presuming they
are all the same.
-Chris