Bug 111992 - [CI][BAT]igt@i915_selftest@live_execlists - incomplete - igt_live_test_end+0x10/0xb0 [i915] timed out, cancelling all further testing
Summary: [CI][BAT]igt@i915_selftest@live_execlists - incomplete - igt_live_test_end+0x...
Status: RESOLVED WORKSFORME
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: not set not set
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-10-14 09:03 UTC by Lakshmi
Modified: 2019-11-11 10:42 UTC (History)
1 user (show)

See Also:
i915 platform: KBL
i915 features: GEM/execlists


Attachments

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