Re: [PATCH] drm/i915: fix exiting context timeout calculation

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 




On 02/12/2022 12:19, Andrzej Hajda wrote:
On 02.12.2022 10:14, Tvrtko Ursulin wrote:

On 01/12/2022 16:36, Andrzej Hajda wrote:
On 01.12.2022 11:28, Tvrtko Ursulin wrote:

On 01/12/2022 00:22, John Harrison wrote:
On 11/29/2022 00:43, Tvrtko Ursulin wrote:
On 28/11/2022 16:52, Andrzej Hajda wrote:
In case context is exiting preempt_timeout_ms is used for timeout,
but since introduction of DRM_I915_PREEMPT_TIMEOUT_COMPUTE it increases
to 7.5 seconds. Heartbeat occurs earlier but it is still 2.5s.

Fixes: d7a8680ec9fb21 ("drm/i915: Improve long running compute w/a for GuC submission")
Closes: https://gitlab.freedesktop.org/drm/intel/-/issues/2410
Signed-off-by: Andrzej Hajda <andrzej.hajda@xxxxxxxxx>
---
Hi all,

I am not sure what is expected solution here, and if my patch does not actually reverts intentions of patch d7a8680ec9fb21. Feel free to propose
something better.
Other alternative would be to increase t/o in IGT tests, but I am not sure
if this is good direction.

Is it the hack with the FIXME marker from 47daf84a8bfb ("drm/i915: Make the heartbeat play nice with long pre-emption timeouts") that actually breaks things? (If IGT modifies the preempt timeout the heartbeat extension will not work as intended.)

If so, I think we agreed during review that was a weakness which needs to be addressed, but I would need to re-read the old threads to remember what was the plan. Regardless what it was it may be time is now to continue with those improvements.

What is the actual issue? Just that closing contexts are taking forever to actually close? That would be the whole point of the 'context_is_exiting' patch. Which I still totally disagree with.

If the context is being closed 'gracefully' and it is intended that it should be allowed time to pre-empt without being killed via an engine reset then the 7.5s delay is required. That is the officially agreed upon timeout to allow compute capable contexts to reach a pre-emption point before they should be killed. If an IGT is failing because it enforces a shorter timeout then the IGT needs to be updated to account for the fact that i915 has to support slow compute workloads.

If the context is being closed 'forcefully' and should be killed immediately then you should be using the 'BANNED_PREEMPT_TIMEOUT' value not the sysfs/config value.

Regarding heartbeats...

The heartbeat period is 2.5s. But there are up to five heartbeat periods between the heartbeat starting and it declaring a hang. The patch you mention also introduced a check on the pre-emption timeout when the last period starts. If the pre-emption timeout is longer than the heartbeat period then the last period is extended to guarantee that a full pre-emption time is granted before declaring the hang.

Are you saying that a heartbeat timeout is occurring and killing the system? Or are you just worried that something doesn't align correctly?

I leave this to Andrzej since I am not the one debugging this. I just glanced over the IGT and saw that there's code in there which sets both the preempt timeout and heartbeat interval to non-default values. And then I remembered this:

The test is gem_ctx_persistence@many-contexts. It does not modify sysfs timeouts, but it assumes 1sec is enough to wait for exiting context (no-preemption). It works with bcs, vcs, vecs, but fails on rcs since it has timeout set to 7.5sec (btw it works with GuC submissions enabled). It seemed to me somehow inconsistent, but if this is how it should work
I will just adjust the test.

This looks odd then. That test is using non-preemptable spinners and AFAICT it keeps submitting them for 30s, across all engines, and then it stops and waits for one second for all of them to exit.

With the 7.5 preempt timeout I'd expect test should fail both with GuC and execlists.

OK, my claim about working with GuC was not verified enough, just one testing machine.


What should happen is that every context is marked as "exiting" and is revoked. On the next scheduling event they would all be dropped.

So I think two questions - how did increase of preempt timeout to 7.5s pass CI - is the failure sporadic for instance?

After some data mining on cibuglog from last month I can say results are mostly consistent per machine.
On most machines it always passes.
Always fails on shard-tgl*, shard-rkl-{1,2,3,4,6} (but on shard-rkl-5 it always passes), fi-adl-ddr5, fi-kbl-soraka, fi-rkl-11600.
On re-dg2-{11,12,15} results are inconsistent - some passes, some fails.


Second question - you are saying with GuC test always passes - how does GuC manages to revoke a non-preemptible spinner in less than one second if preempt timeout is 7.5s.. colour me confused.

Anyway those questions are secondary.. Fix here I think pretty obviously is for many_contexts() to fetch the preempt timeout from sysfs and allow for that much time (plus a safety factor). Use the longest timeout between all engines since all are submitted to.

With increasing to 10 seconds the issue disappeared on two RIL machines used for tests, but I will post the patch on try-bot check other machines as well.

One more thing, to be sure. As I understand reset due to stopped heartbeat, should not happen for 7.5sec preemption timeouts, if test do not adjust any timeouts? If yes then there is sth wrong anyway.
See sample logs from dg2 showing what happens: pass[1], fail[2].
In both cases there is 22 "heartbeat * not ticking" log lines, all on 7.5s preemption_timeouts (rcs, ccs).

[1]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_12449/re-dg2-12/igt@gem_ctx_persistence@xxxxxxxxxxxxxxxxxx

<6> [278.652441] [IGT] gem_ctx_persistence: executing
<7> [278.663699] i915 0000:03:00.0: [drm:i915_gem_open [i915]]
<7> [278.664362] i915 0000:03:00.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x0000005c [0x0000005c]
<7> [278.664496] i915 0000:03:00.0: [drm:i915_gem_open [i915]]
<7> [278.664992] i915 0000:03:00.0: [drm:i915_gem_open [i915]]
<6> [278.670968] [IGT] gem_ctx_persistence: starting subtest many-contexts
<7> [278.671164] [drm:eb_lookup_vmas [i915]] EINVAL at eb_validate_vma:505
<7> [278.686769] i915 0000:03:00.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x000001dc [0x000001dc]
<6> [279.367025] i915 0000:03:00.0: [drm] Ignoring context reset notification of exiting context 0x100C on bcs0
<6> [279.368863] i915 0000:03:00.0: [drm] Ignoring context reset notification of exiting context 0x100D on vcs0
<6> [279.370813] i915 0000:03:00.0: [drm] Ignoring context reset notification of exiting context 0x100E on vcs1
<6> [279.373360] i915 0000:03:00.0: [drm] Ignoring context reset notification of exiting context 0x100F on vecs0
<6> [279.376086] i915 0000:03:00.0: [drm] Ignoring context reset notification of exiting context 0x1010 on vecs1
<7> [281.964427] heartbeat ccs3 heartbeat {seqno:e:190, prio:2147483646} not ticking
<7> [281.964449] heartbeat 	Awake? 2
<7> [281.964457] heartbeat 	Barriers?: no
<7> [281.964465] heartbeat 	Latency: 0us
<7> [281.964499] heartbeat 	Runtime: 292051ms
<7> [281.964507] heartbeat 	Forcewake: 0 domains, 0 active
<7> [281.964516] heartbeat 	Heartbeat: 3224 ms ago
<7> [281.964525] heartbeat 	Reset count: 0 (global 28)
<7> [281.964533] heartbeat 	Properties:
<7> [281.964539] heartbeat 		heartbeat_interval_ms: 2500 [default 2500]
<7> [281.964548] heartbeat 		max_busywait_duration_ns: 8000 [default 8000]
<7> [281.964556] heartbeat 		preempt_timeout_ms: 7500 [default 7500]
<7> [281.964564] heartbeat 		stop_timeout_ms: 100 [default 100]
<7> [281.964571] heartbeat 		timeslice_duration_ms: 1 [default 1]
<7> [281.964580] heartbeat 	Requests:
<7> [281.964663] heartbeat 		active in queueE e:190*  prio=2147483646 @ 3224ms: [i915]
<7> [281.964677] heartbeat 		ring->start:  0xfecb0000
<7> [281.964685] heartbeat 		ring->head:   0x000008a0
<7> [281.964692] heartbeat 		ring->tail:   0x00000758
<7> [281.964698] heartbeat 		ring->emit:   0x00000760
<7> [281.964705] heartbeat 		ring->space:  0x00000100

This indeed looks super strange - heartbeat at max prio and not ticking 3224ms after first created. No idea. One for GuC experts if GuC is the only backend where this happens.

Well then I looked at the failures on TGL you mention above:

https://intel-gfx-ci.01.org/tree/drm-tip/IGT_7078/shard-tglb3/igt@gem_ctx_persistence@xxxxxxxxxxxxxxxxxx

<6> [331.908547] [IGT] gem_ctx_persistence: executing
<7> [331.910926] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<7> [331.911475] i915 0000:00:02.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x0000005c [0x0000005c]
<7> [331.911608] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<7> [331.911924] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<6> [331.915834] [IGT] gem_ctx_persistence: starting subtest many-contexts
...
<7> [335.249250] heartbeat rcs0 heartbeat {seqno:5:76, prio:2147483646} not ticking
<7> [335.249269] heartbeat 	Awake? 1338
<7> [335.249273] heartbeat 	Barriers?: no
<7> [335.249277] heartbeat 	Latency: 243us
<7> [335.249291] heartbeat 	Runtime: 10531ms
<7> [335.249294] heartbeat 	Forcewake: 0 domains, 0 active
<7> [335.249297] heartbeat 	Heartbeat: 3307 ms ago
<7> [335.249305] heartbeat 	Reset count: 0 (global 0)
<7> [335.249308] heartbeat 	Properties:
<7> [335.249310] heartbeat 		heartbeat_interval_ms: 2500 [default 2500]
<7> [335.249314] heartbeat 		max_busywait_duration_ns: 8000 [default 8000]
<7> [335.249318] heartbeat 		preempt_timeout_ms: 7500 [default 7500]
<7> [335.249322] heartbeat 		stop_timeout_ms: 100 [default 100]
<7> [335.249326] heartbeat 		timeslice_duration_ms: 1 [default 1]
<7> [335.249336] heartbeat 	Requests:
<7> [335.249387] heartbeat 		hungR 13a:2*  prio=0 @ 3308ms: gem_ctx_persist<1773>
<7> [335.249393] heartbeat 		ring->start:  0x0149f000
<7> [335.249395] heartbeat 		ring->head:   0x00000000
<7> [335.249398] heartbeat 		ring->tail:   0x000000b0
<7> [335.249402] heartbeat 		ring->emit:   0x000000b8
<7> [335.249404] heartbeat 		ring->space:  0x00003f08
<7> [335.249407] heartbeat 		ring->hwsp:   0xfedc4000

Same thing. So either something is totally broken or I totally forgot how things are supposed to work.

There shouldn't be a hearbeat stopped ticking until 4x hearbeat intervals + preempt timeout. And it nicely shows the current engine values for those so it makes no sense.

Was there something left running before the test started? But drop_caches was done on test start..

Regards,

Tvrtko

[2]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_12457/re-dg2-12/igt@gem_ctx_persistence@xxxxxxxxxxxxxxxxxx

Regards
Andrzej



Regards,

Tvrtko


Regards
Andrzej



next_heartbeat():
...
         /*
          * FIXME: The final period extension is disabled if the period has been           * modified from the default. This is to prevent issues with certain           * selftests which override the value and expect specific behaviour.           * Once the selftests have been updated to either cope with variable           * heartbeat periods (or to override the pre-emption timeout as well,           * or just to add a selftest specific override of the extension), the
          * generic override can be removed.
          */
         if (rq && rq->sched.attr.priority >= I915_PRIORITY_BARRIER &&
             delay == engine->defaults.heartbeat_interval_ms) {

Which then wouldn't dtrt with last heartbeat pulse extensions, if the IGT would be relying on that. Don't know, just pointing out to check and see if this FIXME needs to be prioritised.

Regards,

Tvrtko





[Index of Archives]     [AMD Graphics]     [Linux USB Devel]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]

  Powered by Linux