[PATCH i-g-t] HAX-V7 test/kms_flip: Enable trace and logging for vblank event

Mohammed Khajapasha mohammed.khajapasha at intel.com
Tue Apr 14 06:19:18 UTC 2020


Enable trace and logging for vblank event

Signed-off-by: Mohammed Khajapasha <mohammed.khajapasha at intel.com>
---
 lib/igt_core.c                        |  6 ++-
 tests/intel-ci/fast-feedback.testlist |  6 ++-
 tests/kms_flip.c                      | 64 +++++++++++++++++++++++++--
 3 files changed, 69 insertions(+), 7 deletions(-)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 77862498..bc6ede1f 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -326,9 +326,11 @@ enum {
 static int igt_exitcode = IGT_EXIT_SUCCESS;
 static const char *command_str;
 
+#define LOG_BUFFER_SIZE	10*1024*1024
+
 static char* igt_log_domain_filter;
 static struct {
-	char *entries[256];
+	char *entries[LOG_BUFFER_SIZE];
 	uint8_t start, end;
 } log_buffer;
 static pthread_mutex_t log_buffer_mutex = PTHREAD_MUTEX_INITIALIZER;
@@ -2682,7 +2684,7 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
 	program_name = command_str;
 #endif
 
-	if (list_subtests && level <= IGT_LOG_WARN)
+	if (list_subtests && level < IGT_LOG_DEBUG)
 		return;
 
 	if (vasprintf(&line, format, args) == -1)
diff --git a/tests/intel-ci/fast-feedback.testlist b/tests/intel-ci/fast-feedback.testlist
index 2ccad438..3d3aaf80 100644
--- a/tests/intel-ci/fast-feedback.testlist
+++ b/tests/intel-ci/fast-feedback.testlist
@@ -104,8 +104,12 @@ igt at kms_cursor_legacy@basic-flip-before-cursor-legacy
 igt at kms_cursor_legacy@basic-flip-before-cursor-varying-size
 igt at kms_flip@basic-flip-vs-dpms
 igt at kms_flip@basic-flip-vs-modeset
-igt at kms_flip@basic-flip-vs-wf_vblank
 igt at kms_flip@basic-plain-flip
+igt at kms_flip@busy-flip
+igt at kms_flip@plain-flip-fb-recreate
+igt at kms_flip@flip-vs-expired-vblank
+igt at kms_flip@flip-vs-expired-vblank-interruptible
+igt at kms_flip@basic-flip-vs-wf_vblank
 igt at kms_force_connector_basic@force-connector-state
 igt at kms_force_connector_basic@force-edid
 igt at kms_force_connector_basic@force-load-detect
diff --git a/tests/kms_flip.c b/tests/kms_flip.c
index afaed69a..7bcaecf2 100755
--- a/tests/kms_flip.c
+++ b/tests/kms_flip.c
@@ -194,6 +194,35 @@ struct test_output {
 	double vblank_interval;
 };
 
+static void enable_trace_log(void)
+{
+	system("echo 0x135 > /sys/module/drm/parameters/debug");
+	system("echo 0 > /sys/kernel/debug/tracing/tracing_on");
+	system("echo 6144 > /sys/kernel/debug/tracing/buffer_total_size_kb");
+	system("echo > /sys/kernel/debug/tracing/trace");
+	system("echo nop > /sys/kernel/debug/tracing/current_tracer");
+	system("echo 1 > /sys/kernel/debug/tracing/events/drm/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/sched/enable");
+	/*
+	system("echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wait_task/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_wait/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/sched/sched_waking/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable");
+	*/
+	system("echo 1 > /sys/kernel/debug/tracing/events/i915/intel_pipe_enable/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/i915/intel_pipe_disable/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/i915/intel_pipe_update_start/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/i915/intel_pipe_update_end/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/i915/intel_pipe_update_vblank_evaded/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/events/i915/intel_update_plane/enable");
+	system("echo 1 > /sys/kernel/debug/tracing/tracing_on");
+}
+
+static void disable_trace_log(void)
+{
+	system("echo 0 > /sys/kernel/debug/tracing/tracing_on");
+	system("cat /sys/kernel/debug/tracing/trace");
+}
 
 static unsigned long gettime_us(void)
 {
@@ -306,6 +335,7 @@ static int do_page_flip(struct test_output *o, uint32_t fb_id, bool event)
 	if (ret == 0 && event)
 		set_flag(&o->pending_events, EVENT_FLIP);
 
+	igt_debug("Pending events after page flip 0x%x\n", o->pending_events);
 	return ret;
 }
 
@@ -346,6 +376,8 @@ static int __wait_for_vblank(unsigned int flags, int crtc_idx,
 	} else
 		ret = -errno;
 
+	igt_debug("ret:%d reply->sequence:%lu\n", ret, reply->sequence);
+
 	return ret;
 }
 
@@ -364,6 +396,8 @@ static int do_wait_for_vblank(struct test_output *o, int pipe_id,
 	if (ret == 0 && !(o->flags & TEST_VBLANK_BLOCK))
 		set_flag(&o->pending_events, EVENT_VBLANK);
 
+	igt_debug("Pending events after wait for vblank:0x%x\n", o->pending_events);
+
 	return ret;
 }
 
@@ -405,6 +439,8 @@ static void page_flip_handler(int fd, unsigned int frame, unsigned int sec,
 	int primary = (unsigned long)data & 1;
 	struct test_output *o = (void *)((unsigned long)data & ~ 1);
 
+	igt_debug("page_flip_handler for seq:%lu event at:%lu\n", frame, gettime_us());
+
 	if (++o->flip_count == o->count)
 		clear_flag(&o->pending_events, EVENT_FLIP);
 	if (primary)
@@ -427,11 +463,15 @@ static void *vblank_wait_thread_func(void *data)
 	struct vblank_reply reply;
 	int i;
 
+	igt_debug("Wait thread for vblank for block event\n");
+
 	for (i = 0; i < 32; i++) {
 		unsigned long start = gettime_us();
 		__wait_for_vblank(TEST_VBLANK_BLOCK, o->pipe, 20, (unsigned long)o, &reply);
-		if (gettime_us() - start > 2 * mode_frame_time(o))
+		if (gettime_us() - start > 2 * mode_frame_time(o)) {
+			igt_debug("Wait thread exit for vblank for block event at:%lu\n", gettime_us());
 			return (void*)1;
+		}
 	}
 
 	return 0;
@@ -477,6 +517,7 @@ static void vblank_handler(int fd, unsigned int frame, unsigned int sec,
 {
 	struct test_output *o = data;
 
+	igt_debug("vblank_handler event at:%lu\n",gettime_us());
 	clear_flag(&o->pending_events, EVENT_VBLANK);
 	event_handler(&o->vblank_state, frame, sec, usec);
 	fixup_premature_vblank_ts(o, &o->vblank_state);
@@ -525,6 +566,9 @@ static void check_state(const struct test_output *o, const struct event_state *e
 			  elapsed, expected, expected * 0.005,
 			  fabs((elapsed - expected) / expected) * 100);
 
+		if (fabs((elapsed - expected) / expected) <= 0.005)
+			disable_trace_log();
+
 		igt_assert_f(fabs((elapsed - expected) / expected) <= 0.005,
 			     "inconsistent %s ts/seq: last %.06f/%u, current %.06f/%u: elapsed=%.1fus expected=%.1fus\n",
 			     es->name, timeval_float(&es->last_ts), es->last_seq,
@@ -645,6 +689,8 @@ static int set_mode(struct test_output *o, uint32_t fb, int x, int y)
 	return 0;
 }
 
+
+
 /* Return mask of completed events. */
 static unsigned int run_test_step(struct test_output *o)
 {
@@ -689,12 +735,16 @@ static unsigned int run_test_step(struct test_output *o)
 		unsigned long start, end;
 
 		exp_seq = o->flip_state.current_seq;
+		/* enable tracing and logging */
 		start = gettime_us();
 		do_or_die(__wait_for_vblank(TEST_VBLANK_ABSOLUTE |
 					    TEST_VBLANK_BLOCK, o->pipe, exp_seq,
 					    0, &reply));
 		end = gettime_us();
-		igt_debug("Vblank took %luus\n", end - start);
+		igt_debug("exp_seq:%u vblank took start:%luus end:%luus %luus\n",	\
+				exp_seq, start, end, end - start);
+		if ((end - start) > 500)
+			disable_trace_log();
 		igt_assert(end - start < 500);
 		igt_assert_eq(reply.sequence, exp_seq);
 		igt_assert(timercmp(&reply.ts, &o->flip_state.last_ts, ==));
@@ -780,8 +830,12 @@ static unsigned int run_test_step(struct test_output *o)
 		}
 	}
 
-	if (do_flip && (o->flags & TEST_EBUSY))
-		igt_assert_eq(do_page_flip(o, new_fb_id, false), -EBUSY);
+	if (do_flip && (o->flags & TEST_EBUSY)) {
+		int ret = do_page_flip(o, new_fb_id, false);
+		if (ret != -EBUSY)
+			disable_trace_log();
+		igt_assert_eq(ret, -EBUSY);
+	}
 
 	if (do_flip && (o->flags & TEST_RMFB))
 		recreate_fb(o);
@@ -1583,6 +1637,8 @@ igt_main
 	igt_subtest("nonblocking-read")
 		test_nonblocking_read(drm_fd);
 
+	enable_trace_log();
+
 	for (i = 0; i < sizeof(tests) / sizeof (tests[0]); i++) {
 		igt_subtest_f("%s%s",
 			      tests[i].flags & TEST_BASIC ? "basic-" : "",
-- 
2.24.1



More information about the Intel-gfx-trybot mailing list