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

[Kamil Konieczny]

Hi,

On 2024-09-20 at 08:31:37 +0000, 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));

Btw is this (elapsed - submit) correct? In line above it was scaled with two
different factors, first with 1e-6 second with 1e-3.

> 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 ?

What you mean 'per test'? For BAT it is fixed and should not exceed 10s (or 20, I do
not remember exact number here).

As for enviroment, you could add it for this specfic test.
It could also take into account simulation.

As for not printing debugfs imho best way (untill it will debugged and fixed)
would be to use igt_assert_f and print what you want there, for example:

	f_elapsed = 1e-6 * elapsed;
	f_submit = 1e-3 * submit;
	igt_assert_f(f_elapsed < 1.2, "Execution too slow, elapsed=%.3fms submit=%.3fms\n",
		     f_elapsed, f_submit);

Regards,
Kamil

> 
> Thanks,
> Anshuman 
> > +
> >  		syncobj_reset(fd, &syncobj, 1);
> > 
> >  		/*
> > --
> > 2.25.1
>