[igt-dev] [CI] lib/igt_core: Enable extra kernel logs for audio debug

* [igt-dev] [CI] lib/igt_core: Enable extra kernel logs for audio debug
@ 2019-03-16  3:49 Ashutosh Dixit
  2019-03-18 10:53 ` [igt-dev] ✓ Fi.CI.BAT: success for lib/igt_core: Enable extra kernel logs for audio debug (rev3) Patchwork
                   ` (2 more replies)
  0 siblings, 3 replies; 5+ messages in thread
From: Ashutosh Dixit @ 2019-03-16  3:49 UTC (permalink / raw)
  To: igt-dev

For debug of audio issues in power management and driver reload tests,
additional kernel logs may be useful, both in dmesg as well as
ftrace. Add the infrastructure to generate these logs and enable these
logs for selected sub-tests.

At present igt_runner and other CI infrastructure does not capture the
ftrace buffer. Therefore, to avoid changes to igt_runner and the CI
infrastructure the ftrace buffer is dumped to stdout. This is done
after each sub-test so the ftrace output for a subtest can be
associated with that subtest.

Cc: Martin Peres <martin.peres@intel.com>
Cc: Cezary Rojewski <cezary.rojewski@intel.com>
Signed-off-by: Ashutosh Dixit <ashutosh.dixit@intel.com>
---
 lib/igt_core.c                | 78 +++++++++++++++++++++++++++++++++++
 lib/igt_core.h                | 22 ++++++++++
 tests/i915/i915_module_load.c |  6 +--
 tests/i915/i915_pm_rpm.c      | 14 +++----
 tests/i915/i915_suspend.c     | 22 +++++-----
 5 files changed, 121 insertions(+), 21 deletions(-)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 6eb4798e..b371b8ec 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -2434,3 +2434,81 @@ err:
 
 	return -1;
 }
+
+static void igt_clear_ftrace_buf(void)
+{
+	system("echo > /sys/kernel/debug/tracing/trace");
+}
+
+static const char *audio_klog_en[] = {
+	"echo -n \"module *snd* +p\" > /sys/kernel/debug/dynamic_debug/control",
+	"echo -n \"module *soc* +p\" > /sys/kernel/debug/dynamic_debug/control",
+	"echo -n \"module *skl* +p\" > /sys/kernel/debug/dynamic_debug/control",
+	"echo -n \"module *hda* +p\" > /sys/kernel/debug/dynamic_debug/control",
+	"echo -n \"module *bxt* +p\" > /sys/kernel/debug/dynamic_debug/control",
+
+	"F=/sys/kernel/debug/tracing/events/sst/enable; \
+					[ -f $F ] && echo 1 > $F",
+	"F=/sys/kernel/debug/tracing/events/intel-sst/enable; \
+					[ -f $F ] && echo 1 > $F",
+	"F=/sys/kernel/debug/tracing/events/asoc/enable; \
+					[ -f $F ] && echo 1 > $F",
+	"F=/sys/kernel/debug/tracing/events/i2c/enable; \
+					[ -f $F ] && echo 1 > $F",
+	"F=/sys/kernel/debug/tracing/events/hda/enable; \
+					[ -f $F ] && echo 1 > $F",
+	"F=/sys/kernel/debug/tracing/events/hda_controller/enable; \
+					[ -f $F ] && echo 1 > $F",
+	"F=/sys/kernel/debug/tracing/events/hda_intel/enable; \
+					[ -f $F ] && echo 1 > $F",
+	"echo 1 > /sys/kernel/debug/tracing/tracing_on",
+};
+
+bool igt_enable_audio_klog(void)
+{
+	int i;
+
+	igt_clear_ftrace_buf();
+
+	for (i = 0; i < sizeof(audio_klog_en)/sizeof(char*); i++)
+		system(audio_klog_en[i]);
+
+	return true;
+}
+
+static const char *audio_klog_dis[] = {
+	"echo -n \"module *snd* -p\" > /sys/kernel/debug/dynamic_debug/control",
+	"echo -n \"module *soc* -p\" > /sys/kernel/debug/dynamic_debug/control",
+	"echo -n \"module *skl* -p\" > /sys/kernel/debug/dynamic_debug/control",
+	"echo -n \"module *hda* -p\" > /sys/kernel/debug/dynamic_debug/control",
+	"echo -n \"module *bxt* -p\" > /sys/kernel/debug/dynamic_debug/control",
+
+	"F=/sys/kernel/debug/tracing/events/sst/enable; \
+					[ -f $F ] && echo 0 > $F",
+	"F=/sys/kernel/debug/tracing/events/intel-sst/enable; \
+					[ -f $F ] && echo 0 > $F",
+	"F=/sys/kernel/debug/tracing/events/asoc/enable; \
+					[ -f $F ] && echo 0 > $F",
+	"F=/sys/kernel/debug/tracing/events/i2c/enable; \
+					[ -f $F ] && echo 0 > $F",
+	"F=/sys/kernel/debug/tracing/events/hda/enable; \
+					[ -f $F ] && echo 0 > $F",
+	"F=/sys/kernel/debug/tracing/events/hda_controller/enable; \
+					[ -f $F ] && echo 0 > $F",
+	"F=/sys/kernel/debug/tracing/events/hda_intel/enable; \
+					[ -f $F ] && echo 0 > $F",
+	"echo 0 > /sys/kernel/debug/tracing/tracing_on",
+};
+
+void igt_disable_audio_klog(void)
+{
+	int i;
+
+	/* Dump ftrace buffer to stdout */
+	system("cat /sys/kernel/debug/tracing/trace");
+
+	for (i = 0; i < sizeof(audio_klog_dis)/sizeof(char*); i++)
+		system(audio_klog_dis[i]);
+
+	igt_clear_ftrace_buf();
+}
diff --git a/lib/igt_core.h b/lib/igt_core.h
index 47ffd9e7..fbba6cf3 100644
--- a/lib/igt_core.h
+++ b/lib/igt_core.h
@@ -222,6 +222,28 @@ bool __igt_run_subtest(const char *subtest_name);
 #define igt_subtest_f(f...) \
 	__igt_subtest_f(igt_tokencat(__tmpchar, __LINE__), f)
 
+bool igt_enable_audio_klog(void);
+void igt_disable_audio_klog(void);
+
+/* Like igt_subtest but with extra kernel logs */
+#define igt_subtest_audio_klog(name) \
+	for (; __igt_run_subtest((name)) && igt_enable_audio_klog() && \
+		     ((sigsetjmp(igt_subtest_jmpbuf, 1) == 0) ? true : \
+		      (igt_disable_audio_klog(), false)); \
+	     igt_success())
+
+#define __igt_subtest_audio_klog_f(tmp, format...) \
+	for (char tmp [256]; \
+	     snprintf(tmp , sizeof(tmp), format), \
+		     __igt_run_subtest(tmp) && igt_enable_audio_klog() && \
+		     ((sigsetjmp(igt_subtest_jmpbuf, 1) == 0) ? true : \
+		      (igt_disable_audio_klog(), false)); \
+	     igt_success())
+
+/* Like igt_subtest_f but with extra kernel logs */
+#define igt_subtest_audio_klog_f(f...) \
+	__igt_subtest_audio_klog_f(igt_tokencat(__tmpchar, __LINE__), f)
+
 const char *igt_subtest_name(void);
 bool igt_only_list_subtests(void);
 
diff --git a/tests/i915/i915_module_load.c b/tests/i915/i915_module_load.c
index 7fe83520..dcbdd2dc 100644
--- a/tests/i915/i915_module_load.c
+++ b/tests/i915/i915_module_load.c
@@ -326,7 +326,7 @@ hda_dynamic_debug(bool enable)
 
 igt_main
 {
-	igt_subtest("reload") {
+	igt_subtest_audio_klog("reload") {
 		int load_error;
 
 		igt_i915_driver_unload();
@@ -343,7 +343,7 @@ igt_main
 		/* only default modparams, can leave module loaded */
 	}
 
-	igt_subtest("reload-no-display") {
+	igt_subtest_audio_klog("reload-no-display") {
 		igt_i915_driver_unload();
 
 		igt_assert_eq(igt_i915_driver_load("disable_display=1"), 0);
@@ -351,7 +351,7 @@ igt_main
 		igt_i915_driver_unload();
 	}
 
-	igt_subtest("reload-with-fault-injection") {
+	igt_subtest_audio_klog("reload-with-fault-injection") {
 		int i = 0;
 
 		igt_i915_driver_unload();
diff --git a/tests/i915/i915_pm_rpm.c b/tests/i915/i915_pm_rpm.c
index 759c76ea..03fa3806 100644
--- a/tests/i915/i915_pm_rpm.c
+++ b/tests/i915/i915_pm_rpm.c
@@ -1967,7 +1967,7 @@ int main(int argc, char *argv[])
 	igt_subtest_init_parse_opts(&argc, argv, "", long_options,
 				    help_str, opt_handler, NULL);
 
-	igt_subtest("basic-rte") {
+	igt_subtest_audio_klog("basic-rte") {
 		igt_assert(setup_environment());
 		basic_subtest();
 	}
@@ -2064,15 +2064,15 @@ int main(int argc, char *argv[])
 				WAIT_STATUS | WAIT_EXTRA);
 
 	/* System suspend */
-	igt_subtest("system-suspend-devices")
+	igt_subtest_audio_klog("system-suspend-devices")
 		system_suspend_subtest(SUSPEND_STATE_MEM, SUSPEND_TEST_DEVICES);
-	igt_subtest("system-suspend")
+	igt_subtest_audio_klog("system-suspend")
 		system_suspend_subtest(SUSPEND_STATE_MEM, SUSPEND_TEST_NONE);
-	igt_subtest("system-suspend-execbuf")
+	igt_subtest_audio_klog("system-suspend-execbuf")
 		system_suspend_execbuf_subtest();
-	igt_subtest("system-suspend-modeset")
+	igt_subtest_audio_klog("system-suspend-modeset")
 		system_suspend_modeset_subtest();
-	igt_subtest("system-hibernate-devices")
+	igt_subtest_audio_klog("system-hibernate-devices")
 		system_suspend_subtest(SUSPEND_STATE_DISK,
 				       SUSPEND_TEST_DEVICES);
 	igt_subtest("system-hibernate")
@@ -2095,7 +2095,7 @@ int main(int argc, char *argv[])
 	igt_fixture
 		teardown_environment();
 
-	igt_subtest("module-reload") {
+	igt_subtest_audio_klog("module-reload") {
 		igt_debug("Reload w/o display\n");
 		igt_i915_driver_unload();
 		igt_assert_eq(igt_i915_driver_load("disable_display=1 mmio_debug=-1"), 0);
diff --git a/tests/i915/i915_suspend.c b/tests/i915/i915_suspend.c
index cd7cf967..0235aa93 100644
--- a/tests/i915/i915_suspend.c
+++ b/tests/i915/i915_suspend.c
@@ -205,37 +205,37 @@ igt_main
 	igt_fixture
 		fd = drm_open_driver(DRIVER_INTEL);
 
-	igt_subtest("fence-restore-tiled2untiled")
+	igt_subtest_audio_klog("fence-restore-tiled2untiled")
 		test_fence_restore(fd, true, false);
 
-	igt_subtest("fence-restore-untiled")
+	igt_subtest_audio_klog("fence-restore-untiled")
 		test_fence_restore(fd, false, false);
 
-	igt_subtest("debugfs-reader")
+	igt_subtest_audio_klog("debugfs-reader")
 		test_debugfs_reader(false);
 
-	igt_subtest("sysfs-reader")
+	igt_subtest_audio_klog("sysfs-reader")
 		test_sysfs_reader(false);
 
-	igt_subtest("shrink")
+	igt_subtest_audio_klog("shrink")
 		test_shrink(fd, SUSPEND_STATE_MEM);
 
-	igt_subtest("forcewake")
+	igt_subtest_audio_klog("forcewake")
 		test_forcewake(fd, false);
 
-	igt_subtest("fence-restore-tiled2untiled-hibernate")
+	igt_subtest_audio_klog("fence-restore-tiled2untiled-hibernate")
 		test_fence_restore(fd, true, true);
 
-	igt_subtest("fence-restore-untiled-hibernate")
+	igt_subtest_audio_klog("fence-restore-untiled-hibernate")
 		test_fence_restore(fd, false, true);
 
-	igt_subtest("debugfs-reader-hibernate")
+	igt_subtest_audio_klog("debugfs-reader-hibernate")
 		test_debugfs_reader(true);
 
-	igt_subtest("sysfs-reader-hibernate")
+	igt_subtest_audio_klog("sysfs-reader-hibernate")
 		test_sysfs_reader(true);
 
-	igt_subtest("forcewake-hibernate")
+	igt_subtest_audio_klog("forcewake-hibernate")
 		test_forcewake(fd, true);
 
 	igt_fixture
-- 
2.21.0

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply related	[flat|nested] 5+ messages in thread