[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