Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Enable extra kernel logs for audio debug

[Jani Nikula <jani.nikula@linux.intel.com>]

On Wed, 13 Mar 2019, Ashutosh Dixit <ashutosh.dixit@intel.com> wrote:
> 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 which can be
> enabled/disabled at sub-test granularity. Also enable these logs for
> selected sub-tests. The ftrace buffer is dumped to stdout to avoid
> changes in igt_runner and other CI infrastructure.

I think I'd just provide the helpers and add them in igt_fixture instead
of introducing new "extra klog" subtest helpers. I don't think we need
that granularity.

OTOH I think we do need more granularity in enabling the dynamic debug
and the tracing separately.

The *skl* style wildcard dynamid debug enables/disables also seem not
specific enough.

BR,
Jani.

>
> 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                | 71 +++++++++++++++++++++++++++++++++++
>  lib/igt_core.h                | 22 +++++++++++
>  tests/i915/i915_module_load.c |  6 +--
>  tests/i915/i915_pm_rpm.c      | 12 +++---
>  tests/i915/i915_suspend.c     | 22 +++++------
>  5 files changed, 113 insertions(+), 20 deletions(-)
>
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index 6eb4798e..f61da57d 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -2434,3 +2434,74 @@ err:
>  
>  	return -1;
>  }
> +
> +static const char *clear_cmd[] = {
> +	"echo > /sys/kernel/debug/tracing/trace",
> +};
> +
> +static void igt_clear_ftrace_buf(void)
> +{
> +	int i;
> +
> +	for (i = 0; i < sizeof(clear_cmd)/sizeof(char*); i++)
> +		system(clear_cmd[i]);
> +}
> +
> +static const char *enable_cmd[] = {
> +	"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",
> +
> +	"echo 1 > /sys/kernel/debug/tracing/events/sst/enable",
> +	"echo 1 > /sys/kernel/debug/tracing/events/intel-sst/enable",
> +	"echo 1 > /sys/kernel/debug/tracing/events/asoc/enable",
> +	"echo 1 > /sys/kernel/debug/tracing/events/i2c/enable",
> +	"echo 1 > /sys/kernel/debug/tracing/events/hda/enable",
> +	"echo 1 > /sys/kernel/debug/tracing/events/hda_controller/enable",
> +	"echo 1 > /sys/kernel/debug/tracing/events/hda_intel/enable",
> +	"echo 1 > /sys/kernel/debug/tracing/tracing_on",
> +};
> +
> +bool igt_enable_extra_klog(void)
> +{
> +	int i;
> +
> +	igt_clear_ftrace_buf();
> +
> +	for (i = 0; i < sizeof(enable_cmd)/sizeof(char*); i++)
> +		system(enable_cmd[i]);
> +
> +	return true;
> +}
> +
> +static const char *disable_cmd[] = {
> +	"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",
> +
> +	"echo 0 > /sys/kernel/debug/tracing/events/sst/enable",
> +	"echo 0 > /sys/kernel/debug/tracing/events/intel-sst/enable",
> +	"echo 0 > /sys/kernel/debug/tracing/events/asoc/enable",
> +	"echo 0 > /sys/kernel/debug/tracing/events/i2c/enable",
> +	"echo 0 > /sys/kernel/debug/tracing/events/hda/enable",
> +	"echo 0 > /sys/kernel/debug/tracing/events/hda_controller/enable",
> +	"echo 0 > /sys/kernel/debug/tracing/events/hda_intel/enable",
> +	"echo 0 > /sys/kernel/debug/tracing/tracing_on",
> +};
> +
> +void igt_disable_extra_klog(void)
> +{
> +	int i;
> +
> +	/* Dump ftrace buffer to stdout */
> +	system("cat /sys/kernel/debug/tracing/trace");
> +
> +	for (i = 0; i < sizeof(disable_cmd)/sizeof(char*); i++)
> +		system(disable_cmd[i]);
> +
> +	igt_clear_ftrace_buf();
> +}
> diff --git a/lib/igt_core.h b/lib/igt_core.h
> index 47ffd9e7..3e203c65 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_extra_klog(void);
> +void igt_disable_extra_klog(void);
> +
> +/* Like igt_subtest but with extra kernel logs */
> +#define igt_subtest_extra_klog(name) \
> +	for (; __igt_run_subtest((name)) && igt_enable_extra_klog() && \
> +		     ((sigsetjmp(igt_subtest_jmpbuf, 1) == 0) ? true : \
> +		      (igt_disable_extra_klog(), false)); \
> +	     igt_success())
> +
> +#define __igt_subtest_extra_klog_f(tmp, format...) \
> +	for (char tmp [256]; \
> +	     snprintf(tmp , sizeof(tmp), format), \
> +		     __igt_run_subtest(tmp) && igt_enable_extra_klog() && \
> +		     ((sigsetjmp(igt_subtest_jmpbuf, 1) == 0) ? true : \
> +		      (igt_disable_extra_klog(), false)); \
> +	     igt_success())
> +
> +/* Like igt_subtest_f but with extra kernel logs */
> +#define igt_subtest_extra_klog_f(f...) \
> +	__igt_subtest_extra_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..e6f78ede 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_extra_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_extra_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_extra_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..9b034e3d 100644
> --- a/tests/i915/i915_pm_rpm.c
> +++ b/tests/i915/i915_pm_rpm.c
> @@ -2064,15 +2064,15 @@ int main(int argc, char *argv[])
>  				WAIT_STATUS | WAIT_EXTRA);
>  
>  	/* System suspend */
> -	igt_subtest("system-suspend-devices")
> +	igt_subtest_extra_klog("system-suspend-devices")
>  		system_suspend_subtest(SUSPEND_STATE_MEM, SUSPEND_TEST_DEVICES);
> -	igt_subtest("system-suspend")
> +	igt_subtest_extra_klog("system-suspend")
>  		system_suspend_subtest(SUSPEND_STATE_MEM, SUSPEND_TEST_NONE);
> -	igt_subtest("system-suspend-execbuf")
> +	igt_subtest_extra_klog("system-suspend-execbuf")
>  		system_suspend_execbuf_subtest();
> -	igt_subtest("system-suspend-modeset")
> +	igt_subtest_extra_klog("system-suspend-modeset")
>  		system_suspend_modeset_subtest();
> -	igt_subtest("system-hibernate-devices")
> +	igt_subtest_extra_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_extra_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..cd58801e 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_extra_klog("fence-restore-tiled2untiled")
>  		test_fence_restore(fd, true, false);
>  
> -	igt_subtest("fence-restore-untiled")
> +	igt_subtest_extra_klog("fence-restore-untiled")
>  		test_fence_restore(fd, false, false);
>  
> -	igt_subtest("debugfs-reader")
> +	igt_subtest_extra_klog("debugfs-reader")
>  		test_debugfs_reader(false);
>  
> -	igt_subtest("sysfs-reader")
> +	igt_subtest_extra_klog("sysfs-reader")
>  		test_sysfs_reader(false);
>  
> -	igt_subtest("shrink")
> +	igt_subtest_extra_klog("shrink")
>  		test_shrink(fd, SUSPEND_STATE_MEM);
>  
> -	igt_subtest("forcewake")
> +	igt_subtest_extra_klog("forcewake")
>  		test_forcewake(fd, false);
>  
> -	igt_subtest("fence-restore-tiled2untiled-hibernate")
> +	igt_subtest_extra_klog("fence-restore-tiled2untiled-hibernate")
>  		test_fence_restore(fd, true, true);
>  
> -	igt_subtest("fence-restore-untiled-hibernate")
> +	igt_subtest_extra_klog("fence-restore-untiled-hibernate")
>  		test_fence_restore(fd, false, true);
>  
> -	igt_subtest("debugfs-reader-hibernate")
> +	igt_subtest_extra_klog("debugfs-reader-hibernate")
>  		test_debugfs_reader(true);
>  
> -	igt_subtest("sysfs-reader-hibernate")
> +	igt_subtest_extra_klog("sysfs-reader-hibernate")
>  		test_sysfs_reader(true);
>  
> -	igt_subtest("forcewake-hibernate")
> +	igt_subtest_extra_klog("forcewake-hibernate")
>  		test_forcewake(fd, true);
>  
>  	igt_fixture

-- 
Jani Nikula, Intel Open Source Graphics Center
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev