Bug 103927

Summary: [CI][BXT only] igt@* - incomplete timeout/system hang
Product: DRI Reporter: Marta Löfstedt <marta.lofstedt>
Component: DRM/IntelAssignee: Stanislav Lisovskiy <stanislav.lisovskiy>
Status: CLOSED INVALID QA Contact: Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity: normal    
Priority: highest CC: intel-gfx-bugs
Version: DRI git   
Hardware: Other   
OS: All   
Whiteboard: ReadyForDev
i915 platform: BXT i915 features: power/suspend-resume
Bug Depends on:    
Bug Blocks: 105984    

Description Marta Löfstedt 2017-11-27 08:20:02 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3385/shard-apl3/igt@gem_exec_reloc@basic-wc-gtt-active.html

dmesg:
<5>[  703.500041] owatch: Using watchdog device /dev/watchdog0
<5>[  703.500147] owatch: Watchdog /dev/watchdog0 is a software watchdog
<5>[  703.501677] owatch: timeout for /dev/watchdog0 set to 370 (requested 370)
...
<4>[  953.947982] hpet1: lost 7161 rtc interrupts
<4>[  954.837466] hpet1: lost 7161 rtc interrupts
<4>[  955.728351] hpet1: lost 7160 rtc interrupts

run.log:
running: igt/gem_exec_reloc/basic-wc-gtt-active

[48/75] skip: 16, pass: 31, fail: 1 |          
FATAL: command execution failed
java.io.EOFException
...
Finished: FAILURE
Completed CI_IGT_test CI_DRM_3385/shard-apl3/20 : FAILURE
CI_IGT_test runtime 328 seconds
Rebooting shard-apl3
Comment 1 Marta Löfstedt 2017-11-27 08:21:42 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3388/shard-apl2/igt@drv_selftest@mock_breadcrumbs.html

dmesg:
<5>[ 1702.026113] owatch: Using watchdog device /dev/watchdog0
<5>[ 1702.029167] owatch: Watchdog /dev/watchdog0 is a software watchdog
<5>[ 1702.067375] owatch: timeout for /dev/watchdog0 set to 370 (requested 370)
...
<4>[ 1830.939223] hpet1: lost 7160 rtc interrupts
<4>[ 1831.824734] hpet1: lost 7161 rtc interrupts
<4>[ 1832.710064] hpet1: lost 7161 rtc interrupts

run.log:
running: igt/drv_selftest/mock_breadcrumbs

[05/43] pass: 4, dmesg-warn: 1 /          
FATAL: command execution failed
java.io.EOFException
...
Finished: FAILURE
Completed CI_IGT_test CI_DRM_3388/shard-apl2/35 : FAILURE
CI_IGT_test runtime 190 seconds
Rebooting shard-apl2
Comment 2 Marta Löfstedt 2017-11-30 13:34:43 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3416/shard-apl6/igt@gem_tiled_swapping@non-threaded.html


dmesg:
<5>[ 1048.871613] owatch: Using watchdog device /dev/watchdog0
<5>[ 1048.871720] owatch: Watchdog /dev/watchdog0 is a software watchdog
<5>[ 1048.873275] owatch: timeout for /dev/watchdog0 set to 370 (requested 370)
...
<7>[ 1203.843465] [drm:drm_dp_read_desc] DP branch: OUI 00-00-00 dev-ID  HW-rev 0.0 SW-rev 0.0 quirks 0x0000
<7>[ 1203.843520] [drm:intel_dp_detect [i915]] Sink is not MST capable
<7>[ 1203.848943] [drm:drm_helper_hpd_irq_event] [CONNECTOR:72:DP-2] status updated from connected to connected
<7>[ 1203.991750] [IGT] gem_tiled_swapping: executing

no indication of timeout or softdog in run.log, i.e. looks like system hang.
Comment 3 Marta Löfstedt 2017-12-04 07:31:37 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3434/shard-apl5/igt@kms_flip@2x-flip-vs-rmfb-interruptible.html

dmesg:
<5>[ 1128.849581] owatch: Using watchdog device /dev/watchdog0
<5>[ 1128.849994] owatch: Watchdog /dev/watchdog0 is a software watchdog
<5>[ 1128.851845] owatch: timeout for /dev/watchdog0 set to 370 (requested 370)
<4>[ 1129.140345] hpet1: lost 7161 rtc interrupts
...
<4>[ 1465.370844] hpet1: lost 7161 rtc interrupts
<4>[ 1466.262777] hpet1: lost 7161 rtc interrupts
<4>[ 1467.154938] hpet1: lost 7161 rtc interrupts
Folloed by "stray"

run.log:
running: igt/kms_flip/2x-flip-vs-rmfb-interruptible

[20/75] skip: 9, pass: 11 |                        
FATAL: command execution failed
...
Finished: FAILURE
Completed CI_IGT_test CI_DRM_3434/shard-apl5/28 : FAILURE
CI_IGT_test runtime 388 seconds
Rebooting shard-apl5
Comment 5 Marta Löfstedt 2018-01-02 07:50:42 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3574/shard-apl1/igt@gem_cs_tlb@render.html

run.log:
running: igt/gem_exec_flush/basic-uc-set-default

[46/76] skip: 22, pass: 24 -                    
FATAL: command execution failed
...
Completed CI_IGT_test CI_DRM_3574/shard-apl1/26 : FAILURE
CI_IGT_test runtime 547 seconds
Rebooting shard-apl1

dmesg:
<4>[  330.029664] Setting dangerous option reset - tainting kernel
<7>[  330.032933] [IGT] gem_exec_flush: starting subtest basic-uc-set-default
<7>[  335.431877] [IGT] gem_exec_flush: exiting, ret=0
<7>[  335.627075] [IGT] gem_cs_tlb: executing
<7>[  335.644193] [IGT] gem_cs_tlb: starting subtest render
Comment 6 Marta Löfstedt 2018-01-12 12:28:11 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3624/shard-apl6/igt@drv_selftest@live_hugepages.html

run.log:
running: igt/drv_selftest/live_gtt

[20/43] pass: 19, dmesg-warn: 1 | 
FATAL: command execution failed
...
Completed CI_IGT_test CI_DRM_3624/shard-apl6/35 : FAILURE
CI_IGT_test runtime 461 seconds
Rebooting shard-apl6

there is pstore:
<0>[  431.286708] drv_self-5805    1..s1 253153398us : execlists_submission_tasklet: vecs0 in[0]:  ctx=2.1, seqno=1
...
<0>[  431.414112]   <idle>-0       0.Ns1 361042309us : execlists_submission_tasklet: vcs0 out[0]: ctx=3.1, seqno=1358
<0>[  431.414242] ---------------------------------
<0>[  431.414306] Kernel Offset: disabled

dmesg:
<7>[  257.267285] [IGT] drv_selftest: starting subtest live_gtt
...
<7>[  341.784308] [IGT] drv_selftest: starting subtest live_hugepages
...
<6>[  341.982461] failed to allocate THP, finishing test early
<5>[  342.986261] igt_write_huge timed out on engine=1, offset_low=22bd0000 offset_high=ffffdd230000, max_page_size=10000
Comment 7 Marta Löfstedt 2018-01-18 07:34:36 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4148/shard-apl8/igt@perf_pmu@busy-double-start-vecs0.html

there is pstore, but it is hard to interpret since it is dominated by ftrace.
Comment 8 Marta Löfstedt 2018-01-24 09:00:23 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4172/shard-apl5/igt@kms_cursor_crc@cursor-256x256-suspend.html

<1>[    5.150957] BUG: unable to handle kernel NULL pointer dereference at           (null)
<1>[    5.150971] IP: hda_widget_sysfs_reinit+0x13c/0x200 [snd_hda_core]
<6>[    5.150973] PGD 0 P4D 0 
<4>[    5.150977] Oops: 0000 [#1] PREEMPT SMP PTI
<4>[    5.150979] Modules linked in: snd_hda_codec_hdmi(+) snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul snd_hda_intel ghash_clmulni_intel snd_hda_codec snd_hwdep snd_hda_core r8169 lpc_ich mii snd_pcm mei_me mei prime_numbers pinctrl_broxton pinctrl_intel
<4>[    5.151001] CPU: 3 PID: 253 Comm: systemd-udevd Not tainted 4.15.0-rc9-CI-CI_DRM_3673+ #1
<4>[    5.151002] Hardware name:                  /NUC6CAYB, BIOS AYAPLCEL.86A.0040.2017.0619.1722 06/19/2017
<4>[    5.151008] RIP: 0010:hda_widget_sysfs_reinit+0x13c/0x200 [snd_hda_core]
<4>[    5.151009] RSP: 0018:ffffc900003e3b80 EFLAGS: 00010246
<4>[    5.151011] RAX: 0000000000000000 RBX: 0000000000000003 RCX: ffff88025ff69b58
<4>[    5.151012] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: ffffffff82246460
<4>[    5.151014] RBP: ffff880265b84548 R08: 0000000000000001 R09: ffff88026e3fa198
<4>[    5.151015] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
<4>[    5.151016] R13: 0000000000000038 R14: ffffffffa00a67c0 R15: ffff88026a193e38
<4>[    5.151017] FS:  00007fbaf82658c0(0000) GS:ffff88027fd80000(0000) knlGS:0000000000000000
<4>[    5.151018] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[    5.151020] CR2: 0000000000000000 CR3: 000000027326c000 CR4: 00000000003406e0
<4>[    5.151021] Call Trace:
<4>[    5.151030]  snd_hdac_refresh_widgets+0x65/0x90 [snd_hda_core]
<4>[    5.151040]  snd_hda_codec_update_widgets+0xe/0x50 [snd_hda_codec]
<4>[    5.151047]  intel_hsw_common_init.part.20+0x2b/0x90 [snd_hda_codec_hdmi]
<4>[    5.151053]  hda_codec_driver_probe+0x5e/0x100 [snd_hda_codec]
<4>[    5.151059]  driver_probe_device+0x2a3/0x480
<4>[    5.151063]  __driver_attach+0xd9/0xe0
<4>[    5.151066]  ? driver_probe_device+0x480/0x480
<4>[    5.151067]  bus_for_each_dev+0x57/0x90
<4>[    5.151070]  bus_add_driver+0x168/0x260
<4>[    5.151074]  driver_register+0x52/0xc0
<4>[    5.151075]  ? 0xffffffffa03a1000
<4>[    5.151078]  do_one_initcall+0x39/0x150
<4>[    5.151082]  ? rcu_read_lock_sched_held+0x6f/0x80
<4>[    5.151085]  ? kmem_cache_alloc_trace+0x248/0x2b0
<4>[    5.151088]  do_init_module+0x56/0x1ef
<4>[    5.151091]  load_module+0x231c/0x2d70
<4>[    5.151096]  ? show_coresize+0x20/0x20
<4>[    5.151098]  ? vfs_read+0x126/0x150
<4>[    5.151106]  ? SyS_finit_module+0xa5/0xe0
<4>[    5.151108]  SyS_finit_module+0xa5/0xe0
<4>[    5.151115]  do_syscall_64+0x59/0x1a0
<4>[    5.151119]  entry_SYSCALL64_slow_path+0x25/0x25
<4>[    5.151121] RIP: 0033:0x7fbaf70ee9f9
<4>[    5.151122] RSP: 002b:00007ffefb0c8e58 EFLAGS: 00000202 ORIG_RAX: 0000000000000139
<4>[    5.151124] RAX: ffffffffffffffda RBX: 00005591f5ae89f0 RCX: 00007fbaf70ee9f9
<4>[    5.151125] RDX: 0000000000000000 RSI: 00007fbaf7a11e23 RDI: 0000000000000007
<4>[    5.151126] RBP: 00007fbaf7a11e23 R08: 0000000000000000 R09: 0000000000000000
<4>[    5.151127] R10: 0000000000000007 R11: 0000000000000202 R12: 0000000000000000
<4>[    5.151128] R13: 00005591f5aac150 R14: 0000000000020000 R15: 00005591f4a6fe30
<4>[    5.151135] Code: e4 49 c7 c6 c0 67 0a a0 83 e8 01 4c 8d 2c c5 08 00 00 00 eb 2b 48 8b 8d a8 04 00 00 0f b7 d3 83 c3 01 29 c2 48 63 c2 48 8b 51 10 <48> 8b 14 c2 49 8b 47 10 4a 89 14 20 49 83 c4 08 4d 39 e5 74 36 
<1>[    5.151183] RIP: hda_widget_sysfs_reinit+0x13c/0x200 [snd_hda_core] RSP: ffffc900003e3b80
<4>[    5.151184] CR2: 0000000000000000
<4>[    5.151187] ---[ end trace 8765903cf6e4535d ]---
Comment 9 Marta Löfstedt 2018-01-25 12:47:08 UTC
This is a Meta bug to capture all unexplained incompletes on APL-shards
Comment 10 Marta Löfstedt 2018-01-31 14:42:00 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3706/shard-apl3/igt@perf_pmu@most-busy-check-all-vecs0.html

pstore only has ftrace info. 

Note CI_DRM_3704 - CI_DRM_3706 looks strange, lots of not run tests.
Comment 11 Marta Löfstedt 2018-02-05 07:25:31 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3718/shard-apl4/igt@perf_pmu@busy-double-start-vcs0.html

This has pstore which unfortunately only has ftrace information.
Comment 13 Marta Löfstedt 2018-03-22 06:59:47 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3964/fi-bxt-dsi/igt@kms_pipe_crc_basic@suspend-read-crc-pipe-a.html

running: igt/kms_pipe_crc_basic/suspend-read-crc-pipe-a

[240/285] skip: 26, pass: 214 |                        
FATAL: command execution failed
...
Completed CI_IGT_test CI_DRM_3964/fi-bxt-dsi/0 : FAILURE
CI_IGT_test runtime 562 seconds
Rebooting fi-bxt-dsi

Last dmesg:
<7>[  450.080918] [IGT] kms_pipe_crc_basic: starting subtest suspend-read-crc-pipe-A
<7>[  450.081382] [drm:drm_mode_addfb2] [FB:107]
<7>[  450.109061] [drm:drm_mode_setcrtc] [CRTC:46:pipe A]
<7>[  450.109110] [drm:drm_mode_setcrtc] [CONNECTOR:98:DSI-1]
<7>[  450.127575] [drm:drm_mode_setcrtc] [CRTC:65:pipe B]
<7>[  450.129837] [drm:drm_mode_setcrtc] [CRTC:79:pipe C]
<7>[  450.226438] [drm:drm_mode_addfb2] [FB:106]
<7>[  450.244482] [drm:drm_mode_setcrtc] [CRTC:46:pipe A]
<7>[  450.244553] [drm:drm_mode_setcrtc] [CONNECTOR:98:DSI-1]
Comment 14 Marta Löfstedt 2018-03-26 06:52:49 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3974/fi-bxt-dsi/igt@kms_flip@basic-flip-vs-dpms.html

run.log:
running: igt/kms_flip/basic-flip-vs-dpms

[215/285] skip: 22, pass: 193 \         
FATAL: command execution failed
...
Completed CI_IGT_test CI_DRM_3974/fi-bxt-dsi/0 : FAILURE
CI_IGT_test runtime 461 seconds
Rebooting fi-bxt-dsi

Last dmesg:
<7>[  354.175870] [IGT] kms_flip: executing
...
<7>[  354.214763] [drm:drm_dp_i2c_do_msg] native defer
<7>[  354.215624] [drm:lspcon_wait_mode [i915]] Current LSPCON mode P
Comment 15 Stanislav Lisovskiy 2018-07-03 07:28:40 UTC
So far, I couldn't reproduce any of the issues reported here, using my BXT.

I took all the tests mentioned and run them around 100 times. So those are either some specific hardware/configuration issues or they are fixed.
Comment 16 Stanislav Lisovskiy 2018-07-06 08:35:38 UTC
There seems to be some problem with drv_selftests: it occassionally runs out of memory(memory leak?), which causes then all subsequent tests to fail:

<3>[  170.754357] Out of memory: Kill process 5670 (drv_selftest) score 999 or sacrifice child
<7>[  170.754702] [drm:vma_print_allocator.constprop.12 [i915]] vma.node [ffffe000 + 00001000] is pinned: inserted at  i915_gem_gtt_insert+0x135/0x510 [i915]
                   __i915_vma_do_pin+0x462/0xd90 [i915]
                   logical_render_ring_init+0x33e/0x470 [i915]
                   intel_engines_init+0x4f/0x120 [i915]
                   i915_gem_init+0x20b/0x6a0 [i915]
                   i915_driver_load+0xc3a/0x1070 [i915]
                   i915_pci_probe+0x29/0x90 [i915]
                   pci_device_probe+0xa1/0x130
                   driver_probe_device+0x306/0x480
                   __driver_attach+0xdb/0x100
                   bus_for_each_dev+0x74/0xc0
                   bus_add_driver+0x15f/0x250
                   driver_register+0x56/0xe0
                   do_one_initcall+0x58/0x370
                   do_init_module+0x56/0x1ea
                   load_module+0x24

<3>[  170.763513] Out of memory: Kill process 782 (java) score 12 or sacrifice child
<7>[  170.763902] [drm:vma_print_allocator.constprop.12 [i915]] vma.node [ffffe000 + 00001000] is pinned: inserted at  i915_gem_gtt_insert+0x135/0x510 [i915]
                   __i915_vma_do_pin+0x462/0xd90 [i915]
                   logical_render_ring_init+0x33e/0x470 [i915]
                   intel_engines_init+0x4f/0x120 [i915]
                   i915_gem_init+0x20b/0x6a0 [i915]
                   i915_driver_load+0xc3a/0x1070 [i915]
                   i915_pci_probe+0x29/0x90 [i915]
                   pci_device_probe+0xa1/0x130
                   driver_probe_device+0x306/0x480
                   __driver_attach+0xdb/0x100
                   bus_for_each_dev+0x74/0xc0
                   bus_add_driver+0x15f/0x250
                   driver_register+0x56/0xe0
                   do_one_initcall+0x58/0x370
                   do_init_module+0x56/0x1ea
                   load_module+0x24

And so on. I guess this could be one of the reasons for getting lots of incomplete tests.
Comment 17 Francesco Balestrieri 2018-11-08 09:46:15 UTC
> There seems to be some problem with drv_selftests: it occassionally runs out > of memory(memory leak?), which causes then all subsequent tests to fail

Was this ever followed-up? It sounds like it could be major.
Comment 18 Stanislav Lisovskiy 2018-11-08 10:07:38 UTC
This seems to be kind of generic bug, summarizing all test case incompletes, not just some specific failure, so I guess we will always have something here.

According to http://gfx-ci.fi.intel.com/cibuglog-ng/issue/138/history all the recent issues happen to ApolloLake. To me it seems that it either runs out of memory or there is a memory leak in self_tests. I will check it, since didn't have time to do that yet unfortunately.
Comment 19 Francesco Balestrieri 2018-11-23 11:18:20 UTC
Setting to medium since it's a meta-bug of sorts.
Comment 20 Lakshmi 2018-11-25 13:47:21 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5198/fi-bxt-j4205/igt@runner@aborted.html

Out	
Aborting.
Previous test: i915_module_load (reload-with-fault-injection)
Next test: pm_rpm (module-reload)
Kernel tainted (0x2c0 -- 280)

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5198/fi-bxt-j4205/igt%40i915_module_load%40reload-with-fault-injection.html

<4> [353.865920] CPU: 2 PID: 3280 Comm: i915_module_loa Tainted: G     U            4.20.0-rc3-CI-CI_DRM_5198+ #1
<4> [353.866244]  i915_driver_load+0x845/0x1550 [i915]
<4> [353.866356]  i915_pci_probe+0x29/0xa0 [i915]
<0> [353.866953] CPU:0 [LOST 5585480 EVENTS]\x0ai915_mod-3280    0.... 351609810us : i915_request_add: marking (null) as active
<0> [353.867071] i915_mod-3280    0d..1 351609885us : process_csb: rcs0 cs-irq head=1, tail=1
<0> [353.867169] i915_mod-3280    0d..1 351609887us : __i915_request_submit: rcs0 fence 1646:1 -> global=2, current 1
<0> [353.867269] i915_mod-3280    0d..1 351609927us : __execlists_submission_tasklet: rcs0 in[0]:  ctx=0.1, global=2 (fence 1646:1) (current 1), prio=-4094
<0> [353.867367] i915_mod-3280    0.... 351609982us : i915_gem_switch_to_kernel_context: emit barrier on bcs0
<0> [353.867462] i915_mod-3280    0.... 351609996us : i915_request_add: bcs0 fence 1649:1
<0> [353.867553] i915_mod-3280    0.... 351609998us : i915_request_add: marking (null) as active
<0> [353.867649] i915_mod-3280    0d..1 351610048us : process_csb: bcs0 cs-irq head=1, tail=1
<0> [353.867747] i915_mod-3280    0d..1 351610083us : __i915_request_submit: bcs0 fence 1649:1 -> global=2, current 1
<0> [353.867845] i915_mod-3280    0d..1 351610095us : __execlists_submission_tasklet: bcs0 in[0]:  ctx=0.1, global=2 (fence 1649:1) (current 1), prio=-4094
<0> [353.867943] i915_mod-3280    0.... 351610100us : i915_gem_switch_to_kernel_context: emit barrier on vcs0
<0> [353.868039] i915_mod-3280    0.... 351610112us : i915_request_add: vcs0 fence 164c:1
<0> [353.868134] i915_mod-3280    0.... 351610114us : i915_request_add: marking (null) as active
<0> [353.868233] i915_mod-3280    0d..1 351610126us : process_csb: vcs0 cs-irq head=1, tail=1
<0> [353.868328] i915_mod-3280    0d..1 351610127us : __i915_request_submit: vcs0 fence 164c:1 -> global=2, current 1
<0> [353.868425] i915_mod-3280    0d..1 351610139us : __execlists_submission_tasklet: vcs0 in[0]:  ctx=0.1, global=2 (fence 164c:1) (current 1), prio=-4094
<0> [353.868528] i915_mod-3280    0.... 351610144us : last_request_on_engine: last request for (null) on engine vecs0: 1654:1
<0> [353.868623] i915_mod-3280    0.... 351610146us : engine_has_kernel_context_barrier: (null) needs barrier for 1654:1
<0> [353.868715] i915_mod-3280    0.... 351610146us : i915_gem_switch_to_kernel_context: emit barrier on vecs0
<0> [353.868807] i915_mod-3280    0.... 351610158us : last_request_on_engine: last request for (null) on engine vecs0: 1654:1
<0> [353.868903] i915_mod-3280    0.... 351610159us : i915_gem_switch_to_kernel_context: add barrier on vecs0 for 1654:1
<0> [353.868999] i915_mod-3280    0.... 351610170us : i915_request_add: vecs0 fence 164f:1
<0> [353.869092] i915_mod-3280    0.... 351610172us : i915_request_add: marking (null) as active
<0> [353.869188] i915_mod-3280    0d..1 351610185us : process_csb: vecs0 cs-irq head=1, tail=1
<0> [353.869283] i915_mod-3280    0d..1 351610186us : __i915_request_submit: vecs0 fence 164f:1 -> global=2, current 1
<0> [353.869393] i915_mod-3280    0d..1 351610198us : __execlists_submission_tasklet: vecs0 in[0]:  ctx=0.1, global=2 (fence 164f:1) (current 1), prio=-4094
<0> [353.869498] i915_mod-3280    0.... 351610203us : i915_gem_wait_for_idle: flags=2 (locked), timeout=200
<0> [353.869595] i915_mod-3280    0.... 351610244us : i915_request_retire: vecs0 fence 164f:1, global=2, current 2
<0> [353.869690] i915_mod-3280    0.... 351610245us : i915_request_retire: marking (null) as inactive
<0> [353.869784] i915_mod-3280    0.... 351610246us : i915_request_retire: __retire_engine_request(vecs0) fence 1654:1, global=1, current 2
<0> [353.869882] i915_mod-3280    0.... 351610249us : i915_request_retire: __retire_engine_request(vecs0) fence 164f:1, global=2, current 2
<0> [353.869981] i915_mod-3280    0.... 351610262us : i915_request_retire: vcs0 fence 164c:1, global=2, current 2
<0> [353.870075] i915_mod-3280    0.... 351610263us : i915_request_retire: marking (null) as inactive
<0> [353.870170] i915_mod-3280    0.... 351610264us : i915_request_retire: __retire_engine_request(vcs0) fence 164c:1, global=2, current 2
<0> [353.870267] i915_mod-3280    0.... 351610279us : i915_request_retire: bcs0 fence 1649:1, global=2, current 2
<0> [353.870361] i915_mod-3280    0.... 351610280us : i915_request_retire: marking (null) as inactive
<0> [353.870455] i915_mod-3280    0.... 351610281us : i915_request_retire: __retire_engine_request(bcs0) fence 1649:1, global=2, current 2
<0> [353.870554] i915_mod-3280    0.... 351610295us : i915_request_retire: rcs0 fence 1646:1, global=2, current 2
<0> [353.870649] i915_mod-3280    0.... 351610295us : i915_request_retire: marking (null) as inactive
<0> [353.870742] i915_mod-3280    0.... 351610296us : i915_request_retire: __retire_engine_request(rcs0) fence 1646:1, global=2, current 2
<0> [353.870841] i915_mod-3280    0.... 351610310us : i915_request_retire: vecs0 fence 1654:1, global=1, current 2
<0> [353.870934] i915_mod-3280    0.... 351610310us : i915_request_retire: marking (null) as inactive
<0> [353.871026] i915_mod-3280    0.... 351610314us : i915_gem_park: 
<0> [353.871115] i915_mod-3280    0.... 351610329us : __i915_gem_park: 
<0> [353.871203] i915_mod-3280    0.... 351610694us : i915_gem_suspend: 
<0> [353.871288] i915_mod-3280    0.... 351610697us : i915_gem_switch_to_kernel_context: awake?=no
<0> [353.871381] i915_mod-3280    0.... 351610699us : i915_gem_wait_for_idle: flags=13 (locked), timeout=9223372036854775807 (forever)
<0> [353.871478] i915_mod-3280    0.... 351612054us : i915_gem_sanitize: 
<0> [353.871568] i915_mod-3280    0.... 351612063us : intel_engine_stop_cs: rcs0
<0> [353.871659] i915_mod-3280    0.... 351612080us : intel_engine_stop_cs: bcs0
<0> [353.871751] i915_mod-3280    0.... 351612096us : intel_engine_stop_cs: vcs0
<0> [353.871842] i915_mod-3280    0.... 351612114us : intel_engine_stop_cs: vecs0
<0> [353.871936] i915_mod-3280    0.... 351612165us : intel_gpu_reset: engine_mask=ffffffff, ret=0, retry=0
<0> [353.872031] i915_mod-3280    0.... 351612166us : intel_engines_sanitize: 
<0> [353.872128] i915_mod-3280    0.... 351612167us : execlists_reset: rcs0 request global=0, current=2
<0> [353.872224] i915_mod-3280    0.... 351612170us : execlists_reset: bcs0 request global=0, current=2
<0> [353.872322] i915_mod-3280    0.... 351612171us : execlists_reset: vcs0 request global=0, current=2
<0> [353.872422] i915_mod-3280    0.... 351612172us : execlists_reset: vecs0 request global=0, current=2
<0> [353.872448] i915_mod-3280    0.... 351920276us : 0xffffffffa013b910: 
<0> [353.872467] i915_mod-3280    0.... 351920340us : 0xffffffffa0160cdb: rcs0
<0> [353.872487] i915_mod-3280    0.... 351920358us : 0xffffffffa0160cdb: bcs0
<0> [353.872506] i915_mod-3280    0.... 351920373us : 0xffffffffa0160cdb: vcs0
<0> [353.872526] i915_mod-3280    0.... 351920391us : 0xffffffffa0160cdb: vecs0
<0> [353.872546] i915_mod-3280    0.... 351920441us : 0xffffffffa017d058: engine_mask=ffffffff, ret=0, retry=0
<0> [353.872570] i915_mod-3280    0.... 351920442us : 0xffffffffa0161650: 
<0> [353.872591] CPU:1 [LOST 921083 EVENTS]\x0ai915_mod-3280    1.... 351987471us : 0xffffffffa014b770: rcs0 fence 1665:1
<0> [353.872619] i915_mod-3280    1.... 351987576us : 0xffffffffa014bd19: marking (null) as active
<0> [353.872642] i915_mod-3280    1d..1 351987679us : 0xffffffffa016cc00: rcs0 cs-irq head=5, tail=5
<0> [353.872666] i915_mod-3280    1d..1 351987680us : 0xffffffffa014a980: rcs0 fence 1665:1 -> global=1, current 0
<0> [353.872691] i915_mod-3280    1d..1 351987834us : 0xffffffffa016dc57: rcs0 in[0]:  ctx=2.1, global=1 (fence 1665:1) (current 0), prio=2
<0> [353.872719] i915_mod-3280    1.... 351988383us : 0xffffffffa014b770: bcs0 fence 1666:1
<0> [353.872741] i915_mod-3280    1.... 351988386us : 0xffffffffa014bd19: marking (null) as active
<0> [353.872768] i915_mod-3280    1d..1 351988392us : 0xffffffffa016cc00: bcs0 cs-irq head=5, tail=5
<0> [353.872792] i915_mod-3280    1d..1 351988394us : 0xffffffffa014a980: bcs0 fence 1666:1 -> global=1, current 0
<0> [353.872817] i915_mod-3280    1d..1 351988400us : 0xffffffffa016dc57: bcs0 in[0]:  ctx=2.1, global=1 (fence 1666:1) (current 0), prio=2
<0> [353.872845] i915_mod-3280    1.... 351988666us : 0xffffffffa014b770: vcs0 fence 1667:1
<0> [353.872867] i915_mod-3280    1.... 351988669us : 0xffffffffa014bd19: marking (null) as active
<0> [353.872889] i915_mod-3280    1d..1 351988674us : 0xffffffffa016cc00: vcs0 cs-irq head=5, tail=5
<0> [353.872913] i915_mod-3280    1d..1 351988675us : 0xffffffffa014a980: vcs0 fence 1667:1 -> global=1, current 0
<0> [353.872938] i915_mod-3280    1d..1 351988679us : 0xffffffffa016dc57: vcs0 in[0]:  ctx=2.1, global=1 (fence 1667:1) (current 0), prio=2
<0> [353.872966] i915_mod-3280    1.... 351988979us : 0xffffffffa014b770: vecs0 fence 1668:1
<0> [353.872988] i915_mod-3280    1.... 351988982us : 0xffffffffa014bd19: marking (null) as active
<0> [353.873010] i915_mod-3280    1d..1 351988987us : 0xffffffffa016cc00: vecs0 cs-irq head=5, tail=5
<0> [353.873034] i915_mod-3280    1d..1 351988988us : 0xffffffffa014a980: vecs0 fence 1668:1 -> global=1, current 0
<0> [353.873060] i915_mod-3280    1d..1 351988992us : 0xffffffffa016dc57: vecs0 in[0]:  ctx=2.1, global=1 (fence 1668:1) (current 0), prio=2
<0> [353.873087] i915_mod-3280    1.... 351988997us : 0xffffffffa01125f0: awake?=yes
<0> [353.873109] i915_mod-3280    1.... 351988999us : 0xffffffffa0149d40: vcs0 fence 1667:1, global=1, current 1
<0> [353.873133] i915_mod-3280    1.... 351989045us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.873157] i915_mod-3280    1.... 351989047us : 0xffffffffa0149fd3: __retire_engine_request(vcs0) fence 1667:1, global=1, current 1
<0> [353.873185] i915_mod-3280    1.... 351989331us : 0xffffffffa0149d40: bcs0 fence 1666:1, global=1, current 1
<0> [353.873209] i915_mod-3280    1.... 351989332us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.873233] i915_mod-3280    1.... 351989333us : 0xffffffffa0149fd3: __retire_engine_request(bcs0) fence 1666:1, global=1, current 1
<0> [353.873260] i915_mod-3280    1.... 351989346us : 0xffffffffa0149d40: rcs0 fence 1665:1, global=1, current 1
<0> [353.873285] i915_mod-3280    1.... 351989346us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.873308] i915_mod-3280    1.... 351989359us : 0xffffffffa0149fd3: __retire_engine_request(rcs0) fence 1665:1, global=1, current 1
<0> [353.873335] i915_mod-3280    1.... 351989370us : 0xffffffffa01126ab: emit barrier on rcs0
<0> [353.873358] i915_mod-3280    1.... 351989386us : 0xffffffffa014b770: rcs0 fence 165a:1
<0> [353.873379] i915_mod-3280    1.... 351989388us : 0xffffffffa014bd19: marking (null) as active
<0> [353.873402] i915_mod-3280    1d..1 351989463us : 0xffffffffa016cc00: rcs0 cs-irq head=1, tail=1
<0> [353.873426] i915_mod-3280    1d..1 351989465us : 0xffffffffa014a980: rcs0 fence 165a:1 -> global=2, current 1
<0> [353.873452] i915_mod-3280    1d..1 351989505us : 0xffffffffa016dc57: rcs0 in[0]:  ctx=0.1, global=2 (fence 165a:1) (current 1), prio=-4094
<0> [353.873480] i915_mod-3280    1.... 351989510us : 0xffffffffa01126ab: emit barrier on bcs0
<0> [353.873502] i915_mod-3280    1.... 351989522us : 0xffffffffa014b770: bcs0 fence 165d:1
<0> [353.873524] i915_mod-3280    1.... 351989524us : 0xffffffffa014bd19: marking (null) as active
<0> [353.873546] i915_mod-3280    1d..1 351989537us : 0xffffffffa016cc00: bcs0 cs-irq head=1, tail=1
<0> [353.873570] i915_mod-3280    1d..1 351989538us : 0xffffffffa014a980: bcs0 fence 165d:1 -> global=2, current 1
<0> [353.873595] i915_mod-3280    1d..1 351989551us : 0xffffffffa016dc57: bcs0 in[0]:  ctx=0.1, global=2 (fence 165d:1) (current 1), prio=-4094
<0> [353.873623] i915_mod-3280    1.... 351989555us : 0xffffffffa01126ab: emit barrier on vcs0
<0> [353.873645] i915_mod-3280    1.... 351989567us : 0xffffffffa014b770: vcs0 fence 1660:1
<0> [353.873667] i915_mod-3280    1.... 351989569us : 0xffffffffa014bd19: marking (null) as active
<0> [353.873690] i915_mod-3280    1d..1 351989581us : 0xffffffffa016cc00: vcs0 cs-irq head=1, tail=1
<0> [353.873714] i915_mod-3280    1d..1 351989582us : 0xffffffffa014a980: vcs0 fence 1660:1 -> global=2, current 1
<0> [353.873740] i915_mod-3280    1d..1 351989594us : 0xffffffffa016dc57: vcs0 in[0]:  ctx=0.1, global=2 (fence 1660:1) (current 1), prio=-4094
<0> [353.873769] i915_mod-3280    1.... 351989600us : 0xffffffffa010e586: last request for (null) on engine vecs0: 1668:1
<0> [353.873794] i915_mod-3280    1.... 351989601us : 0xffffffffa010ea5a: (null) needs barrier for 1668:1
<0> [353.873818] i915_mod-3280    1.... 351989601us : 0xffffffffa01126ab: emit barrier on vecs0
<0> [353.873840] i915_mod-3280    1.... 351989614us : 0xffffffffa010e586: last request for (null) on engine vecs0: 1668:1
<0> [353.873866] i915_mod-3280    1.... 351989615us : 0xffffffffa011272d: add barrier on vecs0 for 1668:1
<0> [353.873889] i915_mod-3280    1.... 351989626us : 0xffffffffa014b770: vecs0 fence 1663:1
<0> [353.873911] i915_mod-3280    1.... 351989628us : 0xffffffffa014bd19: marking (null) as active
<0> [353.873934] i915_mod-3280    1d..1 351989640us : 0xffffffffa016cc00: vecs0 cs-irq head=1, tail=1
<0> [353.873957] i915_mod-3280    1d..1 351989641us : 0xffffffffa014a980: vecs0 fence 1663:1 -> global=2, current 1
<0> [353.873983] i915_mod-3280    1d..1 351989653us : 0xffffffffa016dc57: vecs0 in[0]:  ctx=0.1, global=2 (fence 1663:1) (current 1), prio=-4094
<0> [353.874012] i915_mod-3280    1.... 351989658us : 0xffffffffa0133d60: flags=2 (locked), timeout=200
<0> [353.874035] i915_mod-3280    1.... 351989699us : 0xffffffffa0149d40: vecs0 fence 1663:1, global=2, current 2
<0> [353.874060] i915_mod-3280    1.... 351989700us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.874083] i915_mod-3280    1.... 351989701us : 0xffffffffa0149fd3: __retire_engine_request(vecs0) fence 1668:1, global=1, current 2
<0> [353.874112] i915_mod-3280    1.... 351989704us : 0xffffffffa0149fd3: __retire_engine_request(vecs0) fence 1663:1, global=2, current 2
<0> [353.874140] i915_mod-3280    1.... 351989716us : 0xffffffffa0149d40: vcs0 fence 1660:1, global=2, current 2
<0> [353.874164] i915_mod-3280    1.... 351989717us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.874187] i915_mod-3280    1.... 351989718us : 0xffffffffa0149fd3: __retire_engine_request(vcs0) fence 1660:1, global=2, current 2
<0> [353.874215] i915_mod-3280    1.... 351989734us : 0xffffffffa0149d40: bcs0 fence 165d:1, global=2, current 2
<0> [353.874239] i915_mod-3280    1.... 351989735us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.874263] i915_mod-3280    1.... 351989736us : 0xffffffffa0149fd3: __retire_engine_request(bcs0) fence 165d:1, global=2, current 2
<0> [353.874291] i915_mod-3280    1.... 351989750us : 0xffffffffa0149d40: rcs0 fence 165a:1, global=2, current 2
<0> [353.874315] i915_mod-3280    1.... 351989750us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.874338] i915_mod-3280    1.... 351989751us : 0xffffffffa0149fd3: __retire_engine_request(rcs0) fence 165a:1, global=2, current 2
<0> [353.874366] i915_mod-3280    1.... 351989765us : 0xffffffffa0149d40: vecs0 fence 1668:1, global=1, current 2
<0> [353.874391] i915_mod-3280    1.... 351989765us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.874413] i915_mod-3280    1.... 351989769us : 0xffffffffa012f670: 
<0> [353.874432] i915_mod-3280    1.... 351989784us : 0xffffffffa012d590: 
<0> [353.874451] i915_mod-3280    1.... 351990197us : 0xffffffffa013b9d0: 
<0> [353.874470] i915_mod-3280    1.... 351990201us : 0xffffffffa01125f0: awake?=no
<0> [353.874491] i915_mod-3280    1.... 351990203us : 0xffffffffa0133d60: flags=13 (locked), timeout=9223372036854775807 (forever)
<0> [353.874517] i915_mod-3280    1.... 351991501us : 0xffffffffa013b910: 
<0> [353.874537] i915_mod-3280    1.... 351991511us : 0xffffffffa0160cdb: rcs0
<0> [353.874557] i915_mod-3280    1.... 351991529us : 0xffffffffa0160cdb: bcs0
<0> [353.874576] i915_mod-3280    1.... 351991544us : 0xffffffffa0160cdb: vcs0
<0> [353.874596] i915_mod-3280    1.... 351991562us : 0xffffffffa0160cdb: vecs0
<0> [353.874616] i915_mod-3280    1.... 351991613us : 0xffffffffa017d058: engine_mask=ffffffff, ret=0, retry=0
<0> [353.874640] i915_mod-3280    1.... 351991614us : 0xffffffffa0161650: 
<0> [353.874660] i915_mod-3280    1.... 351991615us : 0xffffffffa016e900: rcs0 request global=0, current=2
<0> [353.874683] i915_mod-3280    1.... 351991618us : 0xffffffffa016e900: bcs0 request global=0, current=2
<0> [353.874708] i915_mod-3280    1.... 351991619us : 0xffffffffa016e900: vcs0 request global=0, current=2
<0> [353.874731] i915_mod-3280    1.... 351991620us : 0xffffffffa016e900: vecs0 request global=0, current=2
<0> [353.874755] i915_mod-3280    1.... 351999582us : 0xffffffffa0133470: start
<0> [353.874775] i915_mod-3280    1.... 352000857us : 0xffffffffa016d390: rcs0: depth<-0
<0> [353.874796] i915_mod-3280    1d..1 352000861us : 0xffffffffa016cc00: rcs0 cs-irq head=5, tail=5
<0> [353.874819] i915_mod-3280    1.... 352000862us : 0xffffffffa016d390: bcs0: depth<-0
<0> [353.874841] i915_mod-3280    1d..1 352000863us : 0xffffffffa016cc00: bcs0 cs-irq head=5, tail=5
<0> [353.874863] i915_mod-3280    1.... 352000864us : 0xffffffffa016d390: vcs0: depth<-0
<0> [353.874885] i915_mod-3280    1d..1 352000864us : 0xffffffffa016cc00: vcs0 cs-irq head=5, tail=5
<0> [353.874908] i915_mod-3280    1.... 352000865us : 0xffffffffa016d390: vecs0: depth<-0
<0> [353.874929] i915_mod-3280    1d..1 352000866us : 0xffffffffa016cc00: vecs0 cs-irq head=5, tail=5
<0> [353.874952] i915_mod-3280    1.... 352000868us : 0xffffffffa0160cdb: rcs0
<0> [353.874971] i915_mod-3280    1.... 352000885us : 0xffffffffa0160cdb: bcs0
<0> [353.874991] i915_mod-3280    1.... 352000901us : 0xffffffffa0160cdb: vcs0
<0> [353.875010] i915_mod-3280    1.... 352000961us : 0xffffffffa0160cdb: vecs0
<0> [353.875030] i915_mod-3280    1.... 352001011us : 0xffffffffa017d058: engine_mask=ffffffff, ret=0, retry=0
<0> [353.875054] i915_mod-3280    1.... 352007068us : 0xffffffffa016e590: rcs0 current 2
<0> [353.875075] i915_mod-3280    1.... 352007073us : 0xffffffffa016e590: bcs0 current 2
<0> [353.875096] i915_mod-3280    1.... 352007075us : 0xffffffffa016e590: vcs0 current 2
<0> [353.875118] i915_mod-3280    1.... 352007077us : 0xffffffffa016e590: vecs0 current 2
<0> [353.875139] i915_mod-3280    1.... 352016156us : 0xffffffffa0167373: rcs0: depth->0
<0> [353.875161] i915_mod-3280    1.... 352016162us : 0xffffffffa0167373: bcs0: depth->0
<0> [353.875182] i915_mod-3280    1.... 352016165us : 0xffffffffa0167373: vcs0: depth->0
<0> [353.875203] i915_mod-3280    1.... 352016168us : 0xffffffffa0167373: vecs0: depth->0
<0> [353.875224] i915_mod-3280    1.... 352016178us : 0xffffffffa0133603: end
<0> [353.875243] i915_mod-3280    0.... 352268783us : 0xffffffffa013b9d0: 
<0> [353.875261] i915_mod-3280    0.... 352300447us : 0xffffffffa013b910: 
<0> [353.875280] i915_mod-3280    0.... 352300648us : 0xffffffffa0133887: start
<0> [353.875299] i915_mod-3280    0.... 352300657us : 0xffffffffa0160cdb: rcs0
<0> [353.875317] i915_mod-3280    0.... 352300674us : 0xffffffffa0160cdb: bcs0
<0> [353.875336] i915_mod-3280    0.... 352300690us : 0xffffffffa0160cdb: vcs0
<0> [353.875355] i915_mod-3280    0.... 352300708us : 0xffffffffa0160cdb: vecs0
<0> [353.875375] i915_mod-3280    0.... 352300757us : 0xffffffffa017d058: engine_mask=ffffffff, ret=0, retry=0
<0> [353.875398] i915_mod-3280    0.... 352300758us : 0xffffffffa0161650: 
<0> [353.875417] i915_mod-3280    0.... 352300760us : 0xffffffffa016e900: rcs0 request global=0, current=2
<0> [353.875440] i915_mod-3280    0.... 352300762us : 0xffffffffa016e900: bcs0 request global=0, current=2
<0> [353.875463] i915_mod-3280    0.... 352300764us : 0xffffffffa016e900: vcs0 request global=0, current=2
<0> [353.875486] i915_mod-3280    0.... 352300765us : 0xffffffffa016e900: vecs0 request global=0, current=2
<0> [353.875509] i915_mod-3280    0.... 352300768us : 0xffffffffa0133998: end
<0> [353.875528] i915_mod-3280    0.... 352300769us : 0xffffffffa0160cdb: rcs0
<0> [353.875548] i915_mod-3280    0.... 352300786us : 0xffffffffa0160cdb: bcs0
<0> [353.875566] i915_mod-3280    0.... 352300801us : 0xffffffffa0160cdb: vcs0
<0> [353.875585] i915_mod-3280    0.... 352300819us : 0xffffffffa0160cdb: vecs0
<0> [353.875605] i915_mod-3280    0.... 352300867us : 0xffffffffa017d058: engine_mask=ffffffff, ret=0, retry=0
<0> [353.875628] i915_mod-3280    0.... 352300868us : 0xffffffffa0161650: 
<0> [353.875647] i915_mod-3280    0.... 352300869us : 0xffffffffa016e900: rcs0 request global=0, current=2
<0> [353.875670] i915_mod-3280    0.... 352300870us : 0xffffffffa016e900: bcs0 request global=0, current=2
<0> [353.875693] i915_mod-3280    0.... 352300871us : 0xffffffffa016e900: vcs0 request global=0, current=2
<0> [353.875716] i915_mod-3280    0.... 352300872us : 0xffffffffa016e900: vecs0 request global=0, current=2
<0> [353.875840] CPU:3 [LOST 1048713 EVENTS]\x0ai915_mod-3280    3.... 352702305us : i915_request_add: marking (null) as active
<0> [353.875957] i915_mod-3280    3d..1 352702311us : process_csb: bcs0 cs-irq head=5, tail=5
<0> [353.876050] i915_mod-3280    3d..1 352702312us : __i915_request_submit: bcs0 fence 167a:1 -> global=1, current 0
<0> [353.876147] i915_mod-3280    3d..1 352702317us : __execlists_submission_tasklet: bcs0 in[0]:  ctx=2.1, global=1 (fence 167a:1) (current 0), prio=2
<0> [353.876245] i915_mod-3280    3.... 352702665us : i915_request_add: vcs0 fence 167b:1
<0> [353.876334] i915_mod-3280    3.... 352702667us : i915_request_add: marking (null) as active
<0> [353.876428] i915_mod-3280    3d..1 352702672us : process_csb: vcs0 cs-irq head=5, tail=5
<0> [353.876519] i915_mod-3280    3d..1 352702673us : __i915_request_submit: vcs0 fence 167b:1 -> global=1, current 0
<0> [353.876615] i915_mod-3280    3d..1 352702677us : __execlists_submission_tasklet: vcs0 in[0]:  ctx=2.1, global=1 (fence 167b:1) (current 0), prio=2
<0> [353.876713] i915_mod-3280    3.... 352703049us : i915_request_add: vecs0 fence 167c:1
<0> [353.876802] i915_mod-3280    3.... 352703051us : i915_request_add: marking (null) as active
<0> [353.876895] i915_mod-3280    3d..1 352703056us : process_csb: vecs0 cs-irq head=5, tail=5
<0> [353.876986] i915_mod-3280    3d..1 352703057us : __i915_request_submit: vecs0 fence 167c:1 -> global=1, current 0
<0> [353.877083] i915_mod-3280    3d..1 352703062us : __execlists_submission_tasklet: vecs0 in[0]:  ctx=2.1, global=1 (fence 167c:1) (current 0), prio=2
<0> [353.877177] i915_mod-3280    3.... 352703066us : i915_gem_switch_to_kernel_context: awake?=yes
<0> [353.877269] i915_mod-3280    3.... 352703068us : i915_request_retire: vcs0 fence 167b:1, global=1, current 1
<0> [353.877361] i915_mod-3280    3.... 352703069us : i915_request_retire: marking (null) as inactive
<0> [353.877453] i915_mod-3280    3.... 352703071us : i915_request_retire: __retire_engine_request(vcs0) fence 167b:1, global=1, current 1
<0> [353.877549] i915_mod-3280    3.... 352703325us : i915_request_retire: bcs0 fence 167a:1, global=1, current 1
<0> [353.877641] i915_mod-3280    3.... 352703327us : i915_request_retire: marking (null) as inactive
<0> [353.877733] i915_mod-3280    3.... 352703328us : i915_request_retire: __retire_engine_request(bcs0) fence 167a:1, global=1, current 1
<0> [353.877829] i915_mod-3280    3.... 352703340us : i915_request_retire: rcs0 fence 1679:1, global=1, current 1
<0> [353.877921] i915_mod-3280    3.... 352703341us : i915_request_retire: marking (null) as inactive
<0> [353.878014] i915_mod-3280    3.... 352703353us : i915_request_retire: __retire_engine_request(rcs0) fence 1679:1, global=1, current 1
<0> [353.878110] i915_mod-3280    3.... 352703365us : i915_gem_switch_to_kernel_context: emit barrier on rcs0
<0> [353.878203] i915_mod-3280    3.... 352703380us : i915_request_add: rcs0 fence 166e:1
<0> [353.878303] i915_mod-3280    3.... 352703382us : i915_request_add: marking (null) as active
<0> [353.878400] i915_mod-3280    3d..1 352703458us : process_csb: rcs0 cs-irq head=1, tail=1
<0> [353.878494] i915_mod-3280    3d..1 352703459us : __i915_request_submit: rcs0 fence 166e:1 -> global=2, current 1
<0> [353.878596] i915_mod-3280    3d..1 352703498us : __execlists_submission_tasklet: rcs0 in[0]:  ctx=0.1, global=2 (fence 166e:1) (current 1), prio=-4094
<0> [353.878692] i915_mod-3280    3.... 352703503us : i915_gem_switch_to_kernel_context: emit barrier on bcs0
<0> [353.878786] i915_mod-3280    3.... 352703516us : i915_request_add: bcs0 fence 1671:1
<0> [353.878877] i915_mod-3280    3.... 352703517us : i915_request_add: marking (null) as active
<0> [353.878970] i915_mod-3280    3d..1 352703530us : process_csb: bcs0 cs-irq head=1, tail=1
<0> [353.879062] i915_mod-3280    3d..1 352703531us : __i915_request_submit: bcs0 fence 1671:1 -> global=2, current 1
<0> [353.879160] i915_mod-3280    3d..1 352703543us : __execlists_submission_tasklet: bcs0 in[0]:  ctx=0.1, global=2 (fence 1671:1) (current 1), prio=-4094
<0> [353.879255] i915_mod-3280    3.... 352703547us : i915_gem_switch_to_kernel_context: emit barrier on vcs0
<0> [353.879348] i915_mod-3280    3.... 352703559us : i915_request_add: vcs0 fence 1674:1
<0> [353.879440] i915_mod-3280    3.... 352703561us : i915_request_add: marking (null) as active
<0> [353.879534] i915_mod-3280    3d..1 352703573us : process_csb: vcs0 cs-irq head=1, tail=1
<0> [353.879626] i915_mod-3280    3d..1 352703574us : __i915_request_submit: vcs0 fence 1674:1 -> global=2, current 1
<0> [353.879722] i915_mod-3280    3d..1 352703586us : __execlists_submission_tasklet: vcs0 in[0]:  ctx=0.1, global=2 (fence 1674:1) (current 1), prio=-4094
<0> [353.879817] i915_mod-3280    3.... 352703591us : last_request_on_engine: last request for (null) on engine vecs0: 167c:1
<0> [353.879907] i915_mod-3280    3.... 352703592us : engine_has_kernel_context_barrier: (null) needs barrier for 167c:1
<0> [353.880001] i915_mod-3280    3.... 352703592us : i915_gem_switch_to_kernel_context: emit barrier on vecs0
<0> [353.880092] i915_mod-3280    3.... 352703604us : last_request_on_engine: last request for (null) on engine vecs0: 167c:1
<0> [353.880188] i915_mod-3280    3.... 352703605us : i915_gem_switch_to_kernel_context: add barrier on vecs0 for 167c:1
<0> [353.880287] i915_mod-3280    3.... 352703617us : i915_request_add: vecs0 fence 1677:1
<0> [353.880380] i915_mod-3280    3.... 352703618us : i915_request_add: marking (null) as active
<0> [353.880476] i915_mod-3280    3d..1 352703631us : process_csb: vecs0 cs-irq head=1, tail=1
<0> [353.880569] i915_mod-3280    3d..1 352703632us : __i915_request_submit: vecs0 fence 1677:1 -> global=2, current 1
<0> [353.880666] i915_mod-3280    3d..1 352703644us : __execlists_submission_tasklet: vecs0 in[0]:  ctx=0.1, global=2 (fence 1677:1) (current 1), prio=-4094
<0> [353.880765] i915_mod-3280    3.... 352703649us : i915_gem_wait_for_idle: flags=2 (locked), timeout=200
<0> [353.880857] i915_mod-3280    3.... 352703688us : i915_request_retire: vecs0 fence 1677:1, global=2, current 2
<0> [353.880951] i915_mod-3280    3.... 352703689us : i915_request_retire: marking (null) as inactive
<0> [353.881043] i915_mod-3280    3.... 352703690us : i915_request_retire: __retire_engine_request(vecs0) fence 167c:1, global=1, current 2
<0> [353.881140] i915_mod-3280    3.... 352703693us : i915_request_retire: __retire_engine_request(vecs0) fence 1677:1, global=2, current 2
<0> [353.881240] i915_mod-3280    3.... 352703704us : i915_request_retire: vcs0 fence 1674:1, global=2, current 2
<0> [353.881333] i915_mod-3280    3.... 352703705us : i915_request_retire: marking (null) as inactive
<0> [353.881424] i915_mod-3280    3.... 352703706us : i915_request_retire: __retire_engine_request(vcs0) fence 1674:1, global=2, current 2
<0> [353.881520] i915_mod-3280    3.... 352703722us : i915_request_retire: bcs0 fence 1671:1, global=2, current 2
<0> [353.881613] i915_mod-3280    3.... 352703722us : i915_request_retire: marking (null) as inactive
<0> [353.881707] i915_mod-3280    3.... 352703723us : i915_request_retire: __retire_engine_request(bcs0) fence 1671:1, global=2, current 2
<0> [353.881807] i915_mod-3280    3.... 352703737us : i915_request_retire: rcs0 fence 166e:1, global=2, current 2
<0> [353.881900] i915_mod-3280    3.... 352703737us : i915_request_retire: marking (null) as inactive
<0> [353.881991] i915_mod-3280    3.... 352703738us : i915_request_retire: __retire_engine_request(rcs0) fence 166e:1, global=2, current 2
<0> [353.882088] i915_mod-3280    3.... 352703751us : i915_request_retire: vecs0 fence 167c:1, global=1, current 2
<0> [353.882180] i915_mod-3280    3.... 352703752us : i915_request_retire: marking (null) as inactive
<0> [353.882270] i915_mod-3280    3.... 352703755us : i915_gem_park: 
<0> [353.882354] i915_mod-3280    3.... 352703771us : __i915_gem_park: 
<0> [353.882439] i915_mod-3280    0.... 352957225us : i915_gem_suspend: 
<0> [353.882522] i915_mod-3280    0.... 352957233us : i915_gem_switch_to_kernel_context: awake?=no
<0> [353.882613] i915_mod-3280    0.... 352957239us : i915_gem_wait_for_idle: flags=13 (locked), timeout=9223372036854775807 (forever)
<0> [353.882707] i915_mod-3280    0.... 352983690us : i915_gem_sanitize: 
<0> [353.882797] i915_mod-3280    0.... 352983906us : intel_engine_stop_cs: rcs0
<0> [353.882886] i915_mod-3280    0.... 352983953us : intel_engine_stop_cs: bcs0
<0> [353.882975] i915_mod-3280    0.... 352983969us : intel_engine_stop_cs: vcs0
<0> [353.883064] i915_mod-3280    0.... 352983987us : intel_engine_stop_cs: vecs0
<0> [353.883156] i915_mod-3280    0.... 352984038us : intel_gpu_reset: engine_mask=ffffffff, ret=0, retry=0
<0> [353.883249] i915_mod-3280    0.... 352984040us : intel_engines_sanitize: 
<0> [353.883339] i915_mod-3280    0.... 352984042us : execlists_reset: rcs0 request global=0, current=2
<0> [353.883433] i915_mod-3280    0.... 352984045us : execlists_reset: bcs0 request global=0, current=2
<0> [353.883526] i915_mod-3280    0.... 352984046us : execlists_reset: vcs0 request global=0, current=2
<0> [353.883619] i915_mod-3280    0.... 352984048us : execlists_reset: vecs0 request global=0, current=2
<0> [353.883646] CPU:2 [LOST 713842 EVENTS]\x0ai915_mod-3280    2d.s1 353384712us : 0xffffffffa016cec5: rcs0 completed ctx=2
<0> [353.883677] i915_mod-3280    2.... 353385121us : 0xffffffffa014b770: bcs0 fence 168e:1
<0> [353.883698] i915_mod-3280    2.... 353385124us : 0xffffffffa014bd19: marking (null) as active
<0> [353.883720] i915_mod-3280    2d..1 353385130us : 0xffffffffa016cc00: bcs0 cs-irq head=5, tail=5
<0> [353.883743] i915_mod-3280    2d..1 353385131us : 0xffffffffa014a980: bcs0 fence 168e:1 -> global=1, current 0
<0> [353.883768] i915_mod-3280    2d..1 353385136us : 0xffffffffa016dc57: bcs0 in[0]:  ctx=2.1, global=1 (fence 168e:1) (current 0), prio=2
<0> [353.883799] i915_mod-3280    2..s. 353385147us : 0xffffffffa016e100: bcs0 awake?=1, active=1
<0> [353.883820] i915_mod-3280    2d.s1 353385148us : 0xffffffffa016cc00: bcs0 cs-irq head=5, tail=1
<0> [353.883845] i915_mod-3280    2d.s1 353385149us : 0xffffffffa016cc9c: bcs0 csb[0]: status=0x00000001:0x00000000, active=0x1
<0> [353.883871] i915_mod-3280    2d.s1 353385149us : 0xffffffffa016cc9c: bcs0 csb[1]: status=0x00000018:0x00000002, active=0x5
<0> [353.883899] i915_mod-3280    2d.s1 353385150us : 0xffffffffa016cd7e: bcs0 out[0]: ctx=2.1, global=1 (fence 168e:1) (current 1), prio=2
<0> [353.883926] i915_mod-3280    2d.s1 353385151us : 0xffffffffa016cec5: bcs0 completed ctx=2
<0> [353.883948] i915_mod-3280    2..s. 353385156us : 0xffffffffa016e100: bcs0 awake?=1, active=0
<0> [353.883970] i915_mod-3280    2d.s1 353385157us : 0xffffffffa016cc00: bcs0 cs-irq head=1, tail=1
<0> [353.883992] i915_mod-3280    2.... 353385425us : 0xffffffffa014b770: vcs0 fence 168f:1
<0> [353.884013] i915_mod-3280    2.... 353385427us : 0xffffffffa014bd19: marking (null) as active
<0> [353.884035] i915_mod-3280    2d..1 353385432us : 0xffffffffa016cc00: vcs0 cs-irq head=5, tail=5
<0> [353.884058] i915_mod-3280    2d..1 353385433us : 0xffffffffa014a980: vcs0 fence 168f:1 -> global=1, current 0
<0> [353.884082] i915_mod-3280    2d..1 353385438us : 0xffffffffa016dc57: vcs0 in[0]:  ctx=2.1, global=1 (fence 168f:1) (current 0), prio=2
<0> [353.884109] i915_mod-3280    2..s. 353385448us : 0xffffffffa016e100: vcs0 awake?=1, active=1
<0> [353.884131] i915_mod-3280    2d.s1 353385449us : 0xffffffffa016cc00: vcs0 cs-irq head=5, tail=1
<0> [353.884154] i915_mod-3280    2d.s1 353385450us : 0xffffffffa016cc9c: vcs0 csb[0]: status=0x00000001:0x00000000, active=0x1
<0> [353.884180] i915_mod-3280    2d.s1 353385450us : 0xffffffffa016cc9c: vcs0 csb[1]: status=0x00000018:0x00000002, active=0x5
<0> [353.884206] i915_mod-3280    2d.s1 353385452us : 0xffffffffa016cd7e: vcs0 out[0]: ctx=2.1, global=1 (fence 168f:1) (current 1), prio=2
<0> [353.884233] i915_mod-3280    2d.s1 353385452us : 0xffffffffa016cec5: vcs0 completed ctx=2
<0> [353.884255] i915_mod-3280    2..s. 353385457us : 0xffffffffa016e100: vcs0 awake?=1, active=0
<0> [353.884277] i915_mod-3280    2d.s1 353385458us : 0xffffffffa016cc00: vcs0 cs-irq head=1, tail=1
<0> [353.884299] i915_mod-3280    2.... 353385720us : 0xffffffffa014b770: vecs0 fence 1690:1
<0> [353.884320] i915_mod-3280    2.... 353385722us : 0xffffffffa014bd19: marking (null) as active
<0> [353.884342] i915_mod-3280    2d..1 353385727us : 0xffffffffa016cc00: vecs0 cs-irq head=5, tail=5
<0> [353.884365] i915_mod-3280    2d..1 353385728us : 0xffffffffa014a980: vecs0 fence 1690:1 -> global=1, current 0
<0> [353.884390] i915_mod-3280    2d..1 353385733us : 0xffffffffa016dc57: vecs0 in[0]:  ctx=2.1, global=1 (fence 1690:1) (current 0), prio=2
<0> [353.884416] i915_mod-3280    2.... 353385737us : 0xffffffffa01125f0: awake?=yes
<0> [353.884437] i915_mod-3280    2..s2 353385737us : 0xffffffffa016e100: vecs0 awake?=1, active=1
<0> [353.884459] i915_mod-3280    2d.s3 353385737us : 0xffffffffa016cc00: vecs0 cs-irq head=5, tail=1
<0> [353.884481] i915_mod-3280    2d.s3 353385737us : 0xffffffffa016cc9c: vecs0 csb[0]: status=0x00000001:0x00000000, active=0x1
<0> [353.884508] i915_mod-3280    2d.s3 353385737us : 0xffffffffa016cc9c: vecs0 csb[1]: status=0x00000018:0x00000002, active=0x5
<0> [353.884534] i915_mod-3280    2d.s3 353385737us : 0xffffffffa016cd7e: vecs0 out[0]: ctx=2.1, global=1 (fence 1690:1) (current 1), prio=2
<0> [353.884561] i915_mod-3280    2d.s3 353385737us : 0xffffffffa016cec5: vecs0 completed ctx=2
<0> [353.884583] i915_mod-3280    2..s2 353385737us : 0xffffffffa016e100: vecs0 awake?=1, active=0
<0> [353.884605] i915_mod-3280    2d.s3 353385737us : 0xffffffffa016cc00: vecs0 cs-irq head=1, tail=1
<0> [353.884627] i915_mod-3280    2.... 353385755us : 0xffffffffa0149d40: vecs0 fence 1690:1, global=1, current 1
<0> [353.884651] i915_mod-3280    2.... 353385757us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.884674] i915_mod-3280    2.... 353385758us : 0xffffffffa0149fd3: __retire_engine_request(vecs0) fence 1690:1, global=1, current 1
<0> [353.884701] i915_mod-3280    2.... 353386110us : 0xffffffffa0149d40: vcs0 fence 168f:1, global=1, current 1
<0> [353.884724] i915_mod-3280    2.... 353386112us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.884747] i915_mod-3280    2.... 353386114us : 0xffffffffa0149fd3: __retire_engine_request(vcs0) fence 168f:1, global=1, current 1
<0> [353.884774] i915_mod-3280    2.... 353386125us : 0xffffffffa0149d40: bcs0 fence 168e:1, global=1, current 1
<0> [353.884798] i915_mod-3280    2.... 353386126us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.884820] i915_mod-3280    2.... 353386127us : 0xffffffffa0149fd3: __retire_engine_request(bcs0) fence 168e:1, global=1, current 1
<0> [353.884847] i915_mod-3280    2.... 353386137us : 0xffffffffa0149d40: rcs0 fence 168d:1, global=1, current 1
<0> [353.884871] i915_mod-3280    2.... 353386138us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.884893] i915_mod-3280    2.... 353386151us : 0xffffffffa0149fd3: __retire_engine_request(rcs0) fence 168d:1, global=1, current 1
<0> [353.884920] i915_mod-3280    2.... 353386152us : 0xffffffffa012f670: 
<0> [353.884938] i915_mod-3280    2.... 353386169us : 0xffffffffa01126ab: emit barrier on rcs0
<0> [353.884959] i915_mod-3280    2.... 353386170us : 0xffffffffa012f740: 
<0> [353.884978] i915_mod-3280    2.... 353386185us : 0xffffffffa014b770: rcs0 fence 1682:1
<0> [353.884998] i915_mod-3280    2.... 353386187us : 0xffffffffa014bd19: marking (null) as active
<0> [353.885020] i915_mod-3280    2d..1 353386262us : 0xffffffffa016cc00: rcs0 cs-irq head=1, tail=1
<0> [353.885043] i915_mod-3280    2d..1 353386264us : 0xffffffffa014a980: rcs0 fence 1682:1 -> global=2, current 1
<0> [353.885068] i915_mod-3280    2d..1 353386303us : 0xffffffffa016dc57: rcs0 in[0]:  ctx=0.1, global=2 (fence 1682:1) (current 1), prio=-4094
<0> [353.885095] i915_mod-3280    2.... 353386308us : 0xffffffffa01126ab: emit barrier on bcs0
<0> [353.885117] i915_mod-3280    2..s. 353386316us : 0xffffffffa016e100: rcs0 awake?=1, active=1
<0> [353.885138] i915_mod-3280    2d.s1 353386317us : 0xffffffffa016cc00: rcs0 cs-irq head=1, tail=2
<0> [353.885161] i915_mod-3280    2d.s1 353386318us : 0xffffffffa016cc9c: rcs0 csb[2]: status=0x00000001:0x00000000, active=0x1
<0> [353.885187] i915_mod-3280    2.... 353386331us : 0xffffffffa014b770: bcs0 fence 1685:1
<0> [353.885207] i915_mod-3280    2.... 353386333us : 0xffffffffa014bd19: marking (null) as active
<0> [353.885229] i915_mod-3280    2d..1 353386345us : 0xffffffffa016cc00: bcs0 cs-irq head=1, tail=1
<0> [353.885252] i915_mod-3280    2d..1 353386346us : 0xffffffffa014a980: bcs0 fence 1685:1 -> global=2, current 1
<0> [353.885277] i915_mod-3280    2d..1 353386358us : 0xffffffffa016dc57: bcs0 in[0]:  ctx=0.1, global=2 (fence 1685:1) (current 1), prio=-4094
<0> [353.885304] i915_mod-3280    2..s1 353386374us : 0xffffffffa016e100: rcs0 awake?=1, active=5
<0> [353.885326] i915_mod-3280    2d.s2 353386375us : 0xffffffffa016cc00: rcs0 cs-irq head=2, tail=3
<0> [353.885349] i915_mod-3280    2d.s2 353386376us : 0xffffffffa016cc9c: rcs0 csb[3]: status=0x00000018:0x00000000, active=0x5
<0> [353.885375] i915_mod-3280    2d.s2 353386377us : 0xffffffffa016cd7e: rcs0 out[0]: ctx=0.1, global=2 (fence 1682:1) (current 2), prio=-4094
<0> [353.885403] i915_mod-3280    2d.s2 353386378us : 0xffffffffa016cec5: rcs0 completed ctx=0
<0> [353.885424] i915_mod-3280    2..s1 353386379us : 0xffffffffa016e100: bcs0 awake?=1, active=1
<0> [353.885446] i915_mod-3280    2d.s2 353386380us : 0xffffffffa016cc00: bcs0 cs-irq head=1, tail=3
<0> [353.885469] i915_mod-3280    2d.s2 353386380us : 0xffffffffa016cc9c: bcs0 csb[2]: status=0x00000001:0x00000000, active=0x1
<0> [353.885495] i915_mod-3280    2d.s2 353386381us : 0xffffffffa016cc9c: bcs0 csb[3]: status=0x00000018:0x00000000, active=0x5
<0> [353.885521] i915_mod-3280    2d.s2 353386382us : 0xffffffffa016cd7e: bcs0 out[0]: ctx=0.1, global=2 (fence 1685:1) (current 2), prio=-4094
<0> [353.885548] i915_mod-3280    2d.s2 353386383us : 0xffffffffa016cec5: bcs0 completed ctx=0
<0> [353.885570] i915_mod-3280    2.... 353386385us : 0xffffffffa01126ab: emit barrier on vcs0
<0> [353.885593] i915_mod-3280    2.... 353386397us : 0xffffffffa014b770: vcs0 fence 1688:1
<0> [353.885614] i915_mod-3280    2.... 353386399us : 0xffffffffa014bd19: marking (null) as active
<0> [353.885636] i915_mod-3280    2d..1 353386412us : 0xffffffffa016cc00: vcs0 cs-irq head=1, tail=1
<0> [353.885659] i915_mod-3280    2d..1 353386413us : 0xffffffffa014a980: vcs0 fence 1688:1 -> global=2, current 1
<0> [353.885683] i915_mod-3280    2d..1 353386425us : 0xffffffffa016dc57: vcs0 in[0]:  ctx=0.1, global=2 (fence 1688:1) (current 1), prio=-4094
<0> [353.885711] i915_mod-3280    2.... 353386430us : 0xffffffffa01126ab: emit barrier on vecs0
<0> [353.885732] i915_mod-3280    2..s. 353386435us : 0xffffffffa016e100: vcs0 awake?=1, active=1
<0> [353.885754] i915_mod-3280    2d.s1 353386436us : 0xffffffffa016cc00: vcs0 cs-irq head=1, tail=3
<0> [353.885777] i915_mod-3280    2d.s1 353386437us : 0xffffffffa016cc9c: vcs0 csb[2]: status=0x00000001:0x00000000, active=0x1
<0> [353.885803] i915_mod-3280    2d.s1 353386437us : 0xffffffffa016cc9c: vcs0 csb[3]: status=0x00000018:0x00000000, active=0x5
<0> [353.885829] i915_mod-3280    2d.s1 353386438us : 0xffffffffa016cd7e: vcs0 out[0]: ctx=0.1, global=2 (fence 1688:1) (current 2), prio=-4094
<0> [353.885856] i915_mod-3280    2d.s1 353386439us : 0xffffffffa016cec5: vcs0 completed ctx=0
<0> [353.885878] i915_mod-3280    2..s. 353386444us : 0xffffffffa016e100: vcs0 awake?=1, active=0
<0> [353.885900] i915_mod-3280    2d.s1 353386445us : 0xffffffffa016cc00: vcs0 cs-irq head=3, tail=3
<0> [353.885924] i915_mod-3280    2.... 353386457us : 0xffffffffa014b770: vecs0 fence 168b:1
<0> [353.885945] i915_mod-3280    2.... 353386459us : 0xffffffffa014bd19: marking (null) as active
<0> [353.885967] i915_mod-3280    2d..1 353386472us : 0xffffffffa016cc00: vecs0 cs-irq head=1, tail=1
<0> [353.885989] i915_mod-3280    2d..1 353386472us : 0xffffffffa014a980: vecs0 fence 168b:1 -> global=2, current 1
<0> [353.886015] i915_mod-3280    2d..1 353386485us : 0xffffffffa016dc57: vecs0 in[0]:  ctx=0.1, global=2 (fence 168b:1) (current 1), prio=-4094
<0> [353.886043] i915_mod-3280    2..s1 353386494us : 0xffffffffa016e100: vecs0 awake?=1, active=1
<0> [353.886065] i915_mod-3280    2d.s2 353386495us : 0xffffffffa016cc00: vecs0 cs-irq head=1, tail=3
<0> [353.886088] i915_mod-3280    2d.s2 353386496us : 0xffffffffa016cc9c: vecs0 csb[2]: status=0x00000001:0x00000000, active=0x1
<0> [353.886114] i915_mod-3280    2d.s2 353386496us : 0xffffffffa016cc9c: vecs0 csb[3]: status=0x00000018:0x00000000, active=0x5
<0> [353.886140] i915_mod-3280    2d.s2 353386497us : 0xffffffffa016cd7e: vecs0 out[0]: ctx=0.1, global=2 (fence 168b:1) (current 2), prio=-4094
<0> [353.886168] i915_mod-3280    2d.s2 353386498us : 0xffffffffa016cec5: vecs0 completed ctx=0
<0> [353.886190] i915_mod-3280    2..s1 353386503us : 0xffffffffa016e100: vecs0 awake?=1, active=0
<0> [353.886211] i915_mod-3280    2d.s2 353386504us : 0xffffffffa016cc00: vecs0 cs-irq head=3, tail=3
<0> [353.886234] i915_mod-3280    2.... 353386505us : 0xffffffffa0133d60: flags=2 (locked), timeout=200
<0> [353.886257] i915_mod-3280    2.... 353386545us : 0xffffffffa0149d40: vecs0 fence 168b:1, global=2, current 2
<0> [353.886280] i915_mod-3280    2.... 353386545us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.886303] i915_mod-3280    2.... 353386546us : 0xffffffffa0149fd3: __retire_engine_request(vecs0) fence 168b:1, global=2, current 2
<0> [353.886330] i915_mod-3280    2.... 353386564us : 0xffffffffa0149d40: vcs0 fence 1688:1, global=2, current 2
<0> [353.886354] i915_mod-3280    2.... 353386565us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.886376] i915_mod-3280    2.... 353386566us : 0xffffffffa0149fd3: __retire_engine_request(vcs0) fence 1688:1, global=2, current 2
<0> [353.886403] i915_mod-3280    2.... 353386579us : 0xffffffffa0149d40: bcs0 fence 1685:1, global=2, current 2
<0> [353.886427] i915_mod-3280    2.... 353386580us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.886450] i915_mod-3280    2.... 353386581us : 0xffffffffa0149fd3: __retire_engine_request(bcs0) fence 1685:1, global=2, current 2
<0> [353.886477] i915_mod-3280    2.... 353386594us : 0xffffffffa0149d40: rcs0 fence 1682:1, global=2, current 2
<0> [353.886500] i915_mod-3280    2.... 353386594us : 0xffffffffa014a2fc: marking (null) as inactive
<0> [353.886523] i915_mod-3280    2.... 353386595us : 0xffffffffa0149fd3: __retire_engine_request(rcs0) fence 1682:1, global=2, current 2
<0> [353.886549] i915_mod-3280    2.... 353386600us : 0xffffffffa012f670: 
<0> [353.886567] i915_mod-3280    2.... 353386613us : 0xffffffffa012d590: 
<0> [353.886585] i915_mod-3280    3.... 353554300us : 0xffffffffa013b9d0: 
<0> [353.886603] i915_mod-3280    3.... 353554308us : 0xffffffffa01125f0: awake?=no
<0> [353.886624] i915_mod-3280    3.... 353554314us : 0xffffffffa0133d60: flags=13 (locked), timeout=9223372036854775807 (forever)
<0> [353.886649] i915_mod-3280    3.... 353568495us : 0xffffffffa013b910: 
<0> [353.886667] i915_mod-3280    3.... 353568708us : 0xffffffffa0160cdb: rcs0
<0> [353.886686] i915_mod-3280    3.... 353568726us : 0xffffffffa0160cdb: bcs0
<0> [353.886704] i915_mod-3280    3.... 353568741us : 0xffffffffa0160cdb: vcs0
<0> [353.886723] i915_mod-3280    3.... 353568759us : 0xffffffffa0160cdb: vecs0
<0> [353.886742] i915_mod-3280    3.... 353568810us : 0xffffffffa017d058: engine_mask=ffffffff, ret=0, retry=0
<0> [353.886765] i915_mod-3280    3.... 353568812us : 0xffffffffa0161650: 
<0> [353.886784] i915_mod-3280    3.... 353568813us : 0xffffffffa016e900: rcs0 request global=0, current=2
<0> [353.886807] i915_mod-3280    3.... 353568816us : 0xffffffffa016e900: bcs0 request global=0, current=2
<0> [353.886831] i915_mod-3280    3.... 353568819us : 0xffffffffa016e900: vcs0 request global=0, current=2
<0> [353.886854] i915_mod-3280    3.... 353568821us : 0xffffffffa016e900: vecs0 request global=0, current=2
<0> [353.886963] i915_mod-3280    2.... 353891415us : i915_gem_sanitize: 
<0> [353.887053] i915_mod-3280    2.... 353891470us : intel_engine_stop_cs: rcs0
<0> [353.887148] i915_mod-3280    2.... 353891715us : intel_engine_stop_cs: bcs0
<0> [353.887236] i915_mod-3280    2.... 353891731us : intel_engine_stop_cs: vcs0
<0> [353.887324] i915_mod-3280    2.... 353891749us : intel_engine_stop_cs: vecs0
<0> [353.887417] i915_mod-3280    2.... 353891798us : intel_gpu_reset: engine_mask=ffffffff, ret=0, retry=0
<0> [353.887509] i915_mod-3280    2.... 353891800us : intel_engines_sanitize: 
<3> [353.894117] in_atomic(): 1, irqs_disabled(): 1, pid: 3280, name: i915_module_loa
<4> [353.894851] CPU: 2 PID: 3280 Comm: i915_module_loa Tainted: G     UD           4.20.0-rc3-CI-CI_DRM_5198+ #1
<4> [353.895345]  i915_driver_load+0x845/0x1550 [i915]
<4> [353.895464]  i915_pci_probe+0x29/0xa0 [i915]
<3> [353.895977] BUG: scheduling while atomic: i915_module_loa/3280/0x00000002
<4> [353.901687] CPU: 2 PID: 3280 Comm: i915_module_loa Tainted: G     UD W         4.20.0-rc3-CI-CI_DRM_5198+ #1
<4> [353.902283]  i915_driver_load+0x845/0x1550 [i915]
<4> [353.902392]  i915_pci_probe+0x29/0xa0 [i915]
<4> [353.902928] CPU: 2 PID: 3280 Comm: i915_module_loa Tainted: G     UD W         4.20.0-rc3-CI-CI_DRM_5198+ #1
<4> [353.903592]  i915_driver_load+0x845/0x1550 [i915]
<4> [353.903693]  i915_pci_probe+0x29/0xa0 [i915]
<3> [354.921775] in_atomic(): 0, irqs_disabled(): 0, pid: 3280, name: i915_module_loa
<4> [354.921821] CPU: 3 PID: 3280 Comm: i915_module_loa Tainted: G     UD W         4.20.0-rc3-CI-CI_DRM_5198+ #1
<4> [354.922309]  i915_driver_load+0x845/0x1550 [i915]
<4> [354.922414]  i915_pci_probe+0x29/0xa0 [i915]
Comment 21 Lakshmi 2018-11-25 13:49:29 UTC
Setting the priority to Highest as it causes BAT test failure. From the history it can be seen that this issue occurs in either shards and/or BAT tests.
Comment 22 Francesco Balestrieri 2018-12-04 07:18:15 UTC
Stan, did you figure out anything from the latest logs?
Comment 23 Stanislav Lisovskiy 2018-12-04 07:55:15 UTC
(In reply to Francesco Balestrieri from comment #22)
> Stan, did you figure out anything from the latest logs?

There is a NULL pointer deref in  do_remove_conflicting_framebuffers function:

<4>[  353.865901] general protection fault: 0000 [#1] PREEMPT SMP PTI
<4>[  353.865920] CPU: 2 PID: 3280 Comm: i915_module_loa Tainted: G     U            4.20.0-rc3-CI-CI_DRM_5198+ #1
<4>[  353.865938] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4205-ITX, BIOS P1.10 09/29/2016
<4>[  353.865962] RIP: 0010:do_remove_conflicting_framebuffers+0x55/0x180
<4>[  353.865975] Code: ee 41 89 ef 48 85 c0 74 53 f6 40 0a 08 74 4d 4d 85 ed 4c 8b a0 78 04 00 00 74 20 4d 85 e4 74 1b 41 8b 4d 00 31 db 85 c9 74 11 <41> 8b 14 24 85 d2 75 45 83 c3 01 41 39 5d 00 77 ef 4d 85 e4 74 1c
<4>[  353.866006] RSP: 0018:ffffc900002bfa58 EFLAGS: 00010202
<4>[  353.866017] RAX: ffff888275e7e678 RBX: 0000000000000000 RCX: 0000000000000001
<4>[  353.866031] RDX: 0000000000000001 RSI: ffffffffa05a2dc2 RDI: ffff88825c0e6178
<4>[  353.866045] RBP: 0000000000000000 R08: 00000000cfaa903d R09: 0000000000000001
<4>[  353.866058] R10: ffffc900002bfac0 R11: ffffffff820e2810 R12: 6b6b6b6b6b6b6b6b
<4>[  353.866071] R13: ffff88825c0e6178 R14: ffffffff82339400 R15: 0000000000000000
<4>[  353.866086] FS:  00007f71e4e18980(0000) GS:ffff888277f00000(0000) knlGS:0000000000000000
<4>[  353.866102] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[  353.866113] CR2: 000055cd8d020a90 CR3: 0000000269ca8000 CR4: 00000000003406e0
<4>[  353.866127] Call Trace:
<4>[  353.866141]  remove_conflicting_framebuffers+0x2d/0xc0
<4>[  353.866244]  i915_driver_load+0x845/0x1550 [i915]
<4>[  353.866262]  ? _raw_spin_unlock_irqrestore+0x4c/0x60
<4>[  353.866280]  ? lockdep_hardirqs_on+0xe0/0x1b0
<4>[  353.866356]  i915_pci_probe+0x29/0xa0 [i915]
<4>[  353.866369]  pci_device_probe+0xa1/0x130
<4>[  353.866383]  really_probe+0xf3/0x3e0
<4>[  353.866394]  driver_probe_device+0x10a/0x120
<4>[  353.866406]  __driver_attach+0xdb/0x100
<4>[  353.866416]  ? driver_probe_device+0x120/0x120
<4>[  353.866427]  ? driver_probe_device+0x120/0x120
<4>[  353.866438]  bus_for_each_dev+0x74/0xc0
<4>[  353.866449]  bus_add_driver+0x15f/0x250
<4>[  353.866460]  ? 0xffffffffa0730000
<4>[  353.866470]  driver_register+0x56/0xe0
<4>[  353.866479]  ? 0xffffffffa0730000
<4>[  353.866489]  do_one_initcall+0x58/0x2e0
<4>[  353.866501]  ? do_init_module+0x1d/0x1ea
<4>[  353.866512]  ? rcu_read_lock_sched_held+0x6f/0x80
<4>[  353.866525]  ? kmem_cache_alloc_trace+0x264/0x290
<4>[  353.866538]  do_init_module+0x56/0x1ea
<4>[  353.866549]  load_module+0x2714/0x29f0
<4>[  353.866570]  ? __se_sys_finit_module+0xd3/0xf0
<4>[  353.866581]  __se_sys_finit_module+0xd3/0xf0
<4>[  353.866597]  do_syscall_64+0x55/0x190
<4>[  353.866609]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4>[  353.866621] RIP: 0033:0x7f71e44c1839
<4>[  353.866631] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 1f f6 2c 00 f7 d8 64 89 01 48
<4>[  353.866662] RSP: 002b:00007fff86e10c38 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
<4>[  353.866678] RAX: ffffffffffffffda RBX: 0000563533cef0b0 RCX: 00007f71e44c1839
<4>[  353.866691] RDX: 0000000000000000 RSI: 0000563533ce91f0 RDI: 0000000000000005
<4>[  353.866705] RBP: 0000563533ce91f0 R08: 0000000000000000 R09: 0000000000000000
<4>[  353.866718] R10: 0000000000000005 R11: 0000000000000246 R12: 0000000000000000
<4>[  353.866732] R13: 0000563533cece30 R14: 0000000000000020 R15: 0000000000000016
<4>[  353.866751] Modules linked in: i915(+) vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel i2c_i801 lpc_ich r8169 snd_hda_codec snd_hwdep snd_hda_core mei_me snd_pcm pinctrl_broxton mei pinctrl_intel prime_numbers [last unloaded: i915]
Comment 24 Stanislav Lisovskiy 2018-12-04 08:29:07 UTC
I'm going to test a patch today, looks like some of the fb apertures are 0. For which reason I can't say, however, I guess it is still worth checking if its zero so that we at least don't crash in that case.
Comment 25 Chris Wilson 2018-12-04 13:12:38 UTC
(In reply to Stanislav Lisovskiy from comment #23)
> (In reply to Francesco Balestrieri from comment #22)
> > Stan, did you figure out anything from the latest logs?
> 
> There is a NULL pointer deref in  do_remove_conflicting_framebuffers
> function:

That's a known-use-after-free. You can't guarantee that you even see a NULL pointer as its value depends on what else gets written by a third party.
Comment 26 Stanislav Lisovskiy 2018-12-04 14:25:17 UTC
(In reply to Chris Wilson from comment #25)
> (In reply to Stanislav Lisovskiy from comment #23)
> > (In reply to Francesco Balestrieri from comment #22)
> > > Stan, did you figure out anything from the latest logs?
> > 
> > There is a NULL pointer deref in  do_remove_conflicting_framebuffers
> > function:
> 
> That's a known-use-after-free. You can't guarantee that you even see a NULL
> pointer as its value depends on what else gets written by a third party.

Ok, is there any patch available elsewhere?
Comment 27 Chris Wilson 2018-12-04 20:19:07 UTC
(In reply to Stanislav Lisovskiy from comment #26)
> (In reply to Chris Wilson from comment #25)
> > (In reply to Stanislav Lisovskiy from comment #23)
> > > (In reply to Francesco Balestrieri from comment #22)
> > > > Stan, did you figure out anything from the latest logs?
> > > 
> > > There is a NULL pointer deref in  do_remove_conflicting_framebuffers
> > > function:
> > 
> > That's a known-use-after-free. You can't guarantee that you even see a NULL
> > pointer as its value depends on what else gets written by a third party.
> 
> Ok, is there any patch available elsewhere?

Nope, we are hoping for a kasan hit to tell us where the use-after-free emanated from.
Comment 28 Stanislav Lisovskiy 2018-12-05 07:23:14 UTC
(In reply to Chris Wilson from comment #27)
> (In reply to Stanislav Lisovskiy from comment #26)
> > (In reply to Chris Wilson from comment #25)
> > > (In reply to Stanislav Lisovskiy from comment #23)
> > > > (In reply to Francesco Balestrieri from comment #22)
> > > > > Stan, did you figure out anything from the latest logs?
> > > > 
> > > > There is a NULL pointer deref in  do_remove_conflicting_framebuffers
> > > > function:
> > > 
> > > That's a known-use-after-free. You can't guarantee that you even see a NULL
> > > pointer as its value depends on what else gets written by a third party.
> > 
> > Ok, is there any patch available elsewhere?
> 
> Nope, we are hoping for a kasan hit to tell us where the use-after-free
> emanated from.

We could try also poisoning registered_fb[i] somehow to mark and determine when it was freed.
Comment 29 Chris Wilson 2018-12-05 09:35:58 UTC
This bug has too many completely unrelated issues caught up in it.
Comment 30 Stanislav Lisovskiy 2018-12-05 09:44:57 UTC
(In reply to Chris Wilson from comment #29)
> This bug has too many completely unrelated issues caught up in it.

Agree. With such kind of filtering it's not going to be closed ever + it is very hard to track completely different issues in it.
Comment 31 Martin Peres 2019-03-08 15:52:15 UTC
(In reply to Stanislav Lisovskiy from comment #30)
> (In reply to Chris Wilson from comment #29)
> > This bug has too many completely unrelated issues caught up in it.
> 
> Agree. With such kind of filtering it's not going to be closed ever + it is
> very hard to track completely different issues in it.

I will start splitting the giant incomplete bugs into sub-bugs, when it seems tests are easily reproducing the issue.
Comment 32 CI Bug Log 2019-09-29 19:42:18 UTC
A CI Bug Log filter associated to this bug has been updated:

{- fi-bxt-j4205: igt@runner@aborted - fail - Previous test: i915_module_load \(reload-with-fault-injection\) -}
{+ fi-bxt-j4205: igt@runner@aborted - fail - Previous test: (i915_module_load \(reload-with-fault-injection\)|i915_selftest (mock_timelines)) +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6968/shard-apl4/igt@runner@aborted.html
  * https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6969/shard-apl5/igt@runner@aborted.html
  * https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6970/shard-apl6/igt@runner@aborted.html
  * https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6971/shard-apl7/igt@runner@aborted.html

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.