Bug 103927 - [CI][BXT only] igt@* - incomplete timeout/system hang
Summary: [CI][BXT only] igt@* - incomplete timeout/system hang
Status: CLOSED INVALID
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: highest normal
Assignee: Stanislav Lisovskiy
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks: 105984
  Show dependency treegraph
 
Reported: 2017-11-27 08:20 UTC by Marta Löfstedt
Modified: 2018-12-28 09:37 UTC (History)
1 user (show)

See Also:
i915 platform: BXT
i915 features: power/suspend-resume


Attachments

Note You need to log in before you can comment on or make changes to this bug.
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.


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.