Bug 111992

Summary: [CI][BAT]igt@i915_selftest@live_execlists - incomplete - igt_live_test_end+0x10/0xb0 [i915] timed out, cancelling all further testing
Product: DRI Reporter: Lakshmi <lakshminarayana.vudum>
Component: DRM/IntelAssignee: Intel GFX Bugs mailing list <intel-gfx-bugs>
Status: RESOLVED WORKSFORME QA Contact: Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity: not set    
Priority: not set CC: intel-gfx-bugs
Version: DRI git   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: KBL i915 features: GEM/execlists

Description Lakshmi 2019-10-14 09:03:16 UTC 
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_7071/fi-kbl-r/igt@i915_selftest@live_execlists.html
<0> [629.597046] i915_sel-5293    5.... 614747290us : __i915_subtests: Running intel_execlists_live_selftests/live_unlite_preempt
<0> [629.597112] i915_sel-5293    5.... 614747589us : __intel_context_do_pin: rcs0 context:1c15e pin ring:{head:0000, tail:0000}
<0> [629.597173] i915_sel-5293    5.... 614747793us : __intel_context_do_pin: rcs0 context:1c15f pin ring:{head:0000, tail:0000}
<0> [629.597235] i915_sel-5293    5.... 614747845us : __engine_unpark: rcs0
<0> [629.597297] i915_sel-5293    5.... 614747849us : __gt_unpark: 
<0> [629.597379] i915_sel-5293    5.... 614748426us : __i915_request_commit: rcs0 fence 1c15e:2
<0> [629.597458] i915_sel-5293    5d..1 614748432us : __i915_request_submit: rcs0 fence 1c15e:2, current 0
<0> [629.597527] i915_sel-5293    5d..1 614748434us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:yes
<0> [629.597593] i915_sel-5293    5d..1 614748435us : trace_ports: rcs0: submit { 1c15e:2, 0:0 }
<0> [629.597656]   <idle>-0       3..s2 614748542us : process_csb: rcs0 cs-irq head=2, tail=3
<0> [629.597721]   <idle>-0       3..s2 614748543us : process_csb: rcs0 csb[3]: status=0x00000001:0x00000000
<0> [629.597782]   <idle>-0       3..s2 614748544us : trace_ports: rcs0: promote { 1c15e:2*, 0:0 }
<0> [629.597842]   <idle>-0       3d.s3 614748546us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:no
<0> [629.597922] i915_sel-5293    5.... 614748619us : __i915_request_commit: rcs0 fence 1c15f:2
<0> [629.598000] i915_sel-5293    5d..1 614748630us : __i915_request_submit: rcs0 fence 1c15f:2, current 0
<0> [629.598066] i915_sel-5293    5d..1 614748632us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:yes
<0> [629.598131] i915_sel-5293    5d..1 614748633us : trace_ports: rcs0: submit { 1c15e:2*, 1c15f:2 }
<0> [629.598194] ksoftirq-36      5..s. 614748744us : process_csb: rcs0 cs-irq head=3, tail=4
<0> [629.598256] ksoftirq-36      5..s. 614748744us : process_csb: rcs0 csb[4]: status=0x00008002:0x00000040
<0> [629.598316] ksoftirq-36      5..s. 614748746us : trace_ports: rcs0: preempted { 1c15e:2*, 0:0 }
<0> [629.598377] ksoftirq-36      5..s. 614748747us : trace_ports: rcs0: promote { 1c15e:2*, 1c15f:2 }
<0> [629.598437] ksoftirq-36      5d.s1 614748751us : __execlists_submission_tasklet: rcs0: preempting last=1c15e:2, prio=3, hint=4096
<0> [629.598517] ksoftirq-36      5d.s1 614748752us : __i915_request_unsubmit: rcs0 fence 1c15f:2, current 0
<0> [629.598594] ksoftirq-36      5d.s1 614748782us : __i915_request_unsubmit: rcs0 fence 1c15e:2, current 1
<0> [629.598671] ksoftirq-36      5d.s1 614748784us : __i915_request_submit: rcs0 fence 1c15f:2, current 0
<0> [629.598749] ksoftirq-36      5d.s1 614748791us : __i915_request_submit: rcs0 fence 1c15e:2, current 1
<0> [629.598818] ksoftirq-36      5d.s1 614748792us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:yes
<0> [629.598884] ksoftirq-36      5d.s1 614748793us : trace_ports: rcs0: submit { 1c15f:2, 1c15e:2 }
<0> [629.598948] ksoftirq-36      5..s. 614748899us : process_csb: rcs0 cs-irq head=4, tail=5
<0> [629.599012] ksoftirq-36      5..s. 614748900us : process_csb: rcs0 csb[5]: status=0x00000802:0x00000040
<0> [629.599073] ksoftirq-36      5..s. 614748900us : trace_ports: rcs0: preempted { 1c15e:2*, 1c15f:2 }
<0> [629.599134] ksoftirq-36      5..s. 614748901us : trace_ports: rcs0: promote { 1c15f:2!, 1c15e:2 }
<0> [629.599194] ksoftirq-36      5d.s1 614748903us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:no
<0> [629.599274] i915_sel-5293    5.... 614748911us : __i915_request_commit: rcs0 fence 1c15e:4
<0> [629.599352] i915_sel-5293    5d..1 614748920us : __i915_request_submit: rcs0 fence 1c15e:4, current 1
<0> [629.599418] i915_sel-5293    5d..1 614748921us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:yes
<0> [629.599482] i915_sel-5293    5d..1 614748922us : trace_ports: rcs0: submit { 1c15e:4, 0:0 }
<0> [629.599561] i915_sel-5293    5.... 614748929us : i915_request_retire: rcs0 fence 1c15f:2, current 2
<0> [629.599626] i915_sel-5293    5.... 614748930us : intel_context_unpin: rcs0 context:1c15f retire
<0> [629.599688] i915_sel-5293    5.... 614748933us : __intel_context_retire: rcs0 context:1c15f retire
<0> [629.599758]   <idle>-0       3..s1 614749329us : process_csb: rcs0 cs-irq head=5, tail=2
<0> [629.599822]   <idle>-0       3..s1 614749330us : process_csb: rcs0 csb[0]: status=0x00000814:0x00000060
<0> [629.599884]   <idle>-0       3..s1 614749330us : trace_ports: rcs0: completed { 1c15f:2!, 1c15e:2 }
<0> [629.599964] i915_sel-5293    5.... 614749337us : i915_request_retire: rcs0 fence 1c15e:2, current 4
<0> [629.600042] i915_sel-5293    5.... 614749357us : i915_request_retire: rcs0 fence 1c15e:4, current 4
<0> [629.600109]   <idle>-0       3..s1 614749365us : process_csb: rcs0 csb[1]: status=0x00008002:0x00000040
<0> [629.600173]   <idle>-0       3..s1 614749365us : trace_ports: rcs0: preempted { 1c15e:2!, 0:0 }
<0> [629.600236]   <idle>-0       3..s1 614749366us : trace_ports: rcs0: promote { 1c15e:4!, 0:0 }
<0> [629.600303]   <idle>-0       3..s1 614749366us : process_csb: rcs0 csb[2]: status=0x00000818:0x00000040
<0> [629.600364]   <idle>-0       3..s1 614749366us : trace_ports: rcs0: completed { 1c15e:4!, 0:0 }
<0> [629.600424]   <idle>-0       3d.s2 614749367us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:no
<0> [629.600505] i915_sel-5293    5d... 614749372us : __i915_request_commit: rcs0 fence 1c146:12
<0> [629.600584] i915_sel-5293    5d..1 614749390us : __i915_request_submit: rcs0 fence 1c146:12, current 10
<0> [629.600651] i915_sel-5293    5d..1 614749400us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:yes
<0> [629.600719] i915_sel-5293    5d..1 614749403us : trace_ports: rcs0: submit { 1c146:12, 0:0 }
<0> [629.600783] i915_sel-5293    5.... 614749408us : intel_context_unpin: rcs0 context:1c15e retire
<0> [629.600844] i915_sel-5293    5.... 614749411us : __intel_context_retire: rcs0 context:1c15e retire
<0> [629.600923] i915_sel-5293    5.... 614749457us : i915_request_retire: rcs0 fence 1c146:12, current 12
<0> [629.600988] i915_sel-5293    5.... 614749459us : __engine_park: rcs0
<0> [629.601055]   <idle>-0       3..s1 614749459us : process_csb: rcs0 cs-irq head=2, tail=4
<0> [629.601119]   <idle>-0       3..s1 614749460us : process_csb: rcs0 csb[3]: status=0x00000001:0x00000000
<0> [629.601183]   <idle>-0       3..s1 614749461us : trace_ports: rcs0: promote { 1c146:12!, 0:0 }
<0> [629.601245]   <idle>-0       3..s1 614749461us : process_csb: rcs0 csb[4]: status=0x00000818:0x00000000
<0> [629.601305]   <idle>-0       3..s1 614749462us : trace_ports: rcs0: completed { 1c146:12!, 0:0 }
<0> [629.601366]   <idle>-0       3d.s2 614749463us : __execlists_submission_tasklet: rcs0: queue_priority_hint:-2147483648, submit:no
<0> [629.601427] kworker/-199     5.... 614749532us : __gt_park: 
<0> [629.601488] i915_sel-5293    5.... 614750422us : __intel_context_do_pin: bcs0 context:1c160 pin ring:{head:0000, tail:0000}
<0> [629.601549] i915_sel-5293    5.... 614750620us : __intel_context_do_pin: bcs0 context:1c161 pin ring:{head:0000, tail:0000}
<0> [629.601609] i915_sel-5293    5.... 614750628us : __engine_unpark: bcs0
<0> [629.601669] i915_sel-5293    5.... 614750631us : __gt_unpark: 
<0> [629.601753] i915_sel-5293    5.... 614751190us : __i915_request_commit: bcs0 fence 1c160:2
<0> [629.601834] i915_sel-5293    5d..1 614751197us : __i915_request_submit: bcs0 fence 1c160:2, current 0
<0> [629.601904] i915_sel-5293    5d..1 614751198us : __execlists_submission_tasklet: bcs0: queue_priority_hint:-2147483648, submit:yes
<0> [629.601969] i915_sel-5293    5d..1 614751199us : trace_ports: bcs0: submit { 1c160:2, 0:0 }
<0> [629.602049] i915_sel-5293    5.... 614751214us : __i915_request_commit: bcs0 fence 1c161:2
<0> [629.602116]   <idle>-0       3..s1 614751240us : process_csb: bcs0 cs-irq head=5, tail=0
<0> [629.602180]   <idle>-0       3..s1 614751240us : process_csb: bcs0 csb[0]: status=0x00000001:0x00000000
<0> [629.602244]   <idle>-0       3..s1 614751242us : trace_ports: bcs0: promote { 1c160:2*, 0:0 }
<0> [629.602305]   <idle>-0       3d.s2 614751244us : __execlists_submission_tasklet: bcs0: preempting last=1c160:2, prio=3, hint=4097
<0> [629.602383]   <idle>-0       3d.s2 614751245us : __i915_request_unsubmit: bcs0 fence 1c160:2, current 1
<0> [629.602462] i915_sel-5293    5.... 614751245us : __i915_request_commit: bcs0 fence 1c160:4
<0> [629.602539]   <idle>-0       3d.s2 614751246us : __i915_request_submit: bcs0 fence 1c161:2, current 0
<0> [629.602615]   <idle>-0       3d.s2 614751256us : __i915_request_submit: bcs0 fence 1c160:2, current 1
<0> [629.602684]   <idle>-0       3d.s2 614751258us : __execlists_submission_tasklet: bcs0: queue_priority_hint:-2147483648, submit:yes
<0> [629.602757]   <idle>-0       3d.s2 614751259us : trace_ports: bcs0: submit { 1c161:2, 1c160:2 }
<0> [629.602835] i915_sel-5293    5.... 614751275us : i915_request_retire: bcs0 fence 1c161:2, current 2
<0> [629.602902] i915_sel-5293    5.... 614751276us : intel_context_unpin: bcs0 context:1c161 retire
<0> [629.602965] i915_sel-5293    5.... 614751278us : __intel_context_retire: bcs0 context:1c161 retire
<0> [629.603126] i915_sel-5293    5.... 614953500us : igt_flush_test: igt_live_test_end+0x10/0xb0 [i915] timed out.

This is simlar to bug 111895 but on KBL.
Comment 1 CI Bug Log 2019-10-14 09:05:50 UTC 
The CI Bug Log issue associated to this bug has been updated.

### New filters associated

* KBL: igt@i915_selftest@live_execlists - incomplete - igt_live_test_end+0x10/0xb0 [i915] timed out, cancelling all further testing
  - https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_7071/fi-kbl-r/igt@i915_selftest@live_execlists.html
Comment 2 Chris Wilson 2019-10-14 09:10:46 UTC 
Not quite the same, the biggest difference with the remaining fails are that are all in live_preempt_unlite. Sadly that debug log didn't include the bcs0 state dump to go with the trace, would have been useful.
Comment 3 Chris Wilson 2019-10-14 09:12:24 UTC 
The curse of another incomplete dmesg.
Comment 4 Chris Wilson 2019-10-14 09:13:02 UTC 
(In reply to Chris Wilson from comment #3)
> The curse of another incomplete dmesg.

Wrong bug...
Comment 5 CI Bug Log 2019-10-16 13:16:27 UTC 
A CI Bug Log filter associated to this bug has been updated:

{- KBL: igt@i915_selftest@live_execlists - incomplete - igt_live_test_end+0x10/0xb0 [i915] timed out, cancelling all further testing -}
{+ KBL WHL: igt@i915_selftest@live_execlists - incomplete - [i915] timed out, cancelling all further testing +}


  No new failures caught with the new filter
Comment 6 Francesco Balestrieri 2019-11-11 10:42:15 UTC 
Seen once one month ago.

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.