[igt-dev] [i-g-t RFC v1] tests/i915_pm_rpm: Add suspend-resume-latency test

[Martin Peres]

On 25/03/2021 07:37, Jigar Bhatt wrote:
> Measuring the suspend-resume time using
> tracefs, writing Suspend Started, Suspend Completed,
> Resume Ended timestamp into tracefs file.
> After writing it's reading from tracefs file and
> measuring different, suspend and resume ,
> individual must be less than 1 sec.

Ahhhh, finally someone got to it! Thanks so much for this, as I was 
feeling bad for not having had the time to write it myself...

Comments are inlined!

> 
> v1:
> - Add limits.h and time.h
> 
> Signed-off-by: Jigar Bhatt <jigar.bhatt at intel.com>
> ---
>   tests/i915/i915_pm_rpm.c | 86 ++++++++++++++++++++++++++++++++++++++++++++++++
>   1 file changed, 86 insertions(+)
> 
> diff --git a/tests/i915/i915_pm_rpm.c b/tests/i915/i915_pm_rpm.c
> index 694a3ea..3cc9259 100644
> --- a/tests/i915/i915_pm_rpm.c
> +++ b/tests/i915/i915_pm_rpm.c
> @@ -53,6 +53,8 @@
>   #include "igt_debugfs.h"
>   #include "igt_device.h"
>   #include "igt_edid.h"
> +#include "limits.h"
> +#include "time.h"
>   
>   #define MSR_PC8_RES	0x630
>   #define MSR_PC9_RES	0x631
> @@ -1998,6 +2000,85 @@ static int opt_handler(int opt, int opt_index, void *data)
>   	return IGT_OPT_HANDLER_SUCCESS;
>   }
>   
> +static void dpms_off(struct mode_set_data *data)
> +{
> +	for (int i = 0; i < data->res->count_connectors; i++) {
> +		drmModeConnectorPtr c = data->connectors[i];
> +
> +		kmstest_set_connector_dpms(drm_fd, c, DRM_MODE_DPMS_OFF);
> +	}
> +}
> +
> +static void dpms_on(struct mode_set_data *data)
> +{
> +	igt_display_t display;
> +
> +	igt_display_require(&display, drm_fd);
> +	for (int i = 0; i < data->res->count_connectors; i++) {
> +		drmModeConnectorPtr c = data->connectors[i];
> +
> +		kmstest_set_connector_dpms(drm_fd, c, DRM_MODE_DPMS_ON);
> +	}
> +}
> +
> +static uint32_t get_trace_timestamp(char *dc_data)
> +{
> +	char *e;
> +	long ret;
> +	char *s = strchr(dc_data, ':');
> +
> +	assert(s);
> +	s++;
> +	ret = strtol(s, &e, 10);
> +	assert(((ret != LONG_MIN && ret != LONG_MAX) || errno != ERANGE) &&
> +		e > s && *e == '\n' && ret >= 0);it is impossible to know from the userspace how long it will take for the machine to go to sleep
> +	return ret;
> +}
> +
> +static long get_timestamp(void)
> +{
> +	struct timespec start;
> +
> +	clock_gettime(CLOCK_MONOTONIC_RAW, &start);
> +	return (start.tv_sec * 1000000 + (start.tv_nsec / 1000));
> +}

By using a monotonic clock, you are measuring the kernel overhead of 
going to sleep and resuming, and not the time spent off.

I think you need to explain why you are using it in the commit message 
(we assume the firmware is basically immediate, as measuring anything 
there is trickyMartin and measuring the wall time is tricky due to 
unreliable RTC clocks, and the inability to start the wake up 
milliseconds after suspend without a kernel patch).

> +
> +static void read_trace(void)
> +{
> +	int fd;
> +	char buf[4096];
> +
> +	fd = open("/sys/kernel/debug/tracing/trace", O_RDONLY);
> +	igt_assert(fd > 0);
> +	igt_assert(read(fd, buf, sizeof(buf)));
> +	igt_assert(((float)(get_trace_timestamp(strstr(buf, "Suspend_Completed")) -
> +			get_trace_timestamp(strstr(buf, "Suspend_Started"))) / 1000000) < 1);
> +	igt_assert(((float)(get_trace_timestamp(strstr(buf, "Resume_Ended")) -
> +			get_trace_timestamp(strstr(buf, "Suspend_Completed"))) / 1000000) < 1);
> +	close(fd);
> +}
> +
> +static void test_suspend_resume_latency(struct mode_set_data *data)
> +{
> +	int fd;
> +	char msg[400];
> +
> +	fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY);
> +	igt_assert(fd > 0);
> +	snprintf(msg, 100, "Suspend_Started : %ld", get_timestamp());
> +	write(fd, msg, strlen(msg));
> +	dpms_off(data);
> +	igt_assert(igt_wait_for_pm_status(IGT_RUNTIME_PM_STATUS_SUSPENDED));
> +	snprintf(msg, 100, "Suspend_Completed : %ld", get_timestamp());
> +	write(fd, msg, strlen(msg));
> +	dpms_on(data);
> +	igt_assert(igt_wait_for_pm_status(IGT_RUNTIME_PM_STATUS_ACTIVE));
> +	snprintf(msg, 100, "Resume_Ended : %ld", get_timestamp());
> +	write(fd, msg, strlen(msg));
> +	close(fd);
> +	read_trace();
> +}

Why do you change the DPMS state during the state? Wouldn't you want to 
have two tests: one with dpms on, and one with dpms off?

Martin

> +
>   const char *help_str =
>   	"  --stress\t\tMake the stress-tests more stressful.\n"
>   	"  --stay\t\tDisable all screen and try to go into runtime pm. Useful for debugging.";
> @@ -2147,6 +2228,11 @@ igt_main_args("", long_options, help_str, opt_handler, NULL)
>   		pm_test_caching();
>   	}
>   
> +	igt_subtest("suspend-resume-latency") {
> +		test_suspend_resume_latency(&ms_data);
> +	}
> +
> +
>   	igt_fixture
>   		teardown_environment(false);
>   
>