[PATCH i-g-t v3] tests/intel/xe_pm_residency: Print execution and sleep times

[Poosa, Karthik]

On 20-09-2024 17:16, Riana Tauro wrote:
> Hi Karthik
>
> On 9/20/2024 2:01 PM, Gupta, Anshuman wrote:
>>
>>
>>> -----Original Message-----
>>> From: Poosa, Karthik <karthik.poosa at intel.com>
>>> Sent: Friday, September 20, 2024 2:03 PM
>>> To: igt-dev at lists.freedesktop.org
>>> Cc: Gupta, Anshuman <anshuman.gupta at intel.com>; Nilawar, Badal
>>> <badal.nilawar at intel.com>; Tauro, Riana <riana.tauro at intel.com>; Poosa,
>>> Karthik <karthik.poosa at intel.com>
>>> Subject: [PATCH i-g-t v3] tests/intel/xe_pm_residency: Print 
>>> execution and sleep
>>> times
>>>
>>> Print the workload execution and sleep times of the test to help 
>>> diagnose
>>> timeouts.
>>>
>>> v2: Patchwork test re-run.
>>>
>>> v3:
>>>   - Assert if syncobj_wait took more than 1.2 seconds, as it causes 
>>> the test
>>>     to timeout because test would sleep for more than 120 seconds which
>>>     triggers per task timeout.
>>>
>>> Signed-off-by: Karthik Poosa <karthik.poosa at intel.com>
>>> Reviewed-by: Riana Tauro <riana.tauro at intel.com>
>>> ---
>>>   tests/intel/xe_pm_residency.c | 5 ++++-
>>>   1 file changed, 4 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/tests/intel/xe_pm_residency.c 
>>> b/tests/intel/xe_pm_residency.c index
>>> 0e687558b..343fdd694 100644
>>> --- a/tests/intel/xe_pm_residency.c
>>> +++ b/tests/intel/xe_pm_residency.c
>>> @@ -139,11 +139,14 @@ static void exec_load(int fd, struct
>>> drm_xe_engine_class_instance *hwe, unsigned
>>>           elapsed = igt_nsec_elapsed(&tv);
>>>           igt_assert_eq(data->data, done[1]);
>>>
>>> -        igt_debug("Execution took %.3fms (submit %.1fus, wait
>>> %.1fus)\n",
>>> +        igt_info("Execution took %.3fms (submit %.1fus, wait
>>> %.1fus)\n",
>>>                 1e-6 * elapsed,
>>>                 1e-3 * submit,
>>>                 1e-3 * (elapsed - submit));
>> We don't need to change to igt_info upon igt_assert it will dump each 
>> igt_debug log.
>>>
>>> +        /* Assert if syncobj_wait took more than 1.2 seconds */
>> Explain by comment why 1.2 seconds  ?
>>> +        igt_assert((uint64_t)(elapsed - submit) < (uint64_t)(1.2 *
>>> +NSEC_PER_SEC));
>
> Why are we checking (elapsed-submit) here when sleep is calculated 
> only based on elapsed?

Hi Riana,

Because I wanted to assert on syncobj_wait time. We dont expect it to 
take in seconds for MI_STORE.

'elapsed' would have both submit and wait time.

See the sample log below.

  Execution took 1.202ms (submit 302.4us, wait 899.8us)

>
> Thanks,
> Riana
>> Your calculation is based upon the igt runner per test timeout which 
>> can change.
>> So better to stick with 1 second. Or better to get per test timeout 
>> via igt environment
>> variable.
>> Cc: Kamil
>> Is it possible to get the per test igt timeout value in igt test ?
>>
>> Thanks,
>> Anshuman
>>> +
>>>           syncobj_reset(fd, &syncobj, 1);
>>>
>>>           /*
>>> -- 
>>> 2.25.1
>>