[PATCH 2/2] drm/i915/pmu: Connect engine busyness stats from GuC to pmu

[Umesh Nerlige Ramappa]

On Tue, Oct 19, 2021 at 09:32:07AM +0100, Tvrtko Ursulin wrote:
>
>On 18/10/2021 19:35, Umesh Nerlige Ramappa wrote:
>>On Mon, Oct 18, 2021 at 08:58:01AM +0100, Tvrtko Ursulin wrote:
>>>
>>>
>>>On 16/10/2021 00:47, Umesh Nerlige Ramappa wrote:
>>>>With GuC handling scheduling, i915 is not aware of the time that a
>>>>context is scheduled in and out of the engine. Since i915 pmu relies on
>>>>this info to provide engine busyness to the user, GuC shares this info
>>>>with i915 for all engines using shared memory. For each engine, this
>>>>info contains:
>>>>
>>>>- total busyness: total time that the context was running (total)
>>>>- id: id of the running context (id)
>>>>- start timestamp: timestamp when the context started running (start)
>>>>
>>>>At the time (now) of sampling the engine busyness, if the id is valid
>>>>(!= ~0), and start is non-zero, then the context is considered to be
>>>>active and the engine busyness is calculated using the below equation
>>>>
>>>>    engine busyness = total + (now - start)
>>>>
>>>>All times are obtained from the gt clock base. For inactive contexts,
>>>>engine busyness is just equal to the total.
>>>>
>>>>The start and total values provided by GuC are 32 bits and wrap around
>>>>in a few minutes. Since perf pmu provides busyness as 64 bit
>>>>monotonically increasing values, there is a need for this implementation
>>>>to account for overflows and extend the time to 64 bits before returning
>>>>busyness to the user. In order to do that, a worker runs periodically at
>>>>frequency = 1/8th the time it takes for the timestamp to wrap. As an
>>>>example, that would be once in 27 seconds for a gt clock frequency of
>>>>19.2 MHz.
>>>>
>>>>Note:
>>>>There might be an overaccounting of busyness due to the fact that GuC
>>>>may be updating the total and start values while kmd is reading them.
>>>>(i.e kmd may read the updated total and the stale start). In such a
>>>>case, user may see higher busyness value followed by smaller ones which
>>>>would eventually catch up to the higher value.
>>>>
>>>>v2: (Tvrtko)
>>>>- Include details in commit message
>>>>- Move intel engine busyness function into execlist code
>>>>- Use union inside engine->stats
>>>>- Use natural type for ping delay jiffies
>>>>- Drop active_work condition checks
>>>>- Use for_each_engine if iterating all engines
>>>>- Drop seq locking, use spinlock at guc level to update engine stats
>>>>- Document worker specific details
>>>>
>>>>v3: (Tvrtko/Umesh)
>>>>- Demarcate guc and execlist stat objects with comments
>>>>- Document known over-accounting issue in commit
>>>>- Provide a consistent view of guc state
>>>>- Add hooks to gt park/unpark for guc busyness
>>>>- Stop/start worker in gt park/unpark path
>>>>- Drop inline
>>>>- Move spinlock and worker inits to guc initialization
>>>>- Drop helpers that are called only once
>>>>
>>>>v4: (Tvrtko/Matt/Umesh)
>>>>- Drop addressed opens from commit message
>>>>- Get runtime pm in ping, remove from the park path
>>>>- Use cancel_delayed_work_sync in disable_submission path
>>>>- Update stats during reset prepare
>>>>- Skip ping if reset in progress
>>>>- Explicitly name execlists and guc stats objects
>>>>- Since disable_submission is called from many places, move resetting
>>>>  stats to intel_guc_submission_reset_prepare
>>>>
>>>>v5: (Tvrtko)
>>>>- Add a trylock helper that does not sleep and synchronize PMU event
>>>>  callbacks and worker with gt reset
>>>>
>>>>v6: (CI BAT failures)
>>>>- DUTs using execlist submission failed to boot since __gt_unpark is
>>>>  called during i915 load. This ends up calling the guc busyness unpark
>>>>  hook and results in kiskstarting an uninitialized worker. Let
>>>>  park/unpark hooks check if guc submission has been initialized.
>>>>- drop cant_sleep() from trylock hepler since rcu_read_lock takes care
>>>>  of that.
>>>>
>>>>v7: (CI) Fix igt at i915_selftest@live at gt_engines
>>>>- For guc mode of submission the engine busyness is derived from gt time
>>>>  domain. Use gt time elapsed as reference in the selftest.
>>>>- Increase busyness calculation to 10ms duration to ensure batch runs
>>>>  longer and falls within the busyness tolerances in selftest.
>>>
>>>[snip]
>>>
>>>>diff --git a/drivers/gpu/drm/i915/gt/selftest_engine_pm.c 
>>>>b/drivers/gpu/drm/i915/gt/selftest_engine_pm.c
>>>>index 75569666105d..24358bef6691 100644
>>>>--- a/drivers/gpu/drm/i915/gt/selftest_engine_pm.c
>>>>+++ b/drivers/gpu/drm/i915/gt/selftest_engine_pm.c
>>>>@@ -234,6 +234,7 @@ static int live_engine_busy_stats(void *arg)
>>>>         struct i915_request *rq;
>>>>         ktime_t de, dt;
>>>>         ktime_t t[2];
>>>>+        u32 gt_stamp;
>>>>         if (!intel_engine_supports_stats(engine))
>>>>             continue;
>>>>@@ -251,10 +252,16 @@ static int live_engine_busy_stats(void *arg)
>>>>         ENGINE_TRACE(engine, "measuring idle time\n");
>>>>         preempt_disable();
>>>>         de = intel_engine_get_busy_time(engine, &t[0]);
>>>>-        udelay(100);
>>>>+        gt_stamp = intel_uncore_read(gt->uncore, GUCPMTIMESTAMP);
>>>>+        udelay(10000);
>>>>         de = ktime_sub(intel_engine_get_busy_time(engine, &t[1]), de);
>>>>+        gt_stamp = intel_uncore_read(gt->uncore, 
>>>>GUCPMTIMESTAMP) - gt_stamp;
>>>>         preempt_enable();
>>>>-        dt = ktime_sub(t[1], t[0]);
>>>>+
>>>>+        dt = intel_engine_uses_guc(engine) ?
>>>>+             intel_gt_clock_interval_to_ns(engine->gt, gt_stamp) :
>>>>+             ktime_sub(t[1], t[0]);
>>>
>>>But this then shows the thing might not work for external callers 
>>>like PMU who have no idea about GUCPMTIMESTAMP and cannot obtain 
>>>it anyway.
>>>
>>>What is the root cause of the failure here, 100us or clock source? 
>>>Is the granularity of GUCPMTIMESTAMP perhaps simply too coarse for 
>>>100us test period? I forget what frequency it runs at.
>>
>>guc timestamp is ticking at 19.2 MHz in adlp/rkl (where I ran this).
>
>So ~52ns clock granularity, right?
>
>In which case 100us with +/- 52ns error should be max 0.05% error - is 
>this math correct?

Correct, but correlating GPU and CPU time in this manner is not 
accurate. In some cases the MMIO read of the GUC timestamp can take 
longer and since intel_engine_get_busy_time captures ktime into t[0] and 
t[1] BEFORE the stats are calculated, there is room for error. Even if 
t[0]/t[1] are captured AFTER the stats are calculated, it's the same 
issue. Ideally the test should do

before = ktime_get()
busyness1 = intel_engine_get_busy_time()
udelay(100)
busyness2 = intel_engine_get_busy_time()
after = ktime_get()

busy% = (busyness2 - busyness1)/(after - before) * 100

Isn't that how the user would do it?

Note: Second parameter to intel_engine_get_busy_time is not uabi, it's 
internal to i915 and mostly used by selftest or rps_timer (in non SLPC 
mode).

>
>>
>>1)
>>With 100us, often times I see that the batch has not yet started, so 
>>I get busy time in the range 0 - 60 %. I increased the time such 
>>that the batch runs long enough to make the scheduling time < 5%.
>
>0-60% should not be possible since there is a igt_wait_for_spinner 
>call before measuring starts, which ensures spinner is executing on 
>the GPU.
>
>I think we first need to understand where is this 0 - 60% problem 
>coming from because I don't think it is from batch not yet started.

Looks like it's possible that the GuC would update the busyness stats 
after the batch starts (when context goes from idle to active), so 
that's where this discrepancy is creeping in from. I am thinking of 
capturing busyness before igt_wait_for_spinner and then poll for 
busyness after the wait until the busyness starts ticking. Then we can  
continue with the remaining part of the test. Thoughts?

I tried running the above and ran into busyness > 100%. That's likely 
from the ktime_get issue mentioned above.

Thanks,
Umesh

>
>Regards,
>
>Tvrtko
>
>>
>>2)
>>I did a 100 runs on rkl/adlp. No failures on rkl. On adlp, I saw one 
>>in 25 runs show 93%/94% busyness for rcs0 and fail (expected is 
>>95%). For that I tried using the guc timestamp thinking it would 
>>provide more accuracy. It did in my testing, but CI still failed for 
>>rkl-guc (110% busyness!!), so now I just think we need to tweak the 
>>expected busyness for guc.
>>
>>Is 1) acceptable?
>>
>>For 2) I am thinking of just changing the expected busyness to 90% 
>>plus for guc mode OR should we just let it fail occassionally? 
>>Thoughts?
>>
>>Thanks,
>>Umesh
>>
>>>
>>>Regards,
>>>
>>>Tvrtko