igt@gem_exec_schedule@in-order@vcs0 on shard-mtlp@CI_DRM

Detail	Value
Duration	0.09 seconds
Hostname	shard-mtlp-5
Igt-Version	IGT-Version: 2.1-gc4a9bee16 (x86_64) (Linux: 6.16.0-CI_DRM_16965-ge75fad13646b+ x86_64)
Out	Starting dynamic subtest: vcs0 Dynamic subtest vcs0: SUCCESS (0.091s)
Err	Starting dynamic subtest: vcs0 Dynamic subtest vcs0: SUCCESS (0.091s)
Dmesg Scroll to first warning	<6> [531.666344] [IGT] gem_exec_schedule: starting dynamic subtest vcs0 <7> [531.666947] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <7> [531.678479] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <3> [531.678596] guc_lrc_desc_unpin:3418 GEM_BUG_ON(!ctx_id_mapped(guc, ce->guc_id.id)) <0> [531.678616] Dumping ftrace buffer: <0> [531.678625] --------------------------------- <0> [531.679617] kworker/-12 20..... 48608188us : __i915_request_commit: 0000:00:02.0 other0: fence 10:17, current 16 <4> [531.679863] kauditd_printk_skb: 113 callbacks suppressed <5> [531.679865] audit: type=1400 audit(1754566429.927:125): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <0> [531.680132] kworker/-12 20D..1. 48608209us : __i915_request_submit: 0000:00:02.0 other0: fence 10:17, current 16 <5> [531.680404] audit: type=1400 audit(1754566429.927:126): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <0> [531.680425] kworker/-12 20..... 48619005us : __engine_unpark: 0000:00:02.0 other0: <5> [531.680684] audit: type=1400 audit(1754566429.928:127): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <5> [531.680697] audit: type=1400 audit(1754566429.928:128): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <0> [531.680699] kworker/-12 20..... 48619035us : __gt_unpark: 0000:00:02.0 <5> [531.680732] audit: type=1400 audit(1754566429.928:129): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <0> [531.680962] kworker/-12 20..... 48619157us : __engine_unpark: 0000:00:02.0 other0: context:f reset { seqno:1, hwsp:1, ring:58 } <0> [531.681288] kworker/-12 20..... 48619211us : __i915_request_commit: 0000:00:02.0 other0: fence 10:18, current 17 <7> [531.681333] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.681637] kworker/-12 20D..1. 48619230us : __i915_request_submit: 0000:00:02.0 other0: fence 10:18, current 17 <0> [531.681930] kworker/-12 20..... 48629856us : __engine_unpark: 0000:00:02.0 other0: <5> [531.681945] audit: type=1400 audit(1754566429.929:130): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <5> [531.681995] audit: type=1400 audit(1754566429.929:131): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <5> [531.682002] audit: type=1400 audit(1754566429.929:132): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <0> [531.682203] kworker/-12 20..... 48629884us : __gt_unpark: 0000:00:02.0 <0> [531.682466] kworker/-12 20..... 48629992us : __engine_unpark: 0000:00:02.0 other0: context:f reset { seqno:1, hwsp:1, ring:58 } <5> [531.682629] audit: type=1400 audit(1754566429.930:133): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <5> [531.682660] audit: type=1400 audit(1754566429.930:134): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0 <0> [531.682767] kworker/-12 20..... 48630040us : __i915_request_commit: 0000:00:02.0 other0: fence 10:19, current 18 <0> [531.682937] kworker/-12 20D..1. 48630058us : __i915_request_submit: 0000:00:02.0 other0: fence 10:19, current 18 <0> [531.683092] kworker/-12 20..... 48640667us : __engine_unpark: 0000:00:02.0 other0: <0> [531.683243] kworker/-12 20..... 48640693us : __gt_unpark: 0000:00:02.0 <0> [531.683391] kworker/-12 20..... 48640789us : __engine_unpark: 0000:00:02.0 other0: context:f reset { seqno:1, hwsp:1, ring:58 } <7> [531.683424] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.683563] kworker/-12 20..... 48640829us : __i915_request_commit: 0000:00:02.0 other0: fence 10:20, current 19 <0> [531.683711] kworker/-12 20D..1. 48640845us : __i915_request_submit: 0000:00:02.0 other0: fence 10:20, current 19 <0> [531.683866] kworker/-12 20..... 48651448us : __engine_unpark: 0000:00:02.0 other0: <0> [531.684015] kworker/-12 20..... 48651474us : __gt_unpark: 0000:00:02.0 <0> [531.684159] kworker/-12 20..... 48651587us : __engine_unpark: 0000:00:02.0 other0: context:f reset { seqno:1, hwsp:1, ring:58 } <0> [531.684331] kworker/-12 20.N... 48651624us : __i915_request_commit: 0000:00:02.0 other0: fence 10:21, current 20 <0> [531.684498] kworker/-12 20DN.1. 48651640us : __i915_request_submit: 0000:00:02.0 other0: fence 10:21, current 20 <0> [531.684666] kworker/-176 21..... 50744611us : i915_request_retire.part.0: 0000:00:02.0 vcs0: fence 1a:2, current 2 <0> [531.684834] kworker/-176 21..... 50745164us : i915_request_retire.part.0: 0000:00:02.0 vcs1: fence 1b:2, current 2 <0> [531.685002] kworker/-176 21..... 50745214us : i915_request_retire.part.0: 0000:00:02.0 vecs0: fence 1c:2, current 2 <0> [531.685169] kworker/-176 21..... 50745259us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 17:2, current 2 <0> [531.685335] kworker/-176 21..... 50746955us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 5:2, current 2 <7> [531.685336] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.685503] kworker/-176 21..... 50749060us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 18:2, current 2 <0> [531.685668] kworker/-176 21..... 50749270us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 19:2, current 2 <0> [531.685833] kworker/-176 21..... 81785890us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 31:2, current 2 <0> [531.685999] kworker/-176 21..... 81786756us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 5:5, current 5 <0> [531.686166] kworker/-176 21..... 81786774us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 6:6, current 7 <0> [531.686331] kworker/-176 21..... 81786779us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 6:7, current 7 <0> [531.686488] kworker/-176 21..... 81786790us : __engine_park: 0000:00:02.0 bcs0: parked <0> [531.686650] kworker/-111 21..... 85753923us : __i915_request_commit: 0000:00:02.0 rcs0: fence 5:7, current 6 <0> [531.686816] kworker/-111 21D..1. 85753973us : __i915_request_submit: 0000:00:02.0 rcs0: fence 5:7, current 6 <0> [531.686982] kworker/-176 21..... 87670985us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 4c:4, current 4 <0> [531.687149] kworker/-177 20..... 90742731us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 4f:2, current 2 <0> [531.687316] kworker/-177 20..... 90743168us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 5:8, current 8 <7> [531.687306] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.687488] kworker/-177 20..... 90743208us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 6:8, current 9 <0> [531.687653] kworker/-177 20..... 90743215us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 6:9, current 9 <0> [531.687807] kworker/-177 20..... 90743244us : __engine_park: 0000:00:02.0 bcs0: parked <0> [531.687966] kworker/-176 21..... 187762834us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 1c3:2, current 2 <0> [531.688129] kworker/-176 21..... 187763507us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 5:21, current 21 <0> [531.688293] kworker/-111 21..... 202227595us : __i915_request_commit: 0000:00:02.0 rcs0: fence 5:22, current 21 <0> [531.688456] kworker/-111 21D..1. 202227623us : __i915_request_submit: 0000:00:02.0 rcs0: fence 5:22, current 21 <0> [531.688619] kworker/-111 21..... 227825927us : __i915_request_commit: 0000:00:02.0 rcs0: fence 5:23, current 22 <0> [531.688783] kworker/-111 21D..1. 227825949us : __i915_request_submit: 0000:00:02.0 rcs0: fence 5:23, current 22 <0> [531.688927] kworker/-448 20..... 253797877us : intel_rps_mark_interactive: 0000:00:02.0 mark interactive: no <0> [531.689047] gem_exec-2386 20..... 292757238us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:11712, current 11696 <0> [531.689168] gem_exec-2386 20DN.1. 292757307us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:11712, current 11696 <0> [531.689292] gem_exec-2370 20..... 293242666us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:14084, current 14084 <7> [531.689225] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.689421] gem_exec-2394 20..... 293727162us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:16770, current 16760 <0> [531.689559] gem_exec-2394 20..... 293729044us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:16780, current 16770 <0> [531.689678] gem_exec-2384 20..... 293793075us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:94b pin ring:{start:f10c5000, head:0000, tail:0000} <0> [531.689819] gem_exec-2384 20..... 293793308us : __i915_request_commit: 0000:00:02.0 vecs0: fence 94b:2, current 0 <0> [531.689950] gem_exec-2384 20D..1. 293793328us : __i915_request_submit: 0000:00:02.0 vecs0: fence 94b:2, current 0 <0> [531.690074] gem_exec-2381 20..... 294192974us : __i915_request_commit: 0000:00:02.0 bcs0: fence 9cd:2, current 0 <0> [531.690201] gem_exec-2381 20D..1. 294193026us : __i915_request_submit: 0000:00:02.0 bcs0: fence 9cd:2, current 0 <0> [531.690322] gem_exec-2381 20..... 294193648us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19516, current 19504 <0> [531.690443] gem_exec-2381 20..... 294193973us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19518, current 19504 <0> [531.690564] gem_exec-2381 20..... 294196890us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19540, current 19530 <0> [531.690684] gem_exec-2381 20D..1. 294196917us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:19540, current 19530 <0> [531.690804] gem_exec-2376 20..... 294213989us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:19702, current 19702 <0> [531.690925] gem_exec-2376 20..... 294214354us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19718, current 19702 <0> [531.691046] gem_exec-2376 20D..1. 294214419us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:19718, current 19702 <0> [531.691166] gem_exec-2376 20..... 294215513us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19726, current 19720 <0> [531.691286] gem_exec-2376 20D..1. 294215535us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:19726, current 19720 <7> [531.691226] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.691408] gem_exec-2387 20.N... 295030492us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:25188, current 25188 <0> [531.691530] gem_exec-2405 20..... 295036117us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:b08 active <0> [531.691653] gem_exec-2392 20..... 295864074us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:33072, current 33048 <0> [531.691779] gem_exec-2392 20..... 295864096us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33048, current 33048 <0> [531.691905] gem_exec-2392 20..... 295864779us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33052, current 33055 <0> [531.692026] gem_exec-2392 20..... 295864841us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:33084, current 33058 <0> [531.692147] gem_exec-2392 20..... 295864858us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33054, current 33059 <0> [531.692267] gem_exec-2392 20..... 295864883us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33056, current 33060 <0> [531.692389] gem_exec-2392 20..... 295864902us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33058, current 33061 <0> [531.692510] gem_exec-2392 20..... 295864923us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33060, current 33062 <0> [531.692631] gem_exec-2392 20..... 295864942us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33062, current 33062 <0> [531.692755] gem_exec-2392 20..... 295867274us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33100, current 33100 <0> [531.692891] gem_exec-2392 20..... 295867401us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:33120, current 33102 <0> [531.693020] gem_exec-2392 20..... 295867429us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33102, current 33102 <0> [531.693145] gem_exec-2365 20..... 296107653us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:36710, current 36686 <0> [531.693271] gem_exec-2365 20..... 296107679us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36686, current 36688 <0> [531.693407] gem_exec-2365 20..... 296107696us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36688, current 36689 <7> [531.693452] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.693535] gem_exec-2365 20..... 296107709us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36690, current 36690 <0> [531.693647] gem_exec-2365 20..... 296108075us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36692, current 36702 <0> [531.693785] gem_exec-2365 20..... 296108099us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36694, current 36702 <0> [531.693923] gem_exec-2365 20..... 296108117us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36696, current 36702 <0> [531.694044] gem_exec-2365 20..... 296108137us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36698, current 36702 <0> [531.694165] gem_exec-2365 20..... 296108155us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36700, current 36702 <0> [531.694286] gem_exec-2365 20..... 296108174us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36702, current 36702 <0> [531.694407] gem_exec-2379 20..... 296219257us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:38510, current 38496 <0> [531.694528] gem_exec-2379 20D..1. 296219283us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:38510, current 38496 <0> [531.694649] gem_exec-2379 20..... 296219301us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:38498, current 38498 <0> [531.694764] CPU:0 [LOST 4931 EVENTS] kworker/-1076 0..... 296334980us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:514 unpin <0> [531.694882] kworker/-1076 0..... 296335050us : __intel_context_retire: 0000:00:02.0 ccs0: context:514 retire runtime: { total:387059ns, avg:65879ns } <0> [531.695007] gem_exec-2373 0..... 296335135us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40258, current 40194 <0> [531.695128] gem_exec-2373 0..... 296335209us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40264, current 40196 <0> [531.695252] gem_exec-2373 0..... 296339021us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40282, current 40272 <0> [531.695390] gem_exec-2373 0D..1. 296339026us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:40282, current 40272 <0> [531.695526] gem_exec-2373 0..... 296339033us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40272, current 40272 <0> [531.695646] gem_exec-2373 0..... 296339246us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:aaa active <7> [531.695627] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.695768] gem_exec-2373 0..... 296339251us : intel_timeline_pin: 0000:00:02.0 timeline:aaa using HWSP offset:edf34000 <0> [531.695866] gem_exec-2373 0..... 296339262us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:aaa pin ring:{start:edfa6000, head:0168, tail:0168} <0> [531.695992] gem_exec-2373 0..... 296339321us : __i915_request_commit: 0000:00:02.0 ccs0: fence aaa:4, current 2 <0> [531.696117] gem_exec-2373 0D..1. 296339574us : __i915_request_submit: 0000:00:02.0 ccs0: fence aaa:4, current 2 <0> [531.696237] gem_exec-2373 0..... 296339797us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40302, current 40274 <0> [531.696359] gem_exec-2373 0..... 296339988us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40320, current 40278 <0> [531.696481] gem_exec-2373 0..... 296343476us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40362, current 40320 <0> [531.696594] gem_exec-2373 0..... 296343540us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:372 active <0> [531.696712] gem_exec-2373 0..... 296343542us : intel_timeline_pin: 0000:00:02.0 timeline:372 using HWSP offset:fd0ea000 <0> [531.696824] gem_exec-2373 0..... 296343549us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:372 pin ring:{start:fd1d4000, head:02d0, tail:02d0} <0> [531.696949] gem_exec-2373 0..... 296343583us : __i915_request_commit: 0000:00:02.0 ccs0: fence 372:6, current 4 <0> [531.697070] gem_exec-2373 0D..1. 296343944us : __i915_request_submit: 0000:00:02.0 ccs0: fence 372:6, current 4 <0> [531.697191] gem_exec-2373 0..... 296344027us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40368, current 40320 <0> [531.697312] gem_exec-2373 0..... 296344131us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40376, current 40320 <0> [531.697433] gem_exec-2373 0..... 296347984us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40428, current 40380 <0> [531.697559] gem_exec-2373 0..... 296347989us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40380, current 40380 <7> [531.697538] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.697679] gem_exec-2373 0..... 296348050us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a1b active <0> [531.697784] gem_exec-2373 0..... 296348053us : intel_timeline_pin: 0000:00:02.0 timeline:a1b using HWSP offset:ef227000 <0> [531.697900] gem_exec-2373 0..... 296348059us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a1b pin ring:{start:ef305000, head:05a0, tail:05a0} <0> [531.698031] gem_exec-2373 0..... 296348098us : __i915_request_commit: 0000:00:02.0 ccs0: fence a1b:10, current 8 <0> [531.698155] gem_exec-2373 0D..1. 296348216us : __i915_request_submit: 0000:00:02.0 ccs0: fence a1b:10, current 8 <0> [531.698280] gem_exec-2373 0..... 296348308us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40440, current 40394 <0> [531.698404] gem_exec-2373 0..... 296348409us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40450, current 40394 <0> [531.698526] gem_exec-2381 0..... 296353491us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40496, current 40486 <0> [531.698647] gem_exec-2381 0..... 296353871us : __i915_request_commit: 0000:00:02.0 bcs0: fence bc3:6, current 4 <0> [531.698769] gem_exec-2381 0D..1. 296353877us : __i915_request_submit: 0000:00:02.0 bcs0: fence bc3:6, current 4 <0> [531.698892] gem_exec-2381 0..... 296354316us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40528, current 40488 <0> [531.699013] gem_exec-2381 0..... 296354937us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40558, current 40503 <0> [531.699133] gem_exec-2363 0..... 296356920us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40544, current 40545 <0> [531.699247] gem_exec-2401 0..... 296366347us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c79 pin ring:{start:ea305000, head:0000, tail:0000} <0> [531.699373] gem_exec-2401 0..... 296366395us : __i915_request_commit: 0000:00:02.0 vcs1: fence c79:2, current 0 <0> [531.699493] gem_exec-2401 0D..1. 296366399us : __i915_request_submit: 0000:00:02.0 vcs1: fence c79:2, current 0 <0> [531.699613] gem_exec-2401 0..... 296368728us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40732, current 40724 <7> [531.699636] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.699734] gem_exec-2401 0D..1. 296368734us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:40732, current 40724 <0> [531.699837] gem_exec-2401 0..... 296369949us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40758, current 40736 <0> [531.699958] gem_exec-2401 0D..1. 296369955us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:40758, current 40736 <0> [531.700078] gem_exec-2401 0..... 296371169us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40816, current 40760 <0> [531.700191] gem_exec-2401 0..... 296371250us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c4c active <0> [531.700307] gem_exec-2401 0..... 296371253us : intel_timeline_pin: 0000:00:02.0 timeline:c4c using HWSP offset:ea8de000 <0> [531.700420] gem_exec-2401 0..... 296371260us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c4c pin ring:{start:ea8df000, head:00b0, tail:00b0} <0> [531.700548] gem_exec-2401 0..... 296371293us : __i915_request_commit: 0000:00:02.0 vcs1: fence c4c:4, current 2 <0> [531.700671] gem_exec-2401 0D..1. 296371297us : __i915_request_submit: 0000:00:02.0 vcs1: fence c4c:4, current 2 <0> [531.700795] gem_exec-2401 0..... 296371379us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40824, current 40764 <0> [531.700918] gem_exec-2401 0..... 296371383us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40764, current 40764 <0> [531.701040] gem_exec-2401 0..... 296371436us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40828, current 40768 <0> [531.701166] gem_exec-2401 0..... 296371440us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40768, current 40768 <0> [531.701285] gem_exec-2378 0..... 296372782us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:c7b pin ring:{start:ea2d5000, head:0000, tail:0000} <0> [531.701413] gem_exec-2378 0..... 296372937us : __i915_request_commit: 0000:00:02.0 vecs0: fence c7b:2, current 0 <0> [531.701538] gem_exec-2378 0D..1. 296372942us : __i915_request_submit: 0000:00:02.0 vecs0: fence c7b:2, current 0 <0> [531.701668] gem_exec-2378 0..... 296375277us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40848, current 40804 <0> [531.701793] gem_exec-2378 0..... 296375281us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40804, current 40804 <0> [531.701916] gem_exec-2378 0..... 296375414us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40810, current 40810 <0> [531.702039] gem_exec-2378 0..... 296375459us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40858, current 40812 <0> [531.702161] gem_exec-2378 0..... 296375465us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40812, current 40812 <7> [531.702093] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.702281] gem_exec-2399 0..... 296376857us : intel_timeline_pin: 0000:00:02.0 timeline:c82 using HWSP offset:ea12e000 <0> [531.702394] gem_exec-2399 0..... 296377485us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:c82 pin ring:{start:ea217000, head:0000, tail:0000} <0> [531.702533] gem_exec-2399 0..... 296377908us : __i915_request_commit: 0000:00:02.0 bcs0: fence c82:2, current 0 <0> [531.702654] gem_exec-2399 0D..1. 296377913us : __i915_request_submit: 0000:00:02.0 bcs0: fence c82:2, current 0 <0> [531.702774] gem_exec-2399 0..... 296378083us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40910, current 40862 <0> [531.702894] gem_exec-2399 0..... 296378298us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40930, current 40862 <0> [531.703015] gem_exec-2399 0..... 296381311us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40982, current 40932 <0> [531.703129] kworker/-157 0..... 296382697us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:a1f unpin <0> [531.703241] kworker/-157 0..... 296382792us : __intel_context_retire: 0000:00:02.0 ccs0: context:a1f retire runtime: { total:892679ns, avg:129002ns } <0> [531.703355] kworker/-157 0..... 296384449us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:9cb unpin <0> [531.703467] kworker/-157 0..... 296384552us : __intel_context_retire: 0000:00:02.0 vcs0: context:9cb retire runtime: { total:107643ns, avg:42082ns } <0> [531.703583] kworker/-157 0..... 296384559us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:664 unpin <0> [531.703692] kworker/-157 0..... 296384641us : __intel_context_retire: 0000:00:02.0 vcs1: context:664 retire runtime: { total:90259ns, avg:39167ns } <0> [531.703805] gem_exec-2370 0..... 296387250us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:c90 active <0> [531.703927] gem_exec-2393 0..... 296388053us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41068, current 41034 <0> [531.704050] gem_exec-2393 0..... 296388058us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41034, current 41034 <0> [531.704161] kworker/-1076 0..... 296388548us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:7d6 unpin <7> [531.704201] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.704271] kworker/-1076 0.N... 296388638us : __intel_context_retire: 0000:00:02.0 vcs0: context:7d6 retire runtime: { total:153170ns, avg:30422ns } <0> [531.704367] kworker/-148 0..... 296390050us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:5c8 unpin <0> [531.704486] kworker/-148 0..... 296390135us : __intel_context_retire: 0000:00:02.0 rcs0: context:5c8 retire runtime: { total:601285ns, avg:101760ns } <0> [531.704603] kworker/-148 0..... 296390145us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:bc3 unpin <0> [531.704714] kworker/-148 0..... 296390230us : __intel_context_retire: 0000:00:02.0 bcs0: context:bc3 retire runtime: { total:57452ns, avg:25493ns } <0> [531.704841] gem_exec-2371 0..... 296392328us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41122, current 41116 <0> [531.704963] gem_exec-2371 0D..1. 296392333us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:41122, current 41116 <0> [531.705085] gem_exec-2394 20.N... 296394243us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41122, current 41128 <0> [531.705208] gem_exec-2394 20.N... 296394271us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41124, current 41128 <0> [531.705321] gem_exec-2371 0..... 296395330us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:b69 active <0> [531.705439] gem_exec-2371 0..... 296395335us : intel_timeline_pin: 0000:00:02.0 timeline:b69 using HWSP offset:ec641000 <0> [531.705554] gem_exec-2394 0..... 296395846us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:3a5 active <0> [531.705679] gem_exec-2394 0..... 296395851us : intel_timeline_pin: 0000:00:02.0 timeline:3a5 using HWSP offset:fca4f000 <0> [531.705793] gem_exec-2394 0..... 296395861us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:3a5 pin ring:{start:fcba0000, head:0160, tail:0160} <0> [531.705920] gem_exec-2394 0..... 296395897us : __i915_request_commit: 0000:00:02.0 vcs0: fence 3a5:6, current 4 <0> [531.706045] gem_exec-2394 0D..1. 296395901us : __i915_request_submit: 0000:00:02.0 vcs0: fence 3a5:6, current 4 <0> [531.706168] gem_exec-2394 0..... 296395962us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41184, current 41132 <0> [531.706289] gem_exec-2394 0..... 296396053us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41192, current 41132 <0> [531.706413] gem_exec-2394 0..... 296400059us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41244, current 41204 <0> [531.706530] gem_exec-2394 0..... 296400242us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:a4e active <7> [531.706463] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.706651] gem_exec-2394 0..... 296400244us : intel_timeline_pin: 0000:00:02.0 timeline:a4e using HWSP offset:eebea000 <0> [531.706766] gem_exec-2394 0..... 296400251us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:a4e pin ring:{start:eec7a000, head:02c0, tail:02c0} <0> [531.706894] gem_exec-2394 0..... 296400286us : __i915_request_commit: 0000:00:02.0 vcs0: fence a4e:10, current 8 <0> [531.707015] gem_exec-2394 0D..1. 296400290us : __i915_request_submit: 0000:00:02.0 vcs0: fence a4e:10, current 8 <0> [531.707136] gem_exec-2394 0..... 296400404us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41270, current 41204 <0> [531.707257] gem_exec-2394 0..... 296404809us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41206, current 41250 <0> [531.707382] gem_exec-2394 0..... 296404820us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41282, current 41250 <0> [531.707507] gem_exec-2394 0D..1. 296404824us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:41282, current 41250 <0> [531.707628] gem_exec-2394 0..... 296404829us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41208, current 41251 <0> [531.707750] gem_exec-2394 0..... 296404834us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41210, current 41251 <0> [531.707871] gem_exec-2394 0..... 296404837us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41212, current 41251 <0> [531.707992] gem_exec-2394 0..... 296404844us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41214, current 41252 <0> [531.708112] gem_exec-2394 0..... 296404848us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41216, current 41252 <0> [531.708233] gem_exec-2394 0..... 296404853us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41218, current 41252 <0> [531.708353] gem_exec-2394 0..... 296404857us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41220, current 41252 <0> [531.708475] gem_exec-2394 0..... 296404861us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41222, current 41252 <0> [531.708601] gem_exec-2394 0..... 296404862us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41224, current 41252 <7> [531.708600] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.708721] gem_exec-2394 0..... 296404864us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41226, current 41252 <0> [531.708824] gem_exec-2394 0..... 296404868us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41228, current 41253 <0> [531.708943] gem_exec-2394 0..... 296404871us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41230, current 41253 <0> [531.709063] gem_exec-2394 0..... 296404872us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41232, current 41253 <0> [531.709183] gem_exec-2394 0..... 296404873us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41234, current 41253 <0> [531.709302] gem_exec-2394 0..... 296404877us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41236, current 41253 <0> [531.709423] gem_exec-2394 0..... 296404878us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41238, current 41253 <0> [531.709544] gem_exec-2394 0..... 296404879us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41240, current 41253 <0> [531.709663] gem_exec-2394 0..... 296404883us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41242, current 41254 <0> [531.709784] gem_exec-2394 0..... 296404888us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41244, current 41254 <0> [531.709905] gem_exec-2394 0..... 296404891us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41246, current 41254 <0> [531.710025] gem_exec-2394 0..... 296404892us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41248, current 41254 <0> [531.710145] gem_exec-2394 0..... 296404893us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41250, current 41254 <0> [531.710265] gem_exec-2394 0..... 296404894us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41252, current 41254 <0> [531.710386] gem_exec-2394 0..... 296404898us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41254, current 41254 <0> [531.710514] gem_exec-2401 0..... 296406268us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41312, current 41288 <0> [531.710635] gem_exec-2401 0D..1. 296406273us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:41312, current 41289 <0> [531.710750] kworker/-157 0..... 296409807us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:3d8 unpin <0> [531.710864] kworker/-157 0..... 296409877us : __intel_context_retire: 0000:00:02.0 vcs1: context:3d8 retire runtime: { total:58459ns, avg:19663ns } <7> [531.710860] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508 <0> [531.710979] kworker/-157 0..... 296409890us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:c4c unpin <0> [531.711073] kworker/-157 0..... 296409959us : __intel_context_retire: 0000:00:02.0 vcs1: context:c4c retire runtime: { total:41340ns, avg:21677ns } <0> [531.711188] kworker/-157 0..... 296409975us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:4d3 unpin <0> [531.711298] kworker/-157 0..... 296410045us : __intel_context_retire: 0000:00:02.0 vcs1: context:4d3 retire runtime: { total:55809ns, avg:18338ns } <0> [531.711414] kworker/-157 0..... 296410946us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:7b9 unpin <0> [531.711526] kworker/-157 0..... 296411014us : __intel_context_retire: 0000:00:02.0 vcs0: context:7b9 retire runtime: { total:100170ns, avg:31217ns } <0> [531.711638] kworker/-157 0..... 296411144us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:629 unpin <0> [531.711747] kworker/-157 0..... 296411213us : __intel_context_retire: 0000:00:02.0 vecs0: context:629 retire runtime: { total:94287ns, avg:22366ns } <0> [531.711859] kworker/-157 0..... 296412520us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:3bf unpin <0> [531.711970] kworker/-157 0..... 296412585us : __intel_context_retire: 0000:00:02.0 vcs1: context:3bf retire runtime: { total:143789ns, avg:40863ns } <0> [531.712086] kworker/-157 0..... 296415447us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:c46 unpin <0> [531.712194] kworker/-157 0..... 296415709us : __intel_context_retire: 0000:00:02.0 rcs0: context:c46 retire runtime: { total:713539ns, avg:713539ns } <0> [531.712306] kworker/-157 0..... 296415734us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:8f8 unpin <0> [531.712417] kworker/-157 0..... 296415818us : __intel_context_retire: 0000:00:02.0 ccs0: context:8f8 retire runtime: { total:187196ns, avg:63759ns } <0> [531.712535] kworker/-157 0..... 296415823us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:b7b unpin <0> [531.712645] kworker/-157 0..... 296415893us : __intel_context_retire: 0000:00:02.0 ccs0: context:b7b retire runtime: { total:205163ns, avg:106371ns } <0> [531.712756] kworker/-157 0..... 296415900us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:c7d unpin <0> [531.712865] kworker/-157 0..... 296415971us : __intel_context_retire: 0000:00:02.0 ccs0: context:c7d retire runtime: { total:51357ns, avg:51357ns } <0> [531.712977] kworker/-157 0..... 296415977us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:c82 unpin <0> [531.713085] kworker/-157 0..... 296416047us : __intel_context_retire: 0000:00:02.0 bcs0: context:c82 retire runtime: { total:16483ns, avg:16483ns } <0> [531.713212] gem_exec-2374 0..... 296437853us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41850, current 41810 <0> [531.713336] gem_exec-2374 0..... 296437858us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41810, current 41810 <0> [531.713471] gem_exec-2374 0..... 296442037us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41898, current 41870 <0> [531.713593] gem_exec-2374 0..... 296442067us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41870, current 41871 <0> [531.713707] gem_exec-2374 0..... 296442173us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:2ec active <0> [531.713831] gem_exec-2374 0..... 296442177us : intel_timeline_pin: 0000:00:02.0 timeline:2ec using HWSP offset:fe274000 <0> [531.713943] gem_exec-2374 0..... 296442186us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:2ec pin ring:{start:fe42e000, head:02d0, tail:02d0} <0> [531.714070] gem_exec-2374 0..... 296442225us : __i915_request_commit: 0000:00:02.0 rcs0: fence 2ec:6, current 4 <0> [531.714193] gem_exec-2374 0D..1. 296442229us : __i915_request_submit: 0000:00:02.0 rcs0: fence 2ec:6, current 4 <0> [531.714314] gem_exec-2374 0..... 296442635us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41926, current 41884 <0> [531.714436] gem_exec-2374 0..... 296442812us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41940, current 41884 <0> [531.714552] kworker/-157 0..... 296443736us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:8a8 unpin <0> [531.714663] kworker/-157 0..... 296443873us : __intel_context_retire: 0000:00:02.0 ccs0: context:8a8 retire runtime: { total:131440ns, avg:70490ns } <0> [531.714777] kworker/-157 0..... 296443879us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:c53 unpin <0> [531.714887] kworker/-157 0..... 296444004us : __intel_context_retire: 0000:00:02.0 ccs0: context:c53 retire runtime: { total:261184ns, avg:261184ns } <0> [531.714999] kworker/-157 0..... 296444010us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:3fc unpin <0> [531.715108] kworker/-157 0..... 296444135us : __intel_context_retire: 0000:00:02.0 bcs0: context:3fc retire runtime: { total:54908ns, avg:21359ns } <0> [531.715220] kworker/-157 0..... 296444143us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:5d8 unpin <0> [531.715329] kworker/-157 0..... 296444270us : __intel_context_retire: 0000:00:02.0 rcs0: context:5d8 retire runtime: { total:466029ns, avg:82892ns } <0> [531.715450] kworker/-157 0..... 296444280us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:3c2 unpin <0> [531.715561] kworker/-157 0..... 296444408us : __intel_context_retire: 0000:00:02.0 bcs0: context:3c2 retire runtime: { total:58618ns, avg:21306ns } <0> [531.715672] kworker/-157 0..... 296444416us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:391 unpin <0> [531.715780] kworker/-157 0..... 296444555us : __intel_context_retire: 0000:00:02.0 bcs0: context:391 retire runtime: { total:123278ns, avg:23267ns } <0> [531.715892] kworker/-157 0..... 296444563us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:aa5 unpin <0> [531.716000] kworker/-157 0..... 296444691us : __intel_context_retire: 0000:00:02.0 ccs0: context:aa5 retire runtime: { total:224614ns, avg:81779ns } <0> [531.716126] gem_exec-2374 0..... 296446954us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41974, current 41950 <0> [531.716249] gem_exec-2374 0D..1. 296446959us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:41974, current 41950 <0> [531.716374] gem_exec-2374 0..... 296446965us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41950, current 41950 <0> [531.716494] kworker/-2406 0..... 296447027us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:637 unpin <0> [531.716605] kworker/-2406 0.N... 296447157us : __intel_context_retire: 0000:00:02.0 ccs0: context:637 retire runtime: { total:227052ns, avg:68529ns } <0> [531.716719] gem_exec-2370 0..... 296447282us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:c90 pin ring:{start:ea061000, head:0000, tail:0000} <0> [531.716847] gem_exec-2370 0..... 296447339us : __i915_request_commit: 0000:00:02.0 vcs0: fence c90:2, current 0 <0> [531.716972] gem_exec-2370 0D..1. 296447343us : __i915_request_submit: 0000:00:02.0 vcs0: fence c90:2, current 0 <0> [531.717096] gem_exec-2370 0..... 296447773us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42016, current 41954 <0> [531.717219] gem_exec-2380 0..... 296450056us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42036, current 41990 <0> [531.717332] gem_exec-2380 0..... 296450333us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:4b3 active <0> [531.717466] gem_exec-2380 0..... 296450336us : intel_timeline_pin: 0000:00:02.0 timeline:4b3 using HWSP offset:fa77c000 <0> [531.717580] gem_exec-2380 0..... 296450346us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:4b3 pin ring:{start:fa813000, head:02d0, tail:02d0} <0> [531.717708] gem_exec-2380 0..... 296450383us : __i915_request_commit: 0000:00:02.0 rcs0: fence 4b3:6, current 4 <0> [531.717831] gem_exec-2380 0D..1. 296450531us : __i915_request_submit: 0000:00:02.0 rcs0: fence 4b3:6, current 4 <0> [531.717953] gem_exec-2380 0..... 296450686us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42062, current 41990 <0> [531.718076] gem_exec-2380 0..... 296454011us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42082, current 42065 <0> [531.718199] gem_exec-2380 0D..1. 296454017us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42082, current 42066 <0> [531.718322] gem_exec-2380 0..... 296454023us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42066, current 42066 <0> [531.718455] gem_exec-2380 0..... 296455809us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42126, current 42088 <0> [531.718572] gem_exec-2380 0..... 296456030us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:3b7 active <0> [531.718691] gem_exec-2380 0..... 296456033us : intel_timeline_pin: 0000:00:02.0 timeline:3b7 using HWSP offset:fc8ec000 <0> [531.718803] gem_exec-2380 0..... 296456041us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:3b7 pin ring:{start:fc9d6000, head:05a0, tail:05a0} <0> [531.718930] gem_exec-2380 0..... 296456085us : __i915_request_commit: 0000:00:02.0 rcs0: fence 3b7:10, current 8 <0> [531.719052] gem_exec-2380 0Dn.1. 296456441us : __i915_request_submit: 0000:00:02.0 rcs0: fence 3b7:10, current 8 <0> [531.719166] gem_exec-2372 0..... 296458100us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:ca2 active <0> [531.719289] gem_exec-2374 0.N... 296464033us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42278, current 42246 <0> [531.719403] gem_exec-2374 0..... 296464275us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:961 active <0> [531.719522] gem_exec-2374 0..... 296464278us : intel_timeline_pin: 0000:00:02.0 timeline:961 using HWSP offset:f0be4000 <0> [531.719634] gem_exec-2374 0..... 296464287us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:961 pin ring:{start:f0c58000, head:05a0, tail:05a0} <0> [531.719763] gem_exec-2374 0..... 296464334us : __i915_request_commit: 0000:00:02.0 rcs0: fence 961:10, current 8 <0> [531.719886] gem_exec-2374 0D..1. 296464533us : __i915_request_submit: 0000:00:02.0 rcs0: fence 961:10, current 8 <0> [531.720009] gem_exec-2374 0..... 296466604us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42326, current 42288 <0> [531.720131] gem_exec-2374 0..... 296466624us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42282, current 42289 <0> [531.720254] gem_exec-2374 0..... 296466637us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42284, current 42290 <0> [531.720379] gem_exec-2374 0..... 296466647us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42286, current 42290 <0> [531.720505] gem_exec-2374 0..... 296466656us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42288, current 42291 <0> [531.720627] gem_exec-2374 0..... 296466658us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42290, current 42291 <0> [531.720743] gem_exec-2386 0..... 296466980us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:b9b active <0> [531.720866] gem_exec-2386 0..... 296466983us : intel_timeline_pin: 0000:00:02.0 timeline:b9b using HWSP offset:ec02c000 <0> [531.720978] gem_exec-2386 0..... 296466991us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:b9b pin ring:{start:ec19f000, head:0168, tail:0168} <0> [531.721104] gem_exec-2386 0..... 296467032us : __i915_request_commit: 0000:00:02.0 rcs0: fence b9b:4, current 2 <0> [531.721226] gem_exec-2386 0D..1. 296467243us : __i915_request_submit: 0000:00:02.0 rcs0: fence b9b:4, current 2 <0> [531.721349] gem_exec-2377 0.N... 296470294us : intel_timeline_pin: 0000:00:02.0 timeline:c9e using HWSP offset:e9e66000 <0> [531.721476] gem_exec-2395 0..... 296479022us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42504, current 42472 <0> [531.721590] gem_exec-2395 0..... 296479580us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:7dd active <0> [531.721712] gem_exec-2395 0..... 296479584us : intel_timeline_pin: 0000:00:02.0 timeline:7dd using HWSP offset:f3f3f000 <0> [531.721828] gem_exec-2395 0..... 296479592us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:7dd pin ring:{start:f3f7a000, head:00b0, tail:00b0} <0> [531.721956] gem_exec-2395 0..... 296479639us : __i915_request_commit: 0000:00:02.0 vcs1: fence 7dd:4, current 2 <0> [531.722082] gem_exec-2395 0D..1. 296479644us : __i915_request_submit: 0000:00:02.0 vcs1: fence 7dd:4, current 2 <0> [531.722205] gem_exec-2395 0..... 296479839us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42544, current 42476 <0> [531.722327] gem_exec-2395 0..... 296483966us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42568, current 42528 <0> [531.722458] gem_exec-2395 0D..1. 296483971us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42568, current 42528 <0> [531.722585] gem_exec-2403 0..... 296484659us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42580, current 42548 <0> [531.722707] gem_exec-2403 0D..1. 296484664us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42580, current 42548 <0> [531.722822] gem_exec-2403 0..... 296485977us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a33 active <0> [531.722941] gem_exec-2403 0..... 296485982us : intel_timeline_pin: 0000:00:02.0 timeline:a33 using HWSP offset:ef0d4000 <0> [531.723055] gem_exec-2403 0..... 296485991us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a33 pin ring:{start:ef0d5000, head:02d0, tail:02d0} <0> [531.723184] gem_exec-2403 0..... 296486046us : __i915_request_commit: 0000:00:02.0 ccs0: fence a33:6, current 4 <0> [531.723305] gem_exec-2403 0D..1. 296486053us : __i915_request_submit: 0000:00:02.0 ccs0: fence a33:6, current 4 <0> [531.723425] gem_exec-2400 0..... 296486223us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:c9a pin ring:{start:e9eba000, head:0000, tail:0000} <0> [531.723554] gem_exec-2400 0..... 296486295us : __i915_request_commit: 0000:00:02.0 vcs0: fence c9a:2, current 0 <0> [531.723684] gem_exec-2400 0D..1. 296486299us : __i915_request_submit: 0000:00:02.0 vcs0: fence c9a:2, current 0 <0> [531.723795] gem_exec-2377 0..... 296489042us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e pin ring:{start:e9e67000, head:0000, tail:0000} <0> [531.723913] gem_exec-2377 0..... 296489056us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:c9e unpin <0> [531.724024] gem_exec-2377 0..... 296489183us : __intel_context_retire: 0000:00:02.0 vcs1: context:c9e retire runtime: { total:0ns, avg:0ns } <0> [531.724136] gem_exec-2377 0..... 296489186us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e active <0> [531.724253] gem_exec-2377 0..... 296489187us : intel_timeline_pin: 0000:00:02.0 timeline:c9e using HWSP offset:e9e66000 <0> [531.724369] gem_exec-2377 0..... 296489190us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e pin ring:{start:e9e67000, head:0000, tail:0000} <0> [531.724490] gem_exec-2377 0..... 296489198us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:c9e unpin <0> [531.724605] gem_exec-2377 0..... 296489323us : __intel_context_retire: 0000:00:02.0 vcs1: context:c9e retire runtime: { total:0ns, avg:0ns } <0> [531.724721] gem_exec-2377 0..... 296489326us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e active <0> [531.724838] gem_exec-2377 0..... 296489327us : intel_timeline_pin: 0000:00:02.0 timeline:c9e using HWSP offset:e9e66000 <0> [531.724948] gem_exec-2377 0..... 296489330us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e pin ring:{start:e9e67000, head:0000, tail:0000} <0> [531.725076] gem_exec-2377 0..... 296489377us : __i915_request_commit: 0000:00:02.0 vcs1: fence c9e:2, current 0 <0> [531.725199] gem_exec-2377 0D..1. 296489381us : __i915_request_submit: 0000:00:02.0 vcs1: fence c9e:2, current 0 <0> [531.725324] gem_exec-2395 0..... 296490984us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42630, current 42630 <0> [531.725455] gem_exec-2377 0..... 296491756us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42688, current 42656 <0> [531.725589] gem_exec-2377 0..... 296492472us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42728, current 42680 <0> [531.725723] gem_exec-2364 0..... 296497066us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42786, current 42722 <0> [531.725841] gem_exec-2364 0..... 296497174us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b05 active <0> [531.725959] gem_exec-2364 0..... 296497177us : intel_timeline_pin: 0000:00:02.0 timeline:b05 using HWSP offset:ed306000 <0> [531.726071] gem_exec-2364 0..... 296497186us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b05 pin ring:{start:ed409000, head:0160, tail:0160} <0> [531.726199] gem_exec-2364 0..... 296497220us : __i915_request_commit: 0000:00:02.0 vcs0: fence b05:6, current 4 <0> [531.726325] gem_exec-2364 0D..1. 296497224us : __i915_request_submit: 0000:00:02.0 vcs0: fence b05:6, current 4 <0> [531.726458] gem_exec-2377 0..... 296500175us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42798, current 42764 <0> [531.726582] gem_exec-2377 0D..1. 296500181us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42798, current 42764 <0> [531.726706] gem_exec-2367 0..... 296501482us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42842, current 42816 <0> [531.726831] gem_exec-2367 0..... 296501486us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42816, current 42816 <0> [531.726950] gem_exec-2397 0..... 296502344us : intel_timeline_pin: 0000:00:02.0 timeline:ca3 using HWSP offset:e9c7f000 <0> [531.727071] gem_exec-2367 0..... 296507140us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42916, current 42896 <0> [531.727202] gem_exec-2367 0D..1. 296507147us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42916, current 42896 <0> [531.727324] gem_exec-2367 0..... 296507522us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42896, current 42904 <0> [531.727454] gem_exec-2367 0..... 296507524us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42898, current 42904 <0> [531.727580] gem_exec-2367 0..... 296507527us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42900, current 42904 <0> [531.727706] gem_exec-2367 0..... 296507530us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42902, current 42904 <0> [531.727830] gem_exec-2367 0..... 296507533us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42904, current 42904 <0> [531.727955] gem_exec-2403 0..... 296508877us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42982, current 42930 <0> [531.728071] gem_exec-2403 0..... 296509052us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a74 active <0> [531.728188] gem_exec-2403 0..... 296509055us : intel_timeline_pin: 0000:00:02.0 timeline:a74 using HWSP offset:ee6a1000 <0> [531.728302] gem_exec-2403 0..... 296509062us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a74 pin ring:{start:ee808000, head:05a0, tail:05a0} <0> [531.728433] gem_exec-2403 0..... 296509102us : __i915_request_commit: 0000:00:02.0 ccs0: fence a74:10, current 8 <0> [531.728561] gem_exec-2403 0D..1. 296509108us : __i915_request_submit: 0000:00:02.0 ccs0: fence a74:10, current 8 <0> [531.728687] gem_exec-2403 0..... 296513942us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43032, current 43025 <0> [531.728812] gem_exec-2403 0D..1. 296513948us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43032, current 43025 <0> [531.728935] gem_exec-2403 0..... 296513955us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43026, current 43026 <0> [531.729057] gem_exec-2403 0..... 296515476us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43068, current 43050 <0> [531.729180] gem_exec-2403 0D..1. 296515483us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43068, current 43050 <0> [531.729294] kworker/-148 0..... 296515729us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:4e2 unpin <0> [531.729417] kworker/-148 0..... 296515801us : __intel_context_retire: 0000:00:02.0 bcs0: context:4e2 retire runtime: { total:84800ns, avg:20511ns } <0> [531.729557] gem_exec-2388 0..... 296516066us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43102, current 43058 <0> [531.729683] gem_exec-2388 0..... 296516070us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43058, current 43058 <0> [531.729807] gem_exec-2388 0..... 296516392us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43126, current 43074 <0> [531.729919] gem_exec-2375 0..... 296516547us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 active <0> [531.730036] gem_exec-2375 0..... 296516550us : intel_timeline_pin: 0000:00:02.0 timeline:8c4 using HWSP offset:f2144000 <0> [531.730149] gem_exec-2375 0..... 296516557us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 pin ring:{start:f2145000, head:0160, tail:0160} <0> [531.730264] gem_exec-2375 0..... 296516571us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:8c4 unpin <0> [531.730379] gem_exec-2375 0..... 296516640us : __intel_context_retire: 0000:00:02.0 bcs0: context:8c4 retire runtime: { total:36146ns, avg:16218ns } <0> [531.730497] gem_exec-2375 0..... 296516644us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 active <0> [531.730613] gem_exec-2375 0..... 296516646us : intel_timeline_pin: 0000:00:02.0 timeline:8c4 using HWSP offset:f2144000 <0> [531.730725] gem_exec-2375 0..... 296516649us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 pin ring:{start:f2145000, head:0160, tail:0160} <0> [531.730840] gem_exec-2375 0..... 296516661us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:8c4 unpin <0> [531.730950] gem_exec-2375 0..... 296516731us : __intel_context_retire: 0000:00:02.0 bcs0: context:8c4 retire runtime: { total:36146ns, avg:16218ns } <0> [531.731062] gem_exec-2375 0..... 296516734us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 active <0> [531.731179] gem_exec-2375 0..... 296516735us : intel_timeline_pin: 0000:00:02.0 timeline:8c4 using HWSP offset:f2144000 <0> [531.731289] gem_exec-2375 0..... 296516738us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 pin ring:{start:f2145000, head:0160, tail:0160} <0> [531.731427] gem_exec-2375 0..... 296516771us : __i915_request_commit: 0000:00:02.0 bcs0: fence 8c4:6, current 4 <0> [531.731558] gem_exec-2375 0D..1. 296517047us : __i915_request_submit: 0000:00:02.0 bcs0: fence 8c4:6, current 4 <0> [531.731683] gem_exec-2387 0..... 296521989us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43190, current 43146 <0> [531.731806] gem_exec-2387 0D..1. 296521995us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43190, current 43146 <0> [531.731931] gem_exec-2374 0..... 296522208us : __i915_request_commit: 0000:00:02.0 rcs0: fence 749:8, current 6 <0> [531.732060] gem_exec-2374 0D..1. 296522212us : __i915_request_submit: 0000:00:02.0 rcs0: fence 749:8, current 6 <0> [531.732193] gem_exec-2374 0..... 296522482us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43216, current 43156 <0> [531.732323] gem_exec-2374 0..... 296522765us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43230, current 43166 <0> [531.732438] kworker/-2408 0..... 296522938us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:8cb unpin <0> [531.732549] kworker/-2408 0..... 296523066us : __intel_context_retire: 0000:00:02.0 rcs0: context:8cb retire runtime: { total:363739ns, avg:117236ns } <0> [531.732663] kworker/-2408 0..... 296523074us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:566 unpin <0> [531.732773] kworker/-2408 0..... 296523203us : __intel_context_retire: 0000:00:02.0 rcs0: context:566 retire runtime: { total:1710681ns, avg:206488ns } <0> [531.732891] kworker/-2408 0..... 296523949us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:a33 unpin <0> [531.733021] kworker/-2408 0..... 296524073us : __intel_context_retire: 0000:00:02.0 ccs0: context:a33 retire runtime: { total:320809ns, avg:125133ns } <0> [531.733137] kworker/-2408 0..... 296524213us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:605 unpin <0> [531.733248] kworker/-2408 0..... 296524337us : __intel_context_retire: 0000:00:02.0 vcs1: context:605 retire runtime: { total:93227ns, avg:22154ns } <0> [531.733361] kworker/-2408 0..... 296525599us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:49c unpin <0> [531.733473] kworker/-2408 0.N... 296525732us : __intel_context_retire: 0000:00:02.0 vcs1: context:49c retire runtime: { total:123596ns, avg:23744ns } <0> [531.733588] gem_exec-2397 0..... 296527754us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 pin ring:{start:e9cb6000, head:0000, tail:0000} <0> [531.733704] gem_exec-2397 0..... 296527773us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:ca3 unpin <0> [531.733816] gem_exec-2397 0..... 296527900us : __intel_context_retire: 0000:00:02.0 ccs0: context:ca3 retire runtime: { total:0ns, avg:0ns } <0> [531.733927] gem_exec-2397 0..... 296527905us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 active <0> [531.734044] gem_exec-2397 0..... 296527906us : intel_timeline_pin: 0000:00:02.0 timeline:ca3 using HWSP offset:e9c7f000 <0> [531.734153] gem_exec-2397 0..... 296527911us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 pin ring:{start:e9cb6000, head:0000, tail:0000} <0> [531.734265] gem_exec-2397 0..... 296527926us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:ca3 unpin <0> [531.734380] gem_exec-2397 0..... 296528053us : __intel_context_retire: 0000:00:02.0 ccs0: context:ca3 retire runtime: { total:0ns, avg:0ns } <0> [531.734497] gem_exec-2397 0..... 296528056us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 active <0> [531.734632] gem_exec-2397 0..... 296528057us : intel_timeline_pin: 0000:00:02.0 timeline:ca3 using HWSP offset:e9c7f000 <0> [531.734760] gem_exec-2397 0..... 296528060us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 pin ring:{start:e9cb6000, head:0000, tail:0000} <0> [531.734912] gem_exec-2397 0..... 296528407us : __i915_request_commit: 0000:00:02.0 ccs0: fence ca3:2, current 0 <0> [531.735064] gem_exec-2397 0D..1. 296528411us : __i915_request_submit: 0000:00:02.0 ccs0: fence ca3:2, current 0 <0> [531.735196] gem_exec-2397 0..... 296529484us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43304, current 43263 <0> [531.735323] gem_exec-2399 0..... 296529684us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43268, current 43268 <0> [531.735449] gem_exec-2397 0..... 296530257us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43348, current 43288 <0> [531.735593] gem_exec-2397 0..... 296530264us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43288, current 43288 <0> [531.735718] gem_exec-2392 0..... 296531089us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43362, current 43302 <0> [531.735832] gem_exec-2392 0..... 296531241us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:82a active <0> [531.735949] gem_exec-2392 0..... 296531245us : intel_timeline_pin: 0000:00:02.0 timeline:82a using HWSP offset:f352e000 <0> [531.736070] gem_exec-2392 0..... 296531253us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:82a pin ring:{start:f367c000, head:0438, tail:0438} <0> [531.736217] gem_exec-2392 0..... 296531291us : __i915_request_commit: 0000:00:02.0 rcs0: fence 82a:8, current 6 <0> [531.736341] gem_exec-2392 0D..1. 296531295us : __i915_request_submit: 0000:00:02.0 rcs0: fence 82a:8, current 6 <0> [531.736464] gem_exec-2392 0..... 296533589us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43400, current 43346 <0> [531.736587] gem_exec-2364 0..... 296536242us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43446, current 43414 <0> [531.736709] gem_exec-2364 0D..1. 296536248us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43446, current 43414 <0> [531.736822] kworker/-1076 0..... 296536777us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:3ca unpin <0> [531.736934] kworker/-1076 0..... 296536848us : __intel_context_retire: 0000:00:02.0 ccs0: context:3ca retire runtime: { total:284080ns, avg:72292ns } <0> [531.737062] gem_exec-2376 0..... 296537535us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43490, current 43446 <0> [531.737175] gem_exec-2376 0..... 296537650us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b99 active <0> [531.737293] gem_exec-2376 0..... 296537652us : intel_timeline_pin: 0000:00:02.0 timeline:b99 using HWSP offset:ec04e000 <0> [531.737407] gem_exec-2376 0..... 296537656us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b99 pin ring:{start:ec22a000, head:0210, tail:0210} <0> [531.737544] gem_exec-2376 0..... 296537689us : __i915_request_commit: 0000:00:02.0 vcs0: fence b99:8, current 6 <0> [531.737684] gem_exec-2376 0D..1. 296537693us : __i915_request_submit: 0000:00:02.0 vcs0: fence b99:8, current 6 <0> [531.737827] gem_exec-2376 0..... 296538210us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43528, current 43458 <0> [531.737963] gem_exec-2376 0..... 296538214us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43458, current 43458 <0> [531.738093] gem_exec-2388 0..... 296545490us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43566, current 43554 <0> [531.738221] gem_exec-2388 0D..1. 296545495us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43566, current 43554 <0> [531.738335] gem_exec-2388 0..... 296546077us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:5b2 active <0> [531.738454] gem_exec-2388 0..... 296546080us : intel_timeline_pin: 0000:00:02.0 timeline:5b2 using HWSP offset:f86d3000 <0> [531.738567] gem_exec-2388 0..... 296546088us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:5b2 pin ring:{start:f883c000, head:02c0, tail:02c0} <0> [531.738694] gem_exec-2388 0..... 296546128us : __i915_request_commit: 0000:00:02.0 vcs0: fence 5b2:10, current 8 <0> [531.738816] gem_exec-2388 0D..1. 296546133us : __i915_request_submit: 0000:00:02.0 vcs0: fence 5b2:10, current 8 <0> [531.738938] gem_exec-2388 0..... 296546810us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43598, current 43568 <0> [531.739060] gem_exec-2388 0..... 296547355us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43632, current 43568 <0> [531.739181] gem_exec-2377 20..... 296548956us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43606, current 43606 <0> [531.739304] gem_exec-2390 0..... 296549167us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43670, current 43606 <0> [531.739431] gem_exec-2385 20..... 296549243us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43672, current 43606 <0> [531.739559] gem_exec-2377 21..... 296552221us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43686, current 43674 <0> [531.739681] gem_exec-2377 21D..1. 296552252us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43686, current 43675 <0> [531.739803] gem_exec-2377 21..... 296552634us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43676, current 43684 <0> [531.739924] gem_exec-2377 21..... 296552652us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43678, current 43684 <0> [531.740045] gem_exec-2377 21..... 296552735us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43680, current 43684 <0> [531.740167] gem_exec-2377 21..... 296552749us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43682, current 43684 <0> [531.740289] gem_exec-2399 0..... 296553553us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43706, current 43689 <0> [531.740412] gem_exec-2399 0D..1. 296553560us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43706, current 43690 <0> [531.740533] gem_exec-2399 0..... 296553566us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43690, current 43690 <0> [531.740656] gem_exec-2363 20..... 296554097us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43712, current 43692 <0> [531.740778] gem_exec-2363 20D..1. 296554119us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43712, current 43693 <0> [531.740900] gem_exec-2372 21..... 296554259us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43698, current 43698 <0> [531.741023] gem_exec-2399 0..... 296555455us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43760, current 43718 <0> [531.741147] gem_exec-2399 0..... 296555761us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43780, current 43718 <0> [531.741261] gem_exec-2362 0..... 296555938us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:c2a active <0> [531.741383] gem_exec-2362 0..... 296555942us : intel_timeline_pin: 0000:00:02.0 timeline:c2a using HWSP offset:ead5e000 <0> [531.741497] gem_exec-2362 0..... 296555950us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:c2a pin ring:{start:eadeb000, head:02d0, tail:02d0} <0> [531.741624] gem_exec-2362 0..... 296555986us : __i915_request_commit: 0000:00:02.0 rcs0: fence c2a:6, current 4 <0> [531.741745] gem_exec-2362 0D..1. 296555991us : __i915_request_submit: 0000:00:02.0 rcs0: fence c2a:6, current 4 <0> [531.741864] gem_exec-2362 0..... 296558541us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43806, current 43744 <0> [531.741980] gem_exec-2394 0..... 296559876us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:cb9 active <0> [531.742095] gem_exec-2371 20..... 296561566us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:cbb active <0> [531.742221] gem_exec-2399 0..... 296563216us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43862, current 43844 <0> [531.742344] gem_exec-2399 0D..1. 296563222us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43862, current 43844 <0> [531.742457] gem_exec-2399 0..... 296563526us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:820 active <0> [531.742576] gem_exec-2399 0..... 296563530us : intel_timeline_pin: 0000:00:02.0 timeline:820 using HWSP offset:f3695000 <0> [531.742687] gem_exec-2399 0..... 296563540us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:820 pin ring:{start:f36f1000, head:0160, tail:0160} <0> [531.742814] gem_exec-2399 0..... 296563586us : __i915_request_commit: 0000:00:02.0 bcs0: fence 820:6, current 4 <0> [531.742935] gem_exec-2399 0D..1. 296563591us : __i915_request_submit: 0000:00:02.0 bcs0: fence 820:6, current 4 <0> [531.743056] gem_exec-2364 0..... 296564053us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43896, current 43854 <0> [531.743168] gem_exec-2364 0..... 296564186us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b82 active <0> [531.743286] gem_exec-2364 0..... 296564189us : intel_timeline_pin: 0000:00:02.0 timeline:b82 using HWSP offset:ec414000 <0> [531.743403] gem_exec-2364 0..... 296564195us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b82 pin ring:{start:ec47f000, head:0210, tail:0210} <0> [531.743529] gem_exec-2364 0..... 296564230us : __i915_request_commit: 0000:00:02.0 vcs0: fence b82:8, current 6 <0> [531.743650] gem_exec-2364 0D..1. 296564234us : __i915_request_submit: 0000:00:02.0 vcs0: fence b82:8, current 6 <0> [531.743771] gem_exec-2364 0..... 296564700us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43924, current 43858 <0> [531.743893] gem_exec-2364 0..... 296566269us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43948, current 43892 <0> [531.744013] gem_exec-2364 0..... 296573469us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44004, current 43988 <0> [531.744135] gem_exec-2364 0D..1. 296573474us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:44004, current 43988 <0> [531.744248] gem_exec-2364 0..... 296574080us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f active <0> [531.744372] gem_exec-2364 0..... 296574086us : intel_timeline_pin: 0000:00:02.0 timeline:49f using HWSP offset:fab13000 <0> [531.744485] gem_exec-2364 0..... 296574093us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f pin ring:{start:fab14000, head:02c0, tail:02c0} <0> [531.744600] gem_exec-2364 0..... 296574121us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:49f unpin <0> [531.744711] gem_exec-2364 0..... 296574204us : __intel_context_retire: 0000:00:02.0 vcs0: context:49f retire runtime: { total:111777ns, avg:37100ns } <0> [531.744823] gem_exec-2364 0..... 296574207us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f active <0> [531.744940] gem_exec-2364 0..... 296574208us : intel_timeline_pin: 0000:00:02.0 timeline:49f using HWSP offset:fab13000 <0> [531.745050] gem_exec-2364 0..... 296574213us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f pin ring:{start:fab14000, head:02c0, tail:02c0} <0> [531.745166] gem_exec-2364 0..... 296574226us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:49f unpin <0> [531.745275] gem_exec-2364 0..... 296574308us : __intel_context_retire: 0000:00:02.0 vcs0: context:49f retire runtime: { total:111777ns, avg:37100ns } <0> [531.745392] gem_exec-2364 0..... 296574311us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f active <0> [531.745510] gem_exec-2364 0..... 296574313us : intel_timeline_pin: 0000:00:02.0 timeline:49f using HWSP offset:fab13000 <0> [531.745619] gem_exec-2364 0..... 296574318us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f pin ring:{start:fab14000, head:02c0, tail:02c0} <0> [531.745732] kworker/-157 0..... 296577912us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:6ac unpin <0> [531.745841] kworker/-157 0..... 296578041us : __intel_context_retire: 0000:00:02.0 vecs0: context:6ac retire runtime: { total:89358ns, avg:29945ns } <0> [531.745953] kworker/-157 0..... 296578049us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:781 unpin <0> [531.746061] kworker/-157 0..... 296578178us : __intel_context_retire: 0000:00:02.0 vcs1: context:781 retire runtime: { total:81779ns, avg:21200ns } <0> [531.746173] kworker/-157 0..... 296578211us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:bed unpin <0> [531.746281] kworker/-157 0..... 296578339us : __intel_context_retire: 0000:00:02.0 vecs0: context:bed retire runtime: { total:55544ns, avg:23108ns } <0> [531.746401] kworker/-157 0..... 296578348us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:962 unpin <0> [531.746511] kworker/-157 0..... 296578473us : __intel_context_retire: 0000:00:02.0 vcs0: context:962 retire runtime: { total:243005ns, avg:40439ns } <0> [531.746642] gem_exec-2393 0..... 296578920us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44086, current 44038 <0> [531.746771] gem_exec-2393 0..... 296578923us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44038, current 44038 <0> [531.746898] gem_exec-2390 0..... 296580944us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44140, current 44090 <0> [531.747010] gem_exec-2390 0..... 296581060us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:a67 active <0> [531.747128] gem_exec-2390 0..... 296581064us : intel_timeline_pin: 0000:00:02.0 timeline:a67 using HWSP offset:ee76c000 <0> [531.747239] gem_exec-2390 0..... 296581074us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:a67 pin ring:{start:ee9d1000, head:00b0, tail:00b0} <0> [531.747375] gem_exec-2390 0..... 296581140us : __i915_request_commit: 0000:00:02.0 vecs0: fence a67:4, current 2 <0> [531.747499] gem_exec-2390 0D..1. 296581149us : __i915_request_submit: 0000:00:02.0 vecs0: fence a67:4, current 2 <0> [531.747623] gem_exec-2390 0..... 296581389us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44166, current 44092 <0> [531.747746] gem_exec-2379 0..... 296585260us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44210, current 44164 <0> [531.747858] kworker/-157 0..... 296595605us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:cae unpin <0> [531.747970] kworker/-157 0..... 296595676us : __intel_context_retire: 0000:00:02.0 bcs0: context:cae retire runtime: { total:18073ns, avg:18073ns } <0> [531.748095] gem_exec-2392 0..... 296596579us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44332, current 44294 <0> [531.748220] gem_exec-2379 20..... 296596741us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44340, current 44294 <0> [531.748346] gem_exec-2372 21..... 296596931us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44348, current 44294 <0> [531.748462] gem_exec-2392 0..... 296597040us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:a65 active <0> [531.748578] gem_exec-2392 0..... 296597044us : intel_timeline_pin: 0000:00:02.0 timeline:a65 using HWSP offset:ee925000 <0> [531.748689] gem_exec-2392 0..... 296597052us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:a65 pin ring:{start:ee9f3000, head:05a0, tail:05a0} <0> [531.748803] kworker/-157 0..... 296600848us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:6a5 unpin <0> [531.748926] gem_exec-2372 21..... 296600886us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44386, current 44328 <0> [531.749037] kworker/-157 0..... 296600920us : __intel_context_retire: 0000:00:02.0 vecs0: context:6a5 retire runtime: { total:162604ns, avg:21783ns } <0> [531.749150] kworker/-157 0..... 296600966us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:add unpin <0> [531.749261] kworker/-157 0..... 296601038us : __intel_context_retire: 0000:00:02.0 vcs0: context:add retire runtime: { total:94923ns, avg:23956ns } <0> [531.749390] gem_exec-2384 0..... 296604593us : intel_timeline_pin: 0000:00:02.0 timeline:cb6 using HWSP offset:e996f000 <0> [531.749514] gem_exec-2405 20..... 296605638us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44426, current 44428 <0> [531.749638] gem_exec-2388 0..... 296606032us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44446, current 44428 <0> [531.749749] gem_exec-2388 0..... 296606119us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:ae2 active <0> [531.749867] gem_exec-2388 0..... 296606122us : intel_timeline_pin: 0000:00:02.0 timeline:ae2 using HWSP offset:ed806000 <0> [531.749980] gem_exec-2388 0..... 296606128us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:ae2 pin ring:{start:ed888000, head:0210, tail:0210} <0> [531.750101] gem_exec-2388 0..... 296606142us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:ae2 unpin <0> [531.750210] gem_exec-2388 0.N... 296606282us : __intel_context_retire: 0000:00:02.0 vcs0: context:ae2 retire runtime: { total:45103ns, avg:15264ns } <0> [531.750341] gem_exec-2395 0..... 296606767us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44474, current 44428 <0> [531.750462] gem_exec-2405 0..... 296607015us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:831 active <0> [531.750600] gem_exec-2405 0..... 296607019us : intel_timeline_pin: 0000:00:02.0 timeline:831 using HWSP offset:f3461000 <0> [531.750719] gem_exec-2405 0..... 296607029us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:831 pin ring:{start:f3535000, head:0210, tail:0210} <0> [531.750847] gem_exec-2405 0..... 296607069us : __i915_request_commit: 0000:00:02.0 bcs0: fence 831:8, current 6 <0> [531.750969] gem_exec-2405 0D..1. 296607073us : __i915_request_submit: 0000:00:02.0 bcs0: fence 831:8, current 6 <0> [531.751081] kworker/-157 0..... 296610311us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:a28 unpin <0> [531.751192] kworker/-157 0..... 296610464us : __intel_context_retire: 0000:00:02.0 vcs1: context:a28 retire runtime: { total:111565ns, avg:30369ns } <0> [531.751307] kworker/-157 0..... 296610488us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:2f5 unpin <0> [531.751421] kworker/-157 0.N... 296610731us : __intel_context_retire: 0000:00:02.0 vcs0: context:2f5 retire runtime: { total:78758ns, avg:19610ns } <0> [531.751548] gem_exec-2372 20..... 296615702us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44582, current 44566 <0> [531.751672] gem_exec-2372 20D..1. 296615722us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:44582, current 44566 <0> [531.751795] gem_exec-2372 20..... 296616684us : i915_request_retire.part.0: 0000:00:02.0 vecs0: fence 5b7:10, current 12 <0> [531.751917] gem_exec-2372 20..... 296616759us : __i915_request_commit: 0000:00:02.0 vecs0: fence 5b7:14, current 12 <0> [531.752039] gem_exec-2372 20D..1. 296616775us : __i915_request_submit: 0000:00:02.0 vecs0: fence 5b7:14, current 12 <0> [531.752161] gem_exec-2386 0..... 296616902us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44600, current 44589 <0> [531.752284] gem_exec-2386 0D..1. 296616909us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:44600, current 44589 <0> [531.752408] gem_exec-2386 0..... 296616916us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44590, current 44590 <0> [531.752523] gem_exec-2386 0..... 296617703us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:65f active <0> [531.752641] gem_exec-2386 0..... 296617708us : intel_timeline_pin: 0000:00:02.0 timeline:65f using HWSP offset:f7073000 <0> [531.752754] gem_exec-2386 0..... 296617718us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:65f pin ring:{start:f7159000, head:02d0, tail:02d0} <0> [531.752881] gem_exec-2372 20..... 296617752us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44622, current 44596 <0> [531.753003] gem_exec-2386 0..... 296617766us : __i915_request_commit: 0000:00:02.0 rcs0: fence 65f:6, current 4 <0> [531.753125] gem_exec-2372 20..... 296617770us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44596, current 44596 <0> [531.753251] gem_exec-2372 20..... 296617884us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44598, current 44598 <0> [531.753386] gem_exec-2372 20..... 296617956us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44624, current 44599 <0> [531.753510] gem_exec-2372 20..... 296617967us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44600, current 44600 <0> [531.753633] gem_exec-2386 0D..1. 296618027us : __i915_request_submit: 0000:00:02.0 rcs0: fence 65f:6, current 4 <0> [531.753760] gem_exec-2386 0..... 296618486us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44648, current 44608 <0> [531.753882] gem_exec-2383 20..... 296618794us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44656, current 44608 <0> [531.754003] gem_exec-2400 0..... 296618970us : intel_timeline_pin: 0000:00:02.0 timeline:cbc using HWSP offset:e9957000 <0> [531.754116] gem_exec-2383 20..... 296619032us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:42f active <0> [531.754235] gem_exec-2383 20..... 296619043us : intel_timeline_pin: 0000:00:02.0 timeline:42f using HWSP offset:fb871000 <0> [531.754359] gem_exec-2383 20..... 296619070us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:42f pin ring:{start:fb945000, head:0160, tail:0160} <0> [531.754488] gem_exec-2383 20..... 296619191us : __i915_request_commit: 0000:00:02.0 vcs1: fence 42f:6, current 4 <0> [531.754610] gem_exec-2383 20D..1. 296619202us : __i915_request_submit: 0000:00:02.0 vcs1: fence 42f:6, current 4 <0> [531.754733] gem_exec-2397 21..... 296619344us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44678, current 44608 <0> [531.754846] kworker/-159 21.N... 296619800us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:5e8 unpin <0> [531.754958] kworker/-159 21.N... 296619971us : __intel_context_retire: 0000:00:02.0 vcs0: context:5e8 retire runtime: { total:101760ns, avg:25599ns } <0> [531.755072] gem_exec-2400 21..... 296620746us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:cbc pin ring:{start:e9a86000, head:0000, tail:0000} <0> [531.755199] gem_exec-2400 21..... 296620916us : __i915_request_commit: 0000:00:02.0 vcs0: fence cbc:2, current 0 <0> [531.755322] gem_exec-2400 21D..1. 296620929us : __i915_request_submit: 0000:00:02.0 vcs0: fence cbc:2, current 0 <0> [531.755435] kworker/-1076 0..... 296621495us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:a67 unpin <0> [531.755546] kworker/-1076 0..... 296621628us : __intel_context_retire: 0000:00:02.0 vecs0: context:a67 retire runtime: { total:62858ns, avg:21571ns } <0> [531.755660] kworker/-1076 0..... 296621639us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:4ea unpin <0> [531.755770] kworker/-1076 0..... 296621769us : __intel_context_retire: 0000:00:02.0 vcs0: context:4ea retire runtime: { total:99004ns, avg:41075ns } <0> [531.755883] kworker/-1076 0..... 296621778us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:3f4 unpin <0> [531.755994] kworker/-1076 0..... 296621908us : __intel_context_retire: 0000:00:02.0 vcs0: context:3f4 retire runtime: { total:137058ns, avg:24698ns } <0> [531.756116] gem_exec-2373 20..... 296622097us : intel_timeline_pin: 0000:00:02.0 timeline:cbd using HWSP offset:e9951000 <0> [531.756226] kworker/-1076 0..... 296623415us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:cb1 unpin <0> [531.756345] kworker/-1076 0..... 296623566us : __intel_context_retire: 0000:00:02.0 vcs1: context:cb1 retire runtime: { total:48601ns, avg:48601ns } <0> [531.756474] gem_exec-2400 21..... 296626806us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44714, current 44692 <0> [531.756597] gem_exec-2400 21..... 296626820us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44690, current 44693 <0> [531.756721] gem_exec-2400 21..... 296626830us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44692, current 44693 <0> [531.756844] gem_exec-2400 21..... 296626834us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44694, current 44694 <0> [531.756966] gem_exec-2376 20..... 296627357us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44740, current 44702 <0> [531.757089] gem_exec-2386 0..... 296627413us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44742, current 44702 <0> [531.757214] gem_exec-2386 0D..1. 296627420us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:44742, current 44702 <0> [531.757334] gem_exec-2386 0..... 296627514us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:728 active <0> [531.757457] gem_exec-2386 0..... 296627517us : intel_timeline_pin: 0000:00:02.0 timeline:728 using HWSP offset:f562d000 <0> [531.757571] gem_exec-2386 0..... 296627525us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:728 pin ring:{start:f5711000, head:02d0, tail:02d0} <6> [531.757630] [IGT] gem_exec_schedule: finished subtest vcs0, SUCCESS <0> [531.757690] gem_exec-2386 0..... 296627547us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:728 unpin <0> [531.757815] gem_exec-2400 21..... 296627613us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44750, current 44702

<6> [531.666344] [IGT] gem_exec_schedule: starting dynamic subtest vcs0

<7> [531.666947] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<7> [531.678479] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<3> [531.678596] guc_lrc_desc_unpin:3418 GEM_BUG_ON(!ctx_id_mapped(guc, ce->guc_id.id))

<0> [531.678625] ---------------------------------

<0> [531.679617] kworker/-12 20..... 48608188us : __i915_request_commit: 0000:00:02.0 other0: fence 10:17, current 16

<4> [531.679863] kauditd_printk_skb: 113 callbacks suppressed

<5> [531.679865] audit: type=1400 audit(1754566429.927:125): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<0> [531.680132] kworker/-12 20D..1. 48608209us : __i915_request_submit: 0000:00:02.0 other0: fence 10:17, current 16

<5> [531.680404] audit: type=1400 audit(1754566429.927:126): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<0> [531.680425] kworker/-12 20..... 48619005us : __engine_unpark: 0000:00:02.0 other0:

<5> [531.680684] audit: type=1400 audit(1754566429.928:127): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<5> [531.680697] audit: type=1400 audit(1754566429.928:128): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<0> [531.680699] kworker/-12 20..... 48619035us : __gt_unpark: 0000:00:02.0

<5> [531.680732] audit: type=1400 audit(1754566429.928:129): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<0> [531.680962] kworker/-12 20..... 48619157us : __engine_unpark: 0000:00:02.0 other0: context:f reset { seqno:1, *hwsp:1, ring:58 }

<0> [531.681288] kworker/-12 20..... 48619211us : __i915_request_commit: 0000:00:02.0 other0: fence 10:18, current 17

<7> [531.681333] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.681637] kworker/-12 20D..1. 48619230us : __i915_request_submit: 0000:00:02.0 other0: fence 10:18, current 17

<0> [531.681930] kworker/-12 20..... 48629856us : __engine_unpark: 0000:00:02.0 other0:

<5> [531.681945] audit: type=1400 audit(1754566429.929:130): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<5> [531.681995] audit: type=1400 audit(1754566429.929:131): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<5> [531.682002] audit: type=1400 audit(1754566429.929:132): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<0> [531.682203] kworker/-12 20..... 48629884us : __gt_unpark: 0000:00:02.0

<0> [531.682466] kworker/-12 20..... 48629992us : __engine_unpark: 0000:00:02.0 other0: context:f reset { seqno:1, *hwsp:1, ring:58 }

<5> [531.682629] audit: type=1400 audit(1754566429.930:133): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<5> [531.682660] audit: type=1400 audit(1754566429.930:134): apparmor="DENIED" operation="open" class="file" profile="rsyslogd" name="/run/systemd/sessions/" pid=848 comm=72733A6D61696E20513A526567 requested_mask="r" denied_mask="r" fsuid=103 ouid=0

<0> [531.682767] kworker/-12 20..... 48630040us : __i915_request_commit: 0000:00:02.0 other0: fence 10:19, current 18

<0> [531.682937] kworker/-12 20D..1. 48630058us : __i915_request_submit: 0000:00:02.0 other0: fence 10:19, current 18

<0> [531.683092] kworker/-12 20..... 48640667us : __engine_unpark: 0000:00:02.0 other0:

<0> [531.683243] kworker/-12 20..... 48640693us : __gt_unpark: 0000:00:02.0

<0> [531.683391] kworker/-12 20..... 48640789us : __engine_unpark: 0000:00:02.0 other0: context:f reset { seqno:1, *hwsp:1, ring:58 }

<7> [531.683424] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.683563] kworker/-12 20..... 48640829us : __i915_request_commit: 0000:00:02.0 other0: fence 10:20, current 19

<0> [531.683711] kworker/-12 20D..1. 48640845us : __i915_request_submit: 0000:00:02.0 other0: fence 10:20, current 19

<0> [531.683866] kworker/-12 20..... 48651448us : __engine_unpark: 0000:00:02.0 other0:

<0> [531.684015] kworker/-12 20..... 48651474us : __gt_unpark: 0000:00:02.0

<0> [531.684159] kworker/-12 20..... 48651587us : __engine_unpark: 0000:00:02.0 other0: context:f reset { seqno:1, *hwsp:1, ring:58 }

<0> [531.684331] kworker/-12 20.N... 48651624us : __i915_request_commit: 0000:00:02.0 other0: fence 10:21, current 20

<0> [531.684498] kworker/-12 20DN.1. 48651640us : __i915_request_submit: 0000:00:02.0 other0: fence 10:21, current 20

<0> [531.684666] kworker/-176 21..... 50744611us : i915_request_retire.part.0: 0000:00:02.0 vcs0: fence 1a:2, current 2

<0> [531.684834] kworker/-176 21..... 50745164us : i915_request_retire.part.0: 0000:00:02.0 vcs1: fence 1b:2, current 2

<0> [531.685002] kworker/-176 21..... 50745214us : i915_request_retire.part.0: 0000:00:02.0 vecs0: fence 1c:2, current 2

<0> [531.685169] kworker/-176 21..... 50745259us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 17:2, current 2

<0> [531.685335] kworker/-176 21..... 50746955us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 5:2, current 2

<7> [531.685336] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.685503] kworker/-176 21..... 50749060us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 18:2, current 2

<0> [531.685668] kworker/-176 21..... 50749270us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 19:2, current 2

<0> [531.685833] kworker/-176 21..... 81785890us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 31:2, current 2

<0> [531.685999] kworker/-176 21..... 81786756us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 5:5, current 5

<0> [531.686166] kworker/-176 21..... 81786774us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 6:6, current 7

<0> [531.686331] kworker/-176 21..... 81786779us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 6:7, current 7

<0> [531.686488] kworker/-176 21..... 81786790us : __engine_park: 0000:00:02.0 bcs0: parked

<0> [531.686650] kworker/-111 21..... 85753923us : __i915_request_commit: 0000:00:02.0 rcs0: fence 5:7, current 6

<0> [531.686816] kworker/-111 21D..1. 85753973us : __i915_request_submit: 0000:00:02.0 rcs0: fence 5:7, current 6

<0> [531.686982] kworker/-176 21..... 87670985us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 4c:4, current 4

<0> [531.687149] kworker/-177 20..... 90742731us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 4f:2, current 2

<0> [531.687316] kworker/-177 20..... 90743168us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 5:8, current 8

<7> [531.687306] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.687488] kworker/-177 20..... 90743208us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 6:8, current 9

<0> [531.687653] kworker/-177 20..... 90743215us : i915_request_retire.part.0: 0000:00:02.0 bcs0: fence 6:9, current 9

<0> [531.687807] kworker/-177 20..... 90743244us : __engine_park: 0000:00:02.0 bcs0: parked

<0> [531.687966] kworker/-176 21..... 187762834us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 1c3:2, current 2

<0> [531.688129] kworker/-176 21..... 187763507us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 5:21, current 21

<0> [531.688293] kworker/-111 21..... 202227595us : __i915_request_commit: 0000:00:02.0 rcs0: fence 5:22, current 21

<0> [531.688456] kworker/-111 21D..1. 202227623us : __i915_request_submit: 0000:00:02.0 rcs0: fence 5:22, current 21

<0> [531.688619] kworker/-111 21..... 227825927us : __i915_request_commit: 0000:00:02.0 rcs0: fence 5:23, current 22

<0> [531.688783] kworker/-111 21D..1. 227825949us : __i915_request_submit: 0000:00:02.0 rcs0: fence 5:23, current 22

<0> [531.688927] kworker/-448 20..... 253797877us : intel_rps_mark_interactive: 0000:00:02.0 mark interactive: no

<0> [531.689047] gem_exec-2386 20..... 292757238us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:11712, current 11696

<0> [531.689168] gem_exec-2386 20DN.1. 292757307us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:11712, current 11696

<0> [531.689292] gem_exec-2370 20..... 293242666us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:14084, current 14084

<7> [531.689225] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.689421] gem_exec-2394 20..... 293727162us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:16770, current 16760

<0> [531.689559] gem_exec-2394 20..... 293729044us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:16780, current 16770

<0> [531.689678] gem_exec-2384 20..... 293793075us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:94b pin ring:{start:f10c5000, head:0000, tail:0000}

<0> [531.689819] gem_exec-2384 20..... 293793308us : __i915_request_commit: 0000:00:02.0 vecs0: fence 94b:2, current 0

<0> [531.689950] gem_exec-2384 20D..1. 293793328us : __i915_request_submit: 0000:00:02.0 vecs0: fence 94b:2, current 0

<0> [531.690074] gem_exec-2381 20..... 294192974us : __i915_request_commit: 0000:00:02.0 bcs0: fence 9cd:2, current 0

<0> [531.690201] gem_exec-2381 20D..1. 294193026us : __i915_request_submit: 0000:00:02.0 bcs0: fence 9cd:2, current 0

<0> [531.690322] gem_exec-2381 20..... 294193648us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19516, current 19504

<0> [531.690443] gem_exec-2381 20..... 294193973us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19518, current 19504

<0> [531.690564] gem_exec-2381 20..... 294196890us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19540, current 19530

<0> [531.690684] gem_exec-2381 20D..1. 294196917us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:19540, current 19530

<0> [531.690804] gem_exec-2376 20..... 294213989us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:19702, current 19702

<0> [531.690925] gem_exec-2376 20..... 294214354us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19718, current 19702

<0> [531.691046] gem_exec-2376 20D..1. 294214419us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:19718, current 19702

<0> [531.691166] gem_exec-2376 20..... 294215513us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:19726, current 19720

<0> [531.691286] gem_exec-2376 20D..1. 294215535us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:19726, current 19720

<7> [531.691226] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.691408] gem_exec-2387 20.N... 295030492us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:25188, current 25188

<0> [531.691530] gem_exec-2405 20..... 295036117us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:b08 active

<0> [531.691653] gem_exec-2392 20..... 295864074us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:33072, current 33048

<0> [531.691779] gem_exec-2392 20..... 295864096us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33048, current 33048

<0> [531.691905] gem_exec-2392 20..... 295864779us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33052, current 33055

<0> [531.692026] gem_exec-2392 20..... 295864841us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:33084, current 33058

<0> [531.692147] gem_exec-2392 20..... 295864858us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33054, current 33059

<0> [531.692267] gem_exec-2392 20..... 295864883us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33056, current 33060

<0> [531.692389] gem_exec-2392 20..... 295864902us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33058, current 33061

<0> [531.692510] gem_exec-2392 20..... 295864923us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33060, current 33062

<0> [531.692631] gem_exec-2392 20..... 295864942us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33062, current 33062

<0> [531.692755] gem_exec-2392 20..... 295867274us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33100, current 33100

<0> [531.692891] gem_exec-2392 20..... 295867401us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:33120, current 33102

<0> [531.693020] gem_exec-2392 20..... 295867429us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:33102, current 33102

<0> [531.693145] gem_exec-2365 20..... 296107653us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:36710, current 36686

<0> [531.693271] gem_exec-2365 20..... 296107679us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36686, current 36688

<0> [531.693407] gem_exec-2365 20..... 296107696us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36688, current 36689

<7> [531.693452] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.693535] gem_exec-2365 20..... 296107709us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36690, current 36690

<0> [531.693647] gem_exec-2365 20..... 296108075us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36692, current 36702

<0> [531.693785] gem_exec-2365 20..... 296108099us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36694, current 36702

<0> [531.693923] gem_exec-2365 20..... 296108117us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36696, current 36702

<0> [531.694044] gem_exec-2365 20..... 296108137us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36698, current 36702

<0> [531.694165] gem_exec-2365 20..... 296108155us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36700, current 36702

<0> [531.694286] gem_exec-2365 20..... 296108174us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:36702, current 36702

<0> [531.694407] gem_exec-2379 20..... 296219257us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:38510, current 38496

<0> [531.694528] gem_exec-2379 20D..1. 296219283us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:38510, current 38496

<0> [531.694649] gem_exec-2379 20..... 296219301us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:38498, current 38498

kworker/-1076 0..... 296334980us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:514 unpin

<0> [531.694882] kworker/-1076 0..... 296335050us : __intel_context_retire: 0000:00:02.0 ccs0: context:514 retire runtime: { total:387059ns, avg:65879ns }

<0> [531.695007] gem_exec-2373 0..... 296335135us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40258, current 40194

<0> [531.695128] gem_exec-2373 0..... 296335209us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40264, current 40196

<0> [531.695252] gem_exec-2373 0..... 296339021us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40282, current 40272

<0> [531.695390] gem_exec-2373 0D..1. 296339026us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:40282, current 40272

<0> [531.695526] gem_exec-2373 0..... 296339033us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40272, current 40272

<0> [531.695646] gem_exec-2373 0..... 296339246us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:aaa active

<7> [531.695627] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.695768] gem_exec-2373 0..... 296339251us : intel_timeline_pin: 0000:00:02.0 timeline:aaa using HWSP offset:edf34000

<0> [531.695866] gem_exec-2373 0..... 296339262us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:aaa pin ring:{start:edfa6000, head:0168, tail:0168}

<0> [531.695992] gem_exec-2373 0..... 296339321us : __i915_request_commit: 0000:00:02.0 ccs0: fence aaa:4, current 2

<0> [531.696117] gem_exec-2373 0D..1. 296339574us : __i915_request_submit: 0000:00:02.0 ccs0: fence aaa:4, current 2

<0> [531.696237] gem_exec-2373 0..... 296339797us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40302, current 40274

<0> [531.696359] gem_exec-2373 0..... 296339988us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40320, current 40278

<0> [531.696481] gem_exec-2373 0..... 296343476us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40362, current 40320

<0> [531.696594] gem_exec-2373 0..... 296343540us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:372 active

<0> [531.696712] gem_exec-2373 0..... 296343542us : intel_timeline_pin: 0000:00:02.0 timeline:372 using HWSP offset:fd0ea000

<0> [531.696824] gem_exec-2373 0..... 296343549us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:372 pin ring:{start:fd1d4000, head:02d0, tail:02d0}

<0> [531.696949] gem_exec-2373 0..... 296343583us : __i915_request_commit: 0000:00:02.0 ccs0: fence 372:6, current 4

<0> [531.697070] gem_exec-2373 0D..1. 296343944us : __i915_request_submit: 0000:00:02.0 ccs0: fence 372:6, current 4

<0> [531.697191] gem_exec-2373 0..... 296344027us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40368, current 40320

<0> [531.697312] gem_exec-2373 0..... 296344131us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40376, current 40320

<0> [531.697433] gem_exec-2373 0..... 296347984us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40428, current 40380

<0> [531.697559] gem_exec-2373 0..... 296347989us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40380, current 40380

<7> [531.697538] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.697679] gem_exec-2373 0..... 296348050us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a1b active

<0> [531.697784] gem_exec-2373 0..... 296348053us : intel_timeline_pin: 0000:00:02.0 timeline:a1b using HWSP offset:ef227000

<0> [531.697900] gem_exec-2373 0..... 296348059us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a1b pin ring:{start:ef305000, head:05a0, tail:05a0}

<0> [531.698031] gem_exec-2373 0..... 296348098us : __i915_request_commit: 0000:00:02.0 ccs0: fence a1b:10, current 8

<0> [531.698155] gem_exec-2373 0D..1. 296348216us : __i915_request_submit: 0000:00:02.0 ccs0: fence a1b:10, current 8

<0> [531.698280] gem_exec-2373 0..... 296348308us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40440, current 40394

<0> [531.698404] gem_exec-2373 0..... 296348409us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40450, current 40394

<0> [531.698526] gem_exec-2381 0..... 296353491us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40496, current 40486

<0> [531.698647] gem_exec-2381 0..... 296353871us : __i915_request_commit: 0000:00:02.0 bcs0: fence bc3:6, current 4

<0> [531.698769] gem_exec-2381 0D..1. 296353877us : __i915_request_submit: 0000:00:02.0 bcs0: fence bc3:6, current 4

<0> [531.698892] gem_exec-2381 0..... 296354316us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40528, current 40488

<0> [531.699013] gem_exec-2381 0..... 296354937us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40558, current 40503

<0> [531.699133] gem_exec-2363 0..... 296356920us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40544, current 40545

<0> [531.699247] gem_exec-2401 0..... 296366347us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c79 pin ring:{start:ea305000, head:0000, tail:0000}

<0> [531.699373] gem_exec-2401 0..... 296366395us : __i915_request_commit: 0000:00:02.0 vcs1: fence c79:2, current 0

<0> [531.699493] gem_exec-2401 0D..1. 296366399us : __i915_request_submit: 0000:00:02.0 vcs1: fence c79:2, current 0

<0> [531.699613] gem_exec-2401 0..... 296368728us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40732, current 40724

<7> [531.699636] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.699734] gem_exec-2401 0D..1. 296368734us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:40732, current 40724

<0> [531.699837] gem_exec-2401 0..... 296369949us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40758, current 40736

<0> [531.699958] gem_exec-2401 0D..1. 296369955us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:40758, current 40736

<0> [531.700078] gem_exec-2401 0..... 296371169us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40816, current 40760

<0> [531.700191] gem_exec-2401 0..... 296371250us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c4c active

<0> [531.700307] gem_exec-2401 0..... 296371253us : intel_timeline_pin: 0000:00:02.0 timeline:c4c using HWSP offset:ea8de000

<0> [531.700420] gem_exec-2401 0..... 296371260us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c4c pin ring:{start:ea8df000, head:00b0, tail:00b0}

<0> [531.700548] gem_exec-2401 0..... 296371293us : __i915_request_commit: 0000:00:02.0 vcs1: fence c4c:4, current 2

<0> [531.700671] gem_exec-2401 0D..1. 296371297us : __i915_request_submit: 0000:00:02.0 vcs1: fence c4c:4, current 2

<0> [531.700795] gem_exec-2401 0..... 296371379us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40824, current 40764

<0> [531.700918] gem_exec-2401 0..... 296371383us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40764, current 40764

<0> [531.701040] gem_exec-2401 0..... 296371436us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40828, current 40768

<0> [531.701166] gem_exec-2401 0..... 296371440us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40768, current 40768

<0> [531.701285] gem_exec-2378 0..... 296372782us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:c7b pin ring:{start:ea2d5000, head:0000, tail:0000}

<0> [531.701413] gem_exec-2378 0..... 296372937us : __i915_request_commit: 0000:00:02.0 vecs0: fence c7b:2, current 0

<0> [531.701538] gem_exec-2378 0D..1. 296372942us : __i915_request_submit: 0000:00:02.0 vecs0: fence c7b:2, current 0

<0> [531.701668] gem_exec-2378 0..... 296375277us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40848, current 40804

<0> [531.701793] gem_exec-2378 0..... 296375281us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40804, current 40804

<0> [531.701916] gem_exec-2378 0..... 296375414us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40810, current 40810

<0> [531.702039] gem_exec-2378 0..... 296375459us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40858, current 40812

<0> [531.702161] gem_exec-2378 0..... 296375465us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:40812, current 40812

<7> [531.702093] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.702281] gem_exec-2399 0..... 296376857us : intel_timeline_pin: 0000:00:02.0 timeline:c82 using HWSP offset:ea12e000

<0> [531.702394] gem_exec-2399 0..... 296377485us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:c82 pin ring:{start:ea217000, head:0000, tail:0000}

<0> [531.702533] gem_exec-2399 0..... 296377908us : __i915_request_commit: 0000:00:02.0 bcs0: fence c82:2, current 0

<0> [531.702654] gem_exec-2399 0D..1. 296377913us : __i915_request_submit: 0000:00:02.0 bcs0: fence c82:2, current 0

<0> [531.702774] gem_exec-2399 0..... 296378083us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40910, current 40862

<0> [531.702894] gem_exec-2399 0..... 296378298us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40930, current 40862

<0> [531.703015] gem_exec-2399 0..... 296381311us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:40982, current 40932

<0> [531.703129] kworker/-157 0..... 296382697us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:a1f unpin

<0> [531.703241] kworker/-157 0..... 296382792us : __intel_context_retire: 0000:00:02.0 ccs0: context:a1f retire runtime: { total:892679ns, avg:129002ns }

<0> [531.703355] kworker/-157 0..... 296384449us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:9cb unpin

<0> [531.703467] kworker/-157 0..... 296384552us : __intel_context_retire: 0000:00:02.0 vcs0: context:9cb retire runtime: { total:107643ns, avg:42082ns }

<0> [531.703583] kworker/-157 0..... 296384559us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:664 unpin

<0> [531.703692] kworker/-157 0..... 296384641us : __intel_context_retire: 0000:00:02.0 vcs1: context:664 retire runtime: { total:90259ns, avg:39167ns }

<0> [531.703805] gem_exec-2370 0..... 296387250us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:c90 active

<0> [531.703927] gem_exec-2393 0..... 296388053us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41068, current 41034

<0> [531.704050] gem_exec-2393 0..... 296388058us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41034, current 41034

<0> [531.704161] kworker/-1076 0..... 296388548us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:7d6 unpin

<7> [531.704201] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.704271] kworker/-1076 0.N... 296388638us : __intel_context_retire: 0000:00:02.0 vcs0: context:7d6 retire runtime: { total:153170ns, avg:30422ns }

<0> [531.704367] kworker/-148 0..... 296390050us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:5c8 unpin

<0> [531.704486] kworker/-148 0..... 296390135us : __intel_context_retire: 0000:00:02.0 rcs0: context:5c8 retire runtime: { total:601285ns, avg:101760ns }

<0> [531.704603] kworker/-148 0..... 296390145us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:bc3 unpin

<0> [531.704714] kworker/-148 0..... 296390230us : __intel_context_retire: 0000:00:02.0 bcs0: context:bc3 retire runtime: { total:57452ns, avg:25493ns }

<0> [531.704841] gem_exec-2371 0..... 296392328us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41122, current 41116

<0> [531.704963] gem_exec-2371 0D..1. 296392333us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:41122, current 41116

<0> [531.705085] gem_exec-2394 20.N... 296394243us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41122, current 41128

<0> [531.705208] gem_exec-2394 20.N... 296394271us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41124, current 41128

<0> [531.705321] gem_exec-2371 0..... 296395330us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:b69 active

<0> [531.705439] gem_exec-2371 0..... 296395335us : intel_timeline_pin: 0000:00:02.0 timeline:b69 using HWSP offset:ec641000

<0> [531.705554] gem_exec-2394 0..... 296395846us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:3a5 active

<0> [531.705679] gem_exec-2394 0..... 296395851us : intel_timeline_pin: 0000:00:02.0 timeline:3a5 using HWSP offset:fca4f000

<0> [531.705793] gem_exec-2394 0..... 296395861us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:3a5 pin ring:{start:fcba0000, head:0160, tail:0160}

<0> [531.705920] gem_exec-2394 0..... 296395897us : __i915_request_commit: 0000:00:02.0 vcs0: fence 3a5:6, current 4

<0> [531.706045] gem_exec-2394 0D..1. 296395901us : __i915_request_submit: 0000:00:02.0 vcs0: fence 3a5:6, current 4

<0> [531.706168] gem_exec-2394 0..... 296395962us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41184, current 41132

<0> [531.706289] gem_exec-2394 0..... 296396053us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41192, current 41132

<0> [531.706413] gem_exec-2394 0..... 296400059us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41244, current 41204

<0> [531.706530] gem_exec-2394 0..... 296400242us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:a4e active

<7> [531.706463] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.706651] gem_exec-2394 0..... 296400244us : intel_timeline_pin: 0000:00:02.0 timeline:a4e using HWSP offset:eebea000

<0> [531.706766] gem_exec-2394 0..... 296400251us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:a4e pin ring:{start:eec7a000, head:02c0, tail:02c0}

<0> [531.706894] gem_exec-2394 0..... 296400286us : __i915_request_commit: 0000:00:02.0 vcs0: fence a4e:10, current 8

<0> [531.707015] gem_exec-2394 0D..1. 296400290us : __i915_request_submit: 0000:00:02.0 vcs0: fence a4e:10, current 8

<0> [531.707136] gem_exec-2394 0..... 296400404us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41270, current 41204

<0> [531.707257] gem_exec-2394 0..... 296404809us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41206, current 41250

<0> [531.707382] gem_exec-2394 0..... 296404820us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41282, current 41250

<0> [531.707507] gem_exec-2394 0D..1. 296404824us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:41282, current 41250

<0> [531.707628] gem_exec-2394 0..... 296404829us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41208, current 41251

<0> [531.707750] gem_exec-2394 0..... 296404834us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41210, current 41251

<0> [531.707871] gem_exec-2394 0..... 296404837us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41212, current 41251

<0> [531.707992] gem_exec-2394 0..... 296404844us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41214, current 41252

<0> [531.708112] gem_exec-2394 0..... 296404848us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41216, current 41252

<0> [531.708233] gem_exec-2394 0..... 296404853us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41218, current 41252

<0> [531.708353] gem_exec-2394 0..... 296404857us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41220, current 41252

<0> [531.708475] gem_exec-2394 0..... 296404861us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41222, current 41252

<0> [531.708601] gem_exec-2394 0..... 296404862us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41224, current 41252

<7> [531.708600] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.708721] gem_exec-2394 0..... 296404864us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41226, current 41252

<0> [531.708824] gem_exec-2394 0..... 296404868us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41228, current 41253

<0> [531.708943] gem_exec-2394 0..... 296404871us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41230, current 41253

<0> [531.709063] gem_exec-2394 0..... 296404872us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41232, current 41253

<0> [531.709183] gem_exec-2394 0..... 296404873us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41234, current 41253

<0> [531.709302] gem_exec-2394 0..... 296404877us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41236, current 41253

<0> [531.709423] gem_exec-2394 0..... 296404878us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41238, current 41253

<0> [531.709544] gem_exec-2394 0..... 296404879us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41240, current 41253

<0> [531.709663] gem_exec-2394 0..... 296404883us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41242, current 41254

<0> [531.709784] gem_exec-2394 0..... 296404888us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41244, current 41254

<0> [531.709905] gem_exec-2394 0..... 296404891us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41246, current 41254

<0> [531.710025] gem_exec-2394 0..... 296404892us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41248, current 41254

<0> [531.710145] gem_exec-2394 0..... 296404893us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41250, current 41254

<0> [531.710265] gem_exec-2394 0..... 296404894us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41252, current 41254

<0> [531.710386] gem_exec-2394 0..... 296404898us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41254, current 41254

<0> [531.710514] gem_exec-2401 0..... 296406268us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41312, current 41288

<0> [531.710635] gem_exec-2401 0D..1. 296406273us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:41312, current 41289

<0> [531.710750] kworker/-157 0..... 296409807us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:3d8 unpin

<0> [531.710864] kworker/-157 0..... 296409877us : __intel_context_retire: 0000:00:02.0 vcs1: context:3d8 retire runtime: { total:58459ns, avg:19663ns }

<7> [531.710860] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:508

<0> [531.710979] kworker/-157 0..... 296409890us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:c4c unpin

<0> [531.711073] kworker/-157 0..... 296409959us : __intel_context_retire: 0000:00:02.0 vcs1: context:c4c retire runtime: { total:41340ns, avg:21677ns }

<0> [531.711188] kworker/-157 0..... 296409975us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:4d3 unpin

<0> [531.711298] kworker/-157 0..... 296410045us : __intel_context_retire: 0000:00:02.0 vcs1: context:4d3 retire runtime: { total:55809ns, avg:18338ns }

<0> [531.711414] kworker/-157 0..... 296410946us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:7b9 unpin

<0> [531.711526] kworker/-157 0..... 296411014us : __intel_context_retire: 0000:00:02.0 vcs0: context:7b9 retire runtime: { total:100170ns, avg:31217ns }

<0> [531.711638] kworker/-157 0..... 296411144us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:629 unpin

<0> [531.711747] kworker/-157 0..... 296411213us : __intel_context_retire: 0000:00:02.0 vecs0: context:629 retire runtime: { total:94287ns, avg:22366ns }

<0> [531.711859] kworker/-157 0..... 296412520us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:3bf unpin

<0> [531.711970] kworker/-157 0..... 296412585us : __intel_context_retire: 0000:00:02.0 vcs1: context:3bf retire runtime: { total:143789ns, avg:40863ns }

<0> [531.712086] kworker/-157 0..... 296415447us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:c46 unpin

<0> [531.712194] kworker/-157 0..... 296415709us : __intel_context_retire: 0000:00:02.0 rcs0: context:c46 retire runtime: { total:713539ns, avg:713539ns }

<0> [531.712306] kworker/-157 0..... 296415734us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:8f8 unpin

<0> [531.712417] kworker/-157 0..... 296415818us : __intel_context_retire: 0000:00:02.0 ccs0: context:8f8 retire runtime: { total:187196ns, avg:63759ns }

<0> [531.712535] kworker/-157 0..... 296415823us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:b7b unpin

<0> [531.712645] kworker/-157 0..... 296415893us : __intel_context_retire: 0000:00:02.0 ccs0: context:b7b retire runtime: { total:205163ns, avg:106371ns }

<0> [531.712756] kworker/-157 0..... 296415900us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:c7d unpin

<0> [531.712865] kworker/-157 0..... 296415971us : __intel_context_retire: 0000:00:02.0 ccs0: context:c7d retire runtime: { total:51357ns, avg:51357ns }

<0> [531.712977] kworker/-157 0..... 296415977us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:c82 unpin

<0> [531.713085] kworker/-157 0..... 296416047us : __intel_context_retire: 0000:00:02.0 bcs0: context:c82 retire runtime: { total:16483ns, avg:16483ns }

<0> [531.713212] gem_exec-2374 0..... 296437853us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41850, current 41810

<0> [531.713336] gem_exec-2374 0..... 296437858us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41810, current 41810

<0> [531.713471] gem_exec-2374 0..... 296442037us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41898, current 41870

<0> [531.713593] gem_exec-2374 0..... 296442067us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41870, current 41871

<0> [531.713707] gem_exec-2374 0..... 296442173us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:2ec active

<0> [531.713831] gem_exec-2374 0..... 296442177us : intel_timeline_pin: 0000:00:02.0 timeline:2ec using HWSP offset:fe274000

<0> [531.713943] gem_exec-2374 0..... 296442186us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:2ec pin ring:{start:fe42e000, head:02d0, tail:02d0}

<0> [531.714070] gem_exec-2374 0..... 296442225us : __i915_request_commit: 0000:00:02.0 rcs0: fence 2ec:6, current 4

<0> [531.714193] gem_exec-2374 0D..1. 296442229us : __i915_request_submit: 0000:00:02.0 rcs0: fence 2ec:6, current 4

<0> [531.714314] gem_exec-2374 0..... 296442635us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41926, current 41884

<0> [531.714436] gem_exec-2374 0..... 296442812us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41940, current 41884

<0> [531.714552] kworker/-157 0..... 296443736us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:8a8 unpin

<0> [531.714663] kworker/-157 0..... 296443873us : __intel_context_retire: 0000:00:02.0 ccs0: context:8a8 retire runtime: { total:131440ns, avg:70490ns }

<0> [531.714777] kworker/-157 0..... 296443879us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:c53 unpin

<0> [531.714887] kworker/-157 0..... 296444004us : __intel_context_retire: 0000:00:02.0 ccs0: context:c53 retire runtime: { total:261184ns, avg:261184ns }

<0> [531.714999] kworker/-157 0..... 296444010us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:3fc unpin

<0> [531.715108] kworker/-157 0..... 296444135us : __intel_context_retire: 0000:00:02.0 bcs0: context:3fc retire runtime: { total:54908ns, avg:21359ns }

<0> [531.715220] kworker/-157 0..... 296444143us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:5d8 unpin

<0> [531.715329] kworker/-157 0..... 296444270us : __intel_context_retire: 0000:00:02.0 rcs0: context:5d8 retire runtime: { total:466029ns, avg:82892ns }

<0> [531.715450] kworker/-157 0..... 296444280us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:3c2 unpin

<0> [531.715561] kworker/-157 0..... 296444408us : __intel_context_retire: 0000:00:02.0 bcs0: context:3c2 retire runtime: { total:58618ns, avg:21306ns }

<0> [531.715672] kworker/-157 0..... 296444416us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:391 unpin

<0> [531.715780] kworker/-157 0..... 296444555us : __intel_context_retire: 0000:00:02.0 bcs0: context:391 retire runtime: { total:123278ns, avg:23267ns }

<0> [531.715892] kworker/-157 0..... 296444563us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:aa5 unpin

<0> [531.716000] kworker/-157 0..... 296444691us : __intel_context_retire: 0000:00:02.0 ccs0: context:aa5 retire runtime: { total:224614ns, avg:81779ns }

<0> [531.716126] gem_exec-2374 0..... 296446954us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:41974, current 41950

<0> [531.716249] gem_exec-2374 0D..1. 296446959us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:41974, current 41950

<0> [531.716374] gem_exec-2374 0..... 296446965us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:41950, current 41950

<0> [531.716494] kworker/-2406 0..... 296447027us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:637 unpin

<0> [531.716605] kworker/-2406 0.N... 296447157us : __intel_context_retire: 0000:00:02.0 ccs0: context:637 retire runtime: { total:227052ns, avg:68529ns }

<0> [531.716719] gem_exec-2370 0..... 296447282us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:c90 pin ring:{start:ea061000, head:0000, tail:0000}

<0> [531.716847] gem_exec-2370 0..... 296447339us : __i915_request_commit: 0000:00:02.0 vcs0: fence c90:2, current 0

<0> [531.716972] gem_exec-2370 0D..1. 296447343us : __i915_request_submit: 0000:00:02.0 vcs0: fence c90:2, current 0

<0> [531.717096] gem_exec-2370 0..... 296447773us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42016, current 41954

<0> [531.717219] gem_exec-2380 0..... 296450056us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42036, current 41990

<0> [531.717332] gem_exec-2380 0..... 296450333us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:4b3 active

<0> [531.717466] gem_exec-2380 0..... 296450336us : intel_timeline_pin: 0000:00:02.0 timeline:4b3 using HWSP offset:fa77c000

<0> [531.717580] gem_exec-2380 0..... 296450346us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:4b3 pin ring:{start:fa813000, head:02d0, tail:02d0}

<0> [531.717708] gem_exec-2380 0..... 296450383us : __i915_request_commit: 0000:00:02.0 rcs0: fence 4b3:6, current 4

<0> [531.717831] gem_exec-2380 0D..1. 296450531us : __i915_request_submit: 0000:00:02.0 rcs0: fence 4b3:6, current 4

<0> [531.717953] gem_exec-2380 0..... 296450686us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42062, current 41990

<0> [531.718076] gem_exec-2380 0..... 296454011us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42082, current 42065

<0> [531.718199] gem_exec-2380 0D..1. 296454017us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42082, current 42066

<0> [531.718322] gem_exec-2380 0..... 296454023us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42066, current 42066

<0> [531.718455] gem_exec-2380 0..... 296455809us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42126, current 42088

<0> [531.718572] gem_exec-2380 0..... 296456030us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:3b7 active

<0> [531.718691] gem_exec-2380 0..... 296456033us : intel_timeline_pin: 0000:00:02.0 timeline:3b7 using HWSP offset:fc8ec000

<0> [531.718803] gem_exec-2380 0..... 296456041us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:3b7 pin ring:{start:fc9d6000, head:05a0, tail:05a0}

<0> [531.718930] gem_exec-2380 0..... 296456085us : __i915_request_commit: 0000:00:02.0 rcs0: fence 3b7:10, current 8

<0> [531.719052] gem_exec-2380 0Dn.1. 296456441us : __i915_request_submit: 0000:00:02.0 rcs0: fence 3b7:10, current 8

<0> [531.719166] gem_exec-2372 0..... 296458100us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:ca2 active

<0> [531.719289] gem_exec-2374 0.N... 296464033us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42278, current 42246

<0> [531.719403] gem_exec-2374 0..... 296464275us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:961 active

<0> [531.719522] gem_exec-2374 0..... 296464278us : intel_timeline_pin: 0000:00:02.0 timeline:961 using HWSP offset:f0be4000

<0> [531.719634] gem_exec-2374 0..... 296464287us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:961 pin ring:{start:f0c58000, head:05a0, tail:05a0}

<0> [531.719763] gem_exec-2374 0..... 296464334us : __i915_request_commit: 0000:00:02.0 rcs0: fence 961:10, current 8

<0> [531.719886] gem_exec-2374 0D..1. 296464533us : __i915_request_submit: 0000:00:02.0 rcs0: fence 961:10, current 8

<0> [531.720009] gem_exec-2374 0..... 296466604us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42326, current 42288

<0> [531.720131] gem_exec-2374 0..... 296466624us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42282, current 42289

<0> [531.720254] gem_exec-2374 0..... 296466637us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42284, current 42290

<0> [531.720379] gem_exec-2374 0..... 296466647us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42286, current 42290

<0> [531.720505] gem_exec-2374 0..... 296466656us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42288, current 42291

<0> [531.720627] gem_exec-2374 0..... 296466658us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42290, current 42291

<0> [531.720743] gem_exec-2386 0..... 296466980us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:b9b active

<0> [531.720866] gem_exec-2386 0..... 296466983us : intel_timeline_pin: 0000:00:02.0 timeline:b9b using HWSP offset:ec02c000

<0> [531.720978] gem_exec-2386 0..... 296466991us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:b9b pin ring:{start:ec19f000, head:0168, tail:0168}

<0> [531.721104] gem_exec-2386 0..... 296467032us : __i915_request_commit: 0000:00:02.0 rcs0: fence b9b:4, current 2

<0> [531.721226] gem_exec-2386 0D..1. 296467243us : __i915_request_submit: 0000:00:02.0 rcs0: fence b9b:4, current 2

<0> [531.721349] gem_exec-2377 0.N... 296470294us : intel_timeline_pin: 0000:00:02.0 timeline:c9e using HWSP offset:e9e66000

<0> [531.721476] gem_exec-2395 0..... 296479022us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42504, current 42472

<0> [531.721590] gem_exec-2395 0..... 296479580us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:7dd active

<0> [531.721712] gem_exec-2395 0..... 296479584us : intel_timeline_pin: 0000:00:02.0 timeline:7dd using HWSP offset:f3f3f000

<0> [531.721828] gem_exec-2395 0..... 296479592us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:7dd pin ring:{start:f3f7a000, head:00b0, tail:00b0}

<0> [531.721956] gem_exec-2395 0..... 296479639us : __i915_request_commit: 0000:00:02.0 vcs1: fence 7dd:4, current 2

<0> [531.722082] gem_exec-2395 0D..1. 296479644us : __i915_request_submit: 0000:00:02.0 vcs1: fence 7dd:4, current 2

<0> [531.722205] gem_exec-2395 0..... 296479839us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42544, current 42476

<0> [531.722327] gem_exec-2395 0..... 296483966us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42568, current 42528

<0> [531.722458] gem_exec-2395 0D..1. 296483971us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42568, current 42528

<0> [531.722585] gem_exec-2403 0..... 296484659us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42580, current 42548

<0> [531.722707] gem_exec-2403 0D..1. 296484664us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42580, current 42548

<0> [531.722822] gem_exec-2403 0..... 296485977us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a33 active

<0> [531.722941] gem_exec-2403 0..... 296485982us : intel_timeline_pin: 0000:00:02.0 timeline:a33 using HWSP offset:ef0d4000

<0> [531.723055] gem_exec-2403 0..... 296485991us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a33 pin ring:{start:ef0d5000, head:02d0, tail:02d0}

<0> [531.723184] gem_exec-2403 0..... 296486046us : __i915_request_commit: 0000:00:02.0 ccs0: fence a33:6, current 4

<0> [531.723305] gem_exec-2403 0D..1. 296486053us : __i915_request_submit: 0000:00:02.0 ccs0: fence a33:6, current 4

<0> [531.723425] gem_exec-2400 0..... 296486223us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:c9a pin ring:{start:e9eba000, head:0000, tail:0000}

<0> [531.723554] gem_exec-2400 0..... 296486295us : __i915_request_commit: 0000:00:02.0 vcs0: fence c9a:2, current 0

<0> [531.723684] gem_exec-2400 0D..1. 296486299us : __i915_request_submit: 0000:00:02.0 vcs0: fence c9a:2, current 0

<0> [531.723795] gem_exec-2377 0..... 296489042us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e pin ring:{start:e9e67000, head:0000, tail:0000}

<0> [531.723913] gem_exec-2377 0..... 296489056us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:c9e unpin

<0> [531.724024] gem_exec-2377 0..... 296489183us : __intel_context_retire: 0000:00:02.0 vcs1: context:c9e retire runtime: { total:0ns, avg:0ns }

<0> [531.724136] gem_exec-2377 0..... 296489186us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e active

<0> [531.724253] gem_exec-2377 0..... 296489187us : intel_timeline_pin: 0000:00:02.0 timeline:c9e using HWSP offset:e9e66000

<0> [531.724369] gem_exec-2377 0..... 296489190us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e pin ring:{start:e9e67000, head:0000, tail:0000}

<0> [531.724490] gem_exec-2377 0..... 296489198us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:c9e unpin

<0> [531.724605] gem_exec-2377 0..... 296489323us : __intel_context_retire: 0000:00:02.0 vcs1: context:c9e retire runtime: { total:0ns, avg:0ns }

<0> [531.724721] gem_exec-2377 0..... 296489326us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e active

<0> [531.724838] gem_exec-2377 0..... 296489327us : intel_timeline_pin: 0000:00:02.0 timeline:c9e using HWSP offset:e9e66000

<0> [531.724948] gem_exec-2377 0..... 296489330us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:c9e pin ring:{start:e9e67000, head:0000, tail:0000}

<0> [531.725076] gem_exec-2377 0..... 296489377us : __i915_request_commit: 0000:00:02.0 vcs1: fence c9e:2, current 0

<0> [531.725199] gem_exec-2377 0D..1. 296489381us : __i915_request_submit: 0000:00:02.0 vcs1: fence c9e:2, current 0

<0> [531.725324] gem_exec-2395 0..... 296490984us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42630, current 42630

<0> [531.725455] gem_exec-2377 0..... 296491756us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42688, current 42656

<0> [531.725589] gem_exec-2377 0..... 296492472us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42728, current 42680

<0> [531.725723] gem_exec-2364 0..... 296497066us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42786, current 42722

<0> [531.725841] gem_exec-2364 0..... 296497174us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b05 active

<0> [531.725959] gem_exec-2364 0..... 296497177us : intel_timeline_pin: 0000:00:02.0 timeline:b05 using HWSP offset:ed306000

<0> [531.726071] gem_exec-2364 0..... 296497186us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b05 pin ring:{start:ed409000, head:0160, tail:0160}

<0> [531.726199] gem_exec-2364 0..... 296497220us : __i915_request_commit: 0000:00:02.0 vcs0: fence b05:6, current 4

<0> [531.726325] gem_exec-2364 0D..1. 296497224us : __i915_request_submit: 0000:00:02.0 vcs0: fence b05:6, current 4

<0> [531.726458] gem_exec-2377 0..... 296500175us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42798, current 42764

<0> [531.726582] gem_exec-2377 0D..1. 296500181us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42798, current 42764

<0> [531.726706] gem_exec-2367 0..... 296501482us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42842, current 42816

<0> [531.726831] gem_exec-2367 0..... 296501486us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42816, current 42816

<0> [531.726950] gem_exec-2397 0..... 296502344us : intel_timeline_pin: 0000:00:02.0 timeline:ca3 using HWSP offset:e9c7f000

<0> [531.727071] gem_exec-2367 0..... 296507140us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42916, current 42896

<0> [531.727202] gem_exec-2367 0D..1. 296507147us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:42916, current 42896

<0> [531.727324] gem_exec-2367 0..... 296507522us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42896, current 42904

<0> [531.727454] gem_exec-2367 0..... 296507524us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42898, current 42904

<0> [531.727580] gem_exec-2367 0..... 296507527us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42900, current 42904

<0> [531.727706] gem_exec-2367 0..... 296507530us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42902, current 42904

<0> [531.727830] gem_exec-2367 0..... 296507533us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:42904, current 42904

<0> [531.727955] gem_exec-2403 0..... 296508877us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:42982, current 42930

<0> [531.728071] gem_exec-2403 0..... 296509052us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a74 active

<0> [531.728188] gem_exec-2403 0..... 296509055us : intel_timeline_pin: 0000:00:02.0 timeline:a74 using HWSP offset:ee6a1000

<0> [531.728302] gem_exec-2403 0..... 296509062us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:a74 pin ring:{start:ee808000, head:05a0, tail:05a0}

<0> [531.728433] gem_exec-2403 0..... 296509102us : __i915_request_commit: 0000:00:02.0 ccs0: fence a74:10, current 8

<0> [531.728561] gem_exec-2403 0D..1. 296509108us : __i915_request_submit: 0000:00:02.0 ccs0: fence a74:10, current 8

<0> [531.728687] gem_exec-2403 0..... 296513942us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43032, current 43025

<0> [531.728812] gem_exec-2403 0D..1. 296513948us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43032, current 43025

<0> [531.728935] gem_exec-2403 0..... 296513955us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43026, current 43026

<0> [531.729057] gem_exec-2403 0..... 296515476us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43068, current 43050

<0> [531.729180] gem_exec-2403 0D..1. 296515483us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43068, current 43050

<0> [531.729294] kworker/-148 0..... 296515729us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:4e2 unpin

<0> [531.729417] kworker/-148 0..... 296515801us : __intel_context_retire: 0000:00:02.0 bcs0: context:4e2 retire runtime: { total:84800ns, avg:20511ns }

<0> [531.729557] gem_exec-2388 0..... 296516066us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43102, current 43058

<0> [531.729683] gem_exec-2388 0..... 296516070us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43058, current 43058

<0> [531.729807] gem_exec-2388 0..... 296516392us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43126, current 43074

<0> [531.729919] gem_exec-2375 0..... 296516547us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 active

<0> [531.730036] gem_exec-2375 0..... 296516550us : intel_timeline_pin: 0000:00:02.0 timeline:8c4 using HWSP offset:f2144000

<0> [531.730149] gem_exec-2375 0..... 296516557us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 pin ring:{start:f2145000, head:0160, tail:0160}

<0> [531.730264] gem_exec-2375 0..... 296516571us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:8c4 unpin

<0> [531.730379] gem_exec-2375 0..... 296516640us : __intel_context_retire: 0000:00:02.0 bcs0: context:8c4 retire runtime: { total:36146ns, avg:16218ns }

<0> [531.730497] gem_exec-2375 0..... 296516644us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 active

<0> [531.730613] gem_exec-2375 0..... 296516646us : intel_timeline_pin: 0000:00:02.0 timeline:8c4 using HWSP offset:f2144000

<0> [531.730725] gem_exec-2375 0..... 296516649us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 pin ring:{start:f2145000, head:0160, tail:0160}

<0> [531.730840] gem_exec-2375 0..... 296516661us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:8c4 unpin

<0> [531.730950] gem_exec-2375 0..... 296516731us : __intel_context_retire: 0000:00:02.0 bcs0: context:8c4 retire runtime: { total:36146ns, avg:16218ns }

<0> [531.731062] gem_exec-2375 0..... 296516734us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 active

<0> [531.731179] gem_exec-2375 0..... 296516735us : intel_timeline_pin: 0000:00:02.0 timeline:8c4 using HWSP offset:f2144000

<0> [531.731289] gem_exec-2375 0..... 296516738us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:8c4 pin ring:{start:f2145000, head:0160, tail:0160}

<0> [531.731427] gem_exec-2375 0..... 296516771us : __i915_request_commit: 0000:00:02.0 bcs0: fence 8c4:6, current 4

<0> [531.731558] gem_exec-2375 0D..1. 296517047us : __i915_request_submit: 0000:00:02.0 bcs0: fence 8c4:6, current 4

<0> [531.731683] gem_exec-2387 0..... 296521989us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43190, current 43146

<0> [531.731806] gem_exec-2387 0D..1. 296521995us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43190, current 43146

<0> [531.731931] gem_exec-2374 0..... 296522208us : __i915_request_commit: 0000:00:02.0 rcs0: fence 749:8, current 6

<0> [531.732060] gem_exec-2374 0D..1. 296522212us : __i915_request_submit: 0000:00:02.0 rcs0: fence 749:8, current 6

<0> [531.732193] gem_exec-2374 0..... 296522482us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43216, current 43156

<0> [531.732323] gem_exec-2374 0..... 296522765us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43230, current 43166

<0> [531.732438] kworker/-2408 0..... 296522938us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:8cb unpin

<0> [531.732549] kworker/-2408 0..... 296523066us : __intel_context_retire: 0000:00:02.0 rcs0: context:8cb retire runtime: { total:363739ns, avg:117236ns }

<0> [531.732663] kworker/-2408 0..... 296523074us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:566 unpin

<0> [531.732773] kworker/-2408 0..... 296523203us : __intel_context_retire: 0000:00:02.0 rcs0: context:566 retire runtime: { total:1710681ns, avg:206488ns }

<0> [531.732891] kworker/-2408 0..... 296523949us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:a33 unpin

<0> [531.733021] kworker/-2408 0..... 296524073us : __intel_context_retire: 0000:00:02.0 ccs0: context:a33 retire runtime: { total:320809ns, avg:125133ns }

<0> [531.733137] kworker/-2408 0..... 296524213us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:605 unpin

<0> [531.733248] kworker/-2408 0..... 296524337us : __intel_context_retire: 0000:00:02.0 vcs1: context:605 retire runtime: { total:93227ns, avg:22154ns }

<0> [531.733361] kworker/-2408 0..... 296525599us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:49c unpin

<0> [531.733473] kworker/-2408 0.N... 296525732us : __intel_context_retire: 0000:00:02.0 vcs1: context:49c retire runtime: { total:123596ns, avg:23744ns }

<0> [531.733588] gem_exec-2397 0..... 296527754us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 pin ring:{start:e9cb6000, head:0000, tail:0000}

<0> [531.733704] gem_exec-2397 0..... 296527773us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:ca3 unpin

<0> [531.733816] gem_exec-2397 0..... 296527900us : __intel_context_retire: 0000:00:02.0 ccs0: context:ca3 retire runtime: { total:0ns, avg:0ns }

<0> [531.733927] gem_exec-2397 0..... 296527905us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 active

<0> [531.734044] gem_exec-2397 0..... 296527906us : intel_timeline_pin: 0000:00:02.0 timeline:ca3 using HWSP offset:e9c7f000

<0> [531.734153] gem_exec-2397 0..... 296527911us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 pin ring:{start:e9cb6000, head:0000, tail:0000}

<0> [531.734265] gem_exec-2397 0..... 296527926us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:ca3 unpin

<0> [531.734380] gem_exec-2397 0..... 296528053us : __intel_context_retire: 0000:00:02.0 ccs0: context:ca3 retire runtime: { total:0ns, avg:0ns }

<0> [531.734497] gem_exec-2397 0..... 296528056us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 active

<0> [531.734632] gem_exec-2397 0..... 296528057us : intel_timeline_pin: 0000:00:02.0 timeline:ca3 using HWSP offset:e9c7f000

<0> [531.734760] gem_exec-2397 0..... 296528060us : __intel_context_do_pin_ww: 0000:00:02.0 ccs0: context:ca3 pin ring:{start:e9cb6000, head:0000, tail:0000}

<0> [531.734912] gem_exec-2397 0..... 296528407us : __i915_request_commit: 0000:00:02.0 ccs0: fence ca3:2, current 0

<0> [531.735064] gem_exec-2397 0D..1. 296528411us : __i915_request_submit: 0000:00:02.0 ccs0: fence ca3:2, current 0

<0> [531.735196] gem_exec-2397 0..... 296529484us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43304, current 43263

<0> [531.735323] gem_exec-2399 0..... 296529684us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43268, current 43268

<0> [531.735449] gem_exec-2397 0..... 296530257us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43348, current 43288

<0> [531.735593] gem_exec-2397 0..... 296530264us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43288, current 43288

<0> [531.735718] gem_exec-2392 0..... 296531089us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43362, current 43302

<0> [531.735832] gem_exec-2392 0..... 296531241us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:82a active

<0> [531.735949] gem_exec-2392 0..... 296531245us : intel_timeline_pin: 0000:00:02.0 timeline:82a using HWSP offset:f352e000

<0> [531.736070] gem_exec-2392 0..... 296531253us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:82a pin ring:{start:f367c000, head:0438, tail:0438}

<0> [531.736217] gem_exec-2392 0..... 296531291us : __i915_request_commit: 0000:00:02.0 rcs0: fence 82a:8, current 6

<0> [531.736341] gem_exec-2392 0D..1. 296531295us : __i915_request_submit: 0000:00:02.0 rcs0: fence 82a:8, current 6

<0> [531.736464] gem_exec-2392 0..... 296533589us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43400, current 43346

<0> [531.736587] gem_exec-2364 0..... 296536242us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43446, current 43414

<0> [531.736709] gem_exec-2364 0D..1. 296536248us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43446, current 43414

<0> [531.736822] kworker/-1076 0..... 296536777us : __intel_context_do_unpin.part.0: 0000:00:02.0 ccs0: context:3ca unpin

<0> [531.736934] kworker/-1076 0..... 296536848us : __intel_context_retire: 0000:00:02.0 ccs0: context:3ca retire runtime: { total:284080ns, avg:72292ns }

<0> [531.737062] gem_exec-2376 0..... 296537535us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43490, current 43446

<0> [531.737175] gem_exec-2376 0..... 296537650us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b99 active

<0> [531.737293] gem_exec-2376 0..... 296537652us : intel_timeline_pin: 0000:00:02.0 timeline:b99 using HWSP offset:ec04e000

<0> [531.737407] gem_exec-2376 0..... 296537656us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b99 pin ring:{start:ec22a000, head:0210, tail:0210}

<0> [531.737544] gem_exec-2376 0..... 296537689us : __i915_request_commit: 0000:00:02.0 vcs0: fence b99:8, current 6

<0> [531.737684] gem_exec-2376 0D..1. 296537693us : __i915_request_submit: 0000:00:02.0 vcs0: fence b99:8, current 6

<0> [531.737827] gem_exec-2376 0..... 296538210us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43528, current 43458

<0> [531.737963] gem_exec-2376 0..... 296538214us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43458, current 43458

<0> [531.738093] gem_exec-2388 0..... 296545490us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43566, current 43554

<0> [531.738221] gem_exec-2388 0D..1. 296545495us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43566, current 43554

<0> [531.738335] gem_exec-2388 0..... 296546077us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:5b2 active

<0> [531.738454] gem_exec-2388 0..... 296546080us : intel_timeline_pin: 0000:00:02.0 timeline:5b2 using HWSP offset:f86d3000

<0> [531.738567] gem_exec-2388 0..... 296546088us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:5b2 pin ring:{start:f883c000, head:02c0, tail:02c0}

<0> [531.738694] gem_exec-2388 0..... 296546128us : __i915_request_commit: 0000:00:02.0 vcs0: fence 5b2:10, current 8

<0> [531.738816] gem_exec-2388 0D..1. 296546133us : __i915_request_submit: 0000:00:02.0 vcs0: fence 5b2:10, current 8

<0> [531.738938] gem_exec-2388 0..... 296546810us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43598, current 43568

<0> [531.739060] gem_exec-2388 0..... 296547355us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43632, current 43568

<0> [531.739181] gem_exec-2377 20..... 296548956us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43606, current 43606

<0> [531.739304] gem_exec-2390 0..... 296549167us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43670, current 43606

<0> [531.739431] gem_exec-2385 20..... 296549243us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43672, current 43606

<0> [531.739559] gem_exec-2377 21..... 296552221us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43686, current 43674

<0> [531.739681] gem_exec-2377 21D..1. 296552252us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43686, current 43675

<0> [531.739803] gem_exec-2377 21..... 296552634us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43676, current 43684

<0> [531.739924] gem_exec-2377 21..... 296552652us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43678, current 43684

<0> [531.740045] gem_exec-2377 21..... 296552735us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43680, current 43684

<0> [531.740167] gem_exec-2377 21..... 296552749us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43682, current 43684

<0> [531.740289] gem_exec-2399 0..... 296553553us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43706, current 43689

<0> [531.740412] gem_exec-2399 0D..1. 296553560us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43706, current 43690

<0> [531.740533] gem_exec-2399 0..... 296553566us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43690, current 43690

<0> [531.740656] gem_exec-2363 20..... 296554097us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43712, current 43692

<0> [531.740778] gem_exec-2363 20D..1. 296554119us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43712, current 43693

<0> [531.740900] gem_exec-2372 21..... 296554259us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:43698, current 43698

<0> [531.741023] gem_exec-2399 0..... 296555455us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43760, current 43718

<0> [531.741147] gem_exec-2399 0..... 296555761us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43780, current 43718

<0> [531.741261] gem_exec-2362 0..... 296555938us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:c2a active

<0> [531.741383] gem_exec-2362 0..... 296555942us : intel_timeline_pin: 0000:00:02.0 timeline:c2a using HWSP offset:ead5e000

<0> [531.741497] gem_exec-2362 0..... 296555950us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:c2a pin ring:{start:eadeb000, head:02d0, tail:02d0}

<0> [531.741624] gem_exec-2362 0..... 296555986us : __i915_request_commit: 0000:00:02.0 rcs0: fence c2a:6, current 4

<0> [531.741745] gem_exec-2362 0D..1. 296555991us : __i915_request_submit: 0000:00:02.0 rcs0: fence c2a:6, current 4

<0> [531.741864] gem_exec-2362 0..... 296558541us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43806, current 43744

<0> [531.741980] gem_exec-2394 0..... 296559876us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:cb9 active

<0> [531.742095] gem_exec-2371 20..... 296561566us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:cbb active

<0> [531.742221] gem_exec-2399 0..... 296563216us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43862, current 43844

<0> [531.742344] gem_exec-2399 0D..1. 296563222us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:43862, current 43844

<0> [531.742457] gem_exec-2399 0..... 296563526us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:820 active

<0> [531.742576] gem_exec-2399 0..... 296563530us : intel_timeline_pin: 0000:00:02.0 timeline:820 using HWSP offset:f3695000

<0> [531.742687] gem_exec-2399 0..... 296563540us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:820 pin ring:{start:f36f1000, head:0160, tail:0160}

<0> [531.742814] gem_exec-2399 0..... 296563586us : __i915_request_commit: 0000:00:02.0 bcs0: fence 820:6, current 4

<0> [531.742935] gem_exec-2399 0D..1. 296563591us : __i915_request_submit: 0000:00:02.0 bcs0: fence 820:6, current 4

<0> [531.743056] gem_exec-2364 0..... 296564053us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43896, current 43854

<0> [531.743168] gem_exec-2364 0..... 296564186us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b82 active

<0> [531.743286] gem_exec-2364 0..... 296564189us : intel_timeline_pin: 0000:00:02.0 timeline:b82 using HWSP offset:ec414000

<0> [531.743403] gem_exec-2364 0..... 296564195us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:b82 pin ring:{start:ec47f000, head:0210, tail:0210}

<0> [531.743529] gem_exec-2364 0..... 296564230us : __i915_request_commit: 0000:00:02.0 vcs0: fence b82:8, current 6

<0> [531.743650] gem_exec-2364 0D..1. 296564234us : __i915_request_submit: 0000:00:02.0 vcs0: fence b82:8, current 6

<0> [531.743771] gem_exec-2364 0..... 296564700us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43924, current 43858

<0> [531.743893] gem_exec-2364 0..... 296566269us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:43948, current 43892

<0> [531.744013] gem_exec-2364 0..... 296573469us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44004, current 43988

<0> [531.744135] gem_exec-2364 0D..1. 296573474us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:44004, current 43988

<0> [531.744248] gem_exec-2364 0..... 296574080us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f active

<0> [531.744372] gem_exec-2364 0..... 296574086us : intel_timeline_pin: 0000:00:02.0 timeline:49f using HWSP offset:fab13000

<0> [531.744485] gem_exec-2364 0..... 296574093us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f pin ring:{start:fab14000, head:02c0, tail:02c0}

<0> [531.744600] gem_exec-2364 0..... 296574121us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:49f unpin

<0> [531.744711] gem_exec-2364 0..... 296574204us : __intel_context_retire: 0000:00:02.0 vcs0: context:49f retire runtime: { total:111777ns, avg:37100ns }

<0> [531.744823] gem_exec-2364 0..... 296574207us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f active

<0> [531.744940] gem_exec-2364 0..... 296574208us : intel_timeline_pin: 0000:00:02.0 timeline:49f using HWSP offset:fab13000

<0> [531.745050] gem_exec-2364 0..... 296574213us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f pin ring:{start:fab14000, head:02c0, tail:02c0}

<0> [531.745166] gem_exec-2364 0..... 296574226us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:49f unpin

<0> [531.745275] gem_exec-2364 0..... 296574308us : __intel_context_retire: 0000:00:02.0 vcs0: context:49f retire runtime: { total:111777ns, avg:37100ns }

<0> [531.745392] gem_exec-2364 0..... 296574311us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f active

<0> [531.745510] gem_exec-2364 0..... 296574313us : intel_timeline_pin: 0000:00:02.0 timeline:49f using HWSP offset:fab13000

<0> [531.745619] gem_exec-2364 0..... 296574318us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:49f pin ring:{start:fab14000, head:02c0, tail:02c0}

<0> [531.745732] kworker/-157 0..... 296577912us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:6ac unpin

<0> [531.745841] kworker/-157 0..... 296578041us : __intel_context_retire: 0000:00:02.0 vecs0: context:6ac retire runtime: { total:89358ns, avg:29945ns }

<0> [531.745953] kworker/-157 0..... 296578049us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:781 unpin

<0> [531.746061] kworker/-157 0..... 296578178us : __intel_context_retire: 0000:00:02.0 vcs1: context:781 retire runtime: { total:81779ns, avg:21200ns }

<0> [531.746173] kworker/-157 0..... 296578211us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:bed unpin

<0> [531.746281] kworker/-157 0..... 296578339us : __intel_context_retire: 0000:00:02.0 vecs0: context:bed retire runtime: { total:55544ns, avg:23108ns }

<0> [531.746401] kworker/-157 0..... 296578348us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:962 unpin

<0> [531.746511] kworker/-157 0..... 296578473us : __intel_context_retire: 0000:00:02.0 vcs0: context:962 retire runtime: { total:243005ns, avg:40439ns }

<0> [531.746642] gem_exec-2393 0..... 296578920us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44086, current 44038

<0> [531.746771] gem_exec-2393 0..... 296578923us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44038, current 44038

<0> [531.746898] gem_exec-2390 0..... 296580944us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44140, current 44090

<0> [531.747010] gem_exec-2390 0..... 296581060us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:a67 active

<0> [531.747128] gem_exec-2390 0..... 296581064us : intel_timeline_pin: 0000:00:02.0 timeline:a67 using HWSP offset:ee76c000

<0> [531.747239] gem_exec-2390 0..... 296581074us : __intel_context_do_pin_ww: 0000:00:02.0 vecs0: context:a67 pin ring:{start:ee9d1000, head:00b0, tail:00b0}

<0> [531.747375] gem_exec-2390 0..... 296581140us : __i915_request_commit: 0000:00:02.0 vecs0: fence a67:4, current 2

<0> [531.747499] gem_exec-2390 0D..1. 296581149us : __i915_request_submit: 0000:00:02.0 vecs0: fence a67:4, current 2

<0> [531.747623] gem_exec-2390 0..... 296581389us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44166, current 44092

<0> [531.747746] gem_exec-2379 0..... 296585260us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44210, current 44164

<0> [531.747858] kworker/-157 0..... 296595605us : __intel_context_do_unpin.part.0: 0000:00:02.0 bcs0: context:cae unpin

<0> [531.747970] kworker/-157 0..... 296595676us : __intel_context_retire: 0000:00:02.0 bcs0: context:cae retire runtime: { total:18073ns, avg:18073ns }

<0> [531.748095] gem_exec-2392 0..... 296596579us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44332, current 44294

<0> [531.748220] gem_exec-2379 20..... 296596741us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44340, current 44294

<0> [531.748346] gem_exec-2372 21..... 296596931us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44348, current 44294

<0> [531.748462] gem_exec-2392 0..... 296597040us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:a65 active

<0> [531.748578] gem_exec-2392 0..... 296597044us : intel_timeline_pin: 0000:00:02.0 timeline:a65 using HWSP offset:ee925000

<0> [531.748689] gem_exec-2392 0..... 296597052us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:a65 pin ring:{start:ee9f3000, head:05a0, tail:05a0}

<0> [531.748803] kworker/-157 0..... 296600848us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:6a5 unpin

<0> [531.748926] gem_exec-2372 21..... 296600886us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44386, current 44328

<0> [531.749037] kworker/-157 0..... 296600920us : __intel_context_retire: 0000:00:02.0 vecs0: context:6a5 retire runtime: { total:162604ns, avg:21783ns }

<0> [531.749150] kworker/-157 0..... 296600966us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:add unpin

<0> [531.749261] kworker/-157 0..... 296601038us : __intel_context_retire: 0000:00:02.0 vcs0: context:add retire runtime: { total:94923ns, avg:23956ns }

<0> [531.749390] gem_exec-2384 0..... 296604593us : intel_timeline_pin: 0000:00:02.0 timeline:cb6 using HWSP offset:e996f000

<0> [531.749514] gem_exec-2405 20..... 296605638us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44426, current 44428

<0> [531.749638] gem_exec-2388 0..... 296606032us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44446, current 44428

<0> [531.749749] gem_exec-2388 0..... 296606119us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:ae2 active

<0> [531.749867] gem_exec-2388 0..... 296606122us : intel_timeline_pin: 0000:00:02.0 timeline:ae2 using HWSP offset:ed806000

<0> [531.749980] gem_exec-2388 0..... 296606128us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:ae2 pin ring:{start:ed888000, head:0210, tail:0210}

<0> [531.750101] gem_exec-2388 0..... 296606142us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:ae2 unpin

<0> [531.750210] gem_exec-2388 0.N... 296606282us : __intel_context_retire: 0000:00:02.0 vcs0: context:ae2 retire runtime: { total:45103ns, avg:15264ns }

<0> [531.750341] gem_exec-2395 0..... 296606767us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44474, current 44428

<0> [531.750462] gem_exec-2405 0..... 296607015us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:831 active

<0> [531.750600] gem_exec-2405 0..... 296607019us : intel_timeline_pin: 0000:00:02.0 timeline:831 using HWSP offset:f3461000

<0> [531.750719] gem_exec-2405 0..... 296607029us : __intel_context_do_pin_ww: 0000:00:02.0 bcs0: context:831 pin ring:{start:f3535000, head:0210, tail:0210}

<0> [531.750847] gem_exec-2405 0..... 296607069us : __i915_request_commit: 0000:00:02.0 bcs0: fence 831:8, current 6

<0> [531.750969] gem_exec-2405 0D..1. 296607073us : __i915_request_submit: 0000:00:02.0 bcs0: fence 831:8, current 6

<0> [531.751081] kworker/-157 0..... 296610311us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:a28 unpin

<0> [531.751192] kworker/-157 0..... 296610464us : __intel_context_retire: 0000:00:02.0 vcs1: context:a28 retire runtime: { total:111565ns, avg:30369ns }

<0> [531.751307] kworker/-157 0..... 296610488us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:2f5 unpin

<0> [531.751421] kworker/-157 0.N... 296610731us : __intel_context_retire: 0000:00:02.0 vcs0: context:2f5 retire runtime: { total:78758ns, avg:19610ns }

<0> [531.751548] gem_exec-2372 20..... 296615702us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44582, current 44566

<0> [531.751672] gem_exec-2372 20D..1. 296615722us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:44582, current 44566

<0> [531.751795] gem_exec-2372 20..... 296616684us : i915_request_retire.part.0: 0000:00:02.0 vecs0: fence 5b7:10, current 12

<0> [531.751917] gem_exec-2372 20..... 296616759us : __i915_request_commit: 0000:00:02.0 vecs0: fence 5b7:14, current 12

<0> [531.752039] gem_exec-2372 20D..1. 296616775us : __i915_request_submit: 0000:00:02.0 vecs0: fence 5b7:14, current 12

<0> [531.752161] gem_exec-2386 0..... 296616902us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44600, current 44589

<0> [531.752284] gem_exec-2386 0D..1. 296616909us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:44600, current 44589

<0> [531.752408] gem_exec-2386 0..... 296616916us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44590, current 44590

<0> [531.752523] gem_exec-2386 0..... 296617703us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:65f active

<0> [531.752641] gem_exec-2386 0..... 296617708us : intel_timeline_pin: 0000:00:02.0 timeline:65f using HWSP offset:f7073000

<0> [531.752754] gem_exec-2386 0..... 296617718us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:65f pin ring:{start:f7159000, head:02d0, tail:02d0}

<0> [531.752881] gem_exec-2372 20..... 296617752us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44622, current 44596

<0> [531.753003] gem_exec-2386 0..... 296617766us : __i915_request_commit: 0000:00:02.0 rcs0: fence 65f:6, current 4

<0> [531.753125] gem_exec-2372 20..... 296617770us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44596, current 44596

<0> [531.753251] gem_exec-2372 20..... 296617884us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44598, current 44598

<0> [531.753386] gem_exec-2372 20..... 296617956us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44624, current 44599

<0> [531.753510] gem_exec-2372 20..... 296617967us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44600, current 44600

<0> [531.753633] gem_exec-2386 0D..1. 296618027us : __i915_request_submit: 0000:00:02.0 rcs0: fence 65f:6, current 4

<0> [531.753760] gem_exec-2386 0..... 296618486us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44648, current 44608

<0> [531.753882] gem_exec-2383 20..... 296618794us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44656, current 44608

<0> [531.754003] gem_exec-2400 0..... 296618970us : intel_timeline_pin: 0000:00:02.0 timeline:cbc using HWSP offset:e9957000

<0> [531.754116] gem_exec-2383 20..... 296619032us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:42f active

<0> [531.754235] gem_exec-2383 20..... 296619043us : intel_timeline_pin: 0000:00:02.0 timeline:42f using HWSP offset:fb871000

<0> [531.754359] gem_exec-2383 20..... 296619070us : __intel_context_do_pin_ww: 0000:00:02.0 vcs1: context:42f pin ring:{start:fb945000, head:0160, tail:0160}

<0> [531.754488] gem_exec-2383 20..... 296619191us : __i915_request_commit: 0000:00:02.0 vcs1: fence 42f:6, current 4

<0> [531.754610] gem_exec-2383 20D..1. 296619202us : __i915_request_submit: 0000:00:02.0 vcs1: fence 42f:6, current 4

<0> [531.754733] gem_exec-2397 21..... 296619344us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44678, current 44608

<0> [531.754846] kworker/-159 21.N... 296619800us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:5e8 unpin

<0> [531.754958] kworker/-159 21.N... 296619971us : __intel_context_retire: 0000:00:02.0 vcs0: context:5e8 retire runtime: { total:101760ns, avg:25599ns }

<0> [531.755072] gem_exec-2400 21..... 296620746us : __intel_context_do_pin_ww: 0000:00:02.0 vcs0: context:cbc pin ring:{start:e9a86000, head:0000, tail:0000}

<0> [531.755199] gem_exec-2400 21..... 296620916us : __i915_request_commit: 0000:00:02.0 vcs0: fence cbc:2, current 0

<0> [531.755322] gem_exec-2400 21D..1. 296620929us : __i915_request_submit: 0000:00:02.0 vcs0: fence cbc:2, current 0

<0> [531.755435] kworker/-1076 0..... 296621495us : __intel_context_do_unpin.part.0: 0000:00:02.0 vecs0: context:a67 unpin

<0> [531.755546] kworker/-1076 0..... 296621628us : __intel_context_retire: 0000:00:02.0 vecs0: context:a67 retire runtime: { total:62858ns, avg:21571ns }

<0> [531.755660] kworker/-1076 0..... 296621639us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:4ea unpin

<0> [531.755770] kworker/-1076 0..... 296621769us : __intel_context_retire: 0000:00:02.0 vcs0: context:4ea retire runtime: { total:99004ns, avg:41075ns }

<0> [531.755883] kworker/-1076 0..... 296621778us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs0: context:3f4 unpin

<0> [531.755994] kworker/-1076 0..... 296621908us : __intel_context_retire: 0000:00:02.0 vcs0: context:3f4 retire runtime: { total:137058ns, avg:24698ns }

<0> [531.756116] gem_exec-2373 20..... 296622097us : intel_timeline_pin: 0000:00:02.0 timeline:cbd using HWSP offset:e9951000

<0> [531.756226] kworker/-1076 0..... 296623415us : __intel_context_do_unpin.part.0: 0000:00:02.0 vcs1: context:cb1 unpin

<0> [531.756345] kworker/-1076 0..... 296623566us : __intel_context_retire: 0000:00:02.0 vcs1: context:cb1 retire runtime: { total:48601ns, avg:48601ns }

<0> [531.756474] gem_exec-2400 21..... 296626806us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44714, current 44692

<0> [531.756597] gem_exec-2400 21..... 296626820us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44690, current 44693

<0> [531.756721] gem_exec-2400 21..... 296626830us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44692, current 44693

<0> [531.756844] gem_exec-2400 21..... 296626834us : i915_request_retire.part.0: 0000:00:02.0 rcs0: fence 298:44694, current 44694

<0> [531.756966] gem_exec-2376 20..... 296627357us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44740, current 44702

<0> [531.757089] gem_exec-2386 0..... 296627413us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44742, current 44702

<0> [531.757214] gem_exec-2386 0D..1. 296627420us : __i915_request_submit: 0000:00:02.0 rcs0: fence 298:44742, current 44702

<0> [531.757334] gem_exec-2386 0..... 296627514us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:728 active

<0> [531.757457] gem_exec-2386 0..... 296627517us : intel_timeline_pin: 0000:00:02.0 timeline:728 using HWSP offset:f562d000

<0> [531.757571] gem_exec-2386 0..... 296627525us : __intel_context_do_pin_ww: 0000:00:02.0 rcs0: context:728 pin ring:{start:f5711000, head:02d0, tail:02d0}

<6> [531.757630] [IGT] gem_exec_schedule: finished subtest vcs0, SUCCESS

<0> [531.757690] gem_exec-2386 0..... 296627547us : __intel_context_do_unpin.part.0: 0000:00:02.0 rcs0: context:728 unpin

<0> [531.757815] gem_exec-2400 21..... 296627613us : __i915_request_commit: 0000:00:02.0 rcs0: fence 298:44750, current 44702

Results for igt@gem_exec_schedule@in-order@vcs0