All of lore.kernel.org
 help / color / mirror / Atom feed
* [igt-dev] [PATCH i-g-t] lib/igt_core: Enable extra kernel logs for audio debug
@ 2019-03-14  5:09 Ashutosh Dixit
  2019-03-14  5:43 ` [igt-dev] ✗ Fi.CI.BAT: failure for " Patchwork
  2019-03-14 10:12 ` [igt-dev] [PATCH i-g-t] " Jani Nikula
  0 siblings, 2 replies; 5+ messages in thread
From: Ashutosh Dixit @ 2019-03-14  5:09 UTC (permalink / raw)
  To: igt-dev; +Cc: Lakshminarayana Vudum

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.

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
-- 
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

* [igt-dev] ✗ Fi.CI.BAT: failure for lib/igt_core: Enable extra kernel logs for audio debug
  2019-03-14  5:09 [igt-dev] [PATCH i-g-t] lib/igt_core: Enable extra kernel logs for audio debug Ashutosh Dixit
@ 2019-03-14  5:43 ` Patchwork
  2019-03-14 10:12 ` [igt-dev] [PATCH i-g-t] " Jani Nikula
  1 sibling, 0 replies; 5+ messages in thread
From: Patchwork @ 2019-03-14  5:43 UTC (permalink / raw)
  To: Ashutosh Dixit; +Cc: igt-dev

== Series Details ==

Series: lib/igt_core: Enable extra kernel logs for audio debug
URL   : https://patchwork.freedesktop.org/series/57974/
State : failure

== Summary ==

CI Bug Log - changes from CI_DRM_5743 -> IGTPW_2616
====================================================

Summary
-------

  **FAILURE**

  Serious unknown changes coming with IGTPW_2616 absolutely need to be
  verified manually.
  
  If you think the reported changes have nothing to do with the changes
  introduced in IGTPW_2616, please notify your bug team to allow them
  to document this new failure mode, which will reduce false positives in CI.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/57974/revisions/1/mbox/

Possible new issues
-------------------

  Here are the unknown changes that may have been introduced in IGTPW_2616:

### IGT changes ###

#### Possible regressions ####

  * igt@i915_module_load@reload:
    - fi-kbl-r:           PASS -> WARN +3
    - fi-apl-guc:         PASS -> WARN +3
    - fi-whl-u:           PASS -> WARN +3
    - fi-skl-6600u:       PASS -> WARN +3
    - fi-bdw-5557u:       PASS -> WARN +3
    - fi-bdw-gvtdvm:      PASS -> WARN +2
    - fi-snb-2520m:       PASS -> WARN +2

  * igt@i915_module_load@reload-no-display:
    - fi-bsw-kefka:       PASS -> WARN +3
    - fi-skl-6700k2:      PASS -> WARN +3
    - fi-elk-e7500:       PASS -> WARN +2
    - fi-bwr-2160:        NOTRUN -> WARN +2
    - fi-snb-2600:        PASS -> WARN +2
    - fi-hsw-peppy:       PASS -> WARN +3
    - fi-icl-u3:          PASS -> WARN +3
    - fi-ilk-650:         PASS -> WARN +2
    - fi-bxt-j4205:       PASS -> WARN +3
    - fi-ivb-3770:        PASS -> WARN +2

  * igt@i915_module_load@reload-with-fault-injection:
    - fi-kbl-8809g:       PASS -> WARN +3
    - fi-skl-gvtdvm:      PASS -> WARN +2
    - fi-byt-j1900:       PASS -> WARN +3
    - fi-cfl-guc:         PASS -> WARN +3
    - fi-skl-guc:         PASS -> WARN +3
    - fi-kbl-7560u:       NOTRUN -> WARN +3
    - fi-skl-6770hq:      PASS -> WARN +3
    - fi-kbl-guc:         PASS -> WARN +3
    - fi-cfl-8109u:       PASS -> WARN +3
    - fi-hsw-4770:        PASS -> WARN +3

  * igt@i915_pm_rpm@module-reload:
    - fi-cfl-8700k:       PASS -> WARN +3
    - fi-kbl-x1275:       PASS -> WARN +3
    - fi-kbl-7567u:       NOTRUN -> WARN +3
    - fi-skl-6260u:       PASS -> WARN +3
    - fi-byt-n2820:       PASS -> WARN +3

  
#### Suppressed ####

  The following results come from untrusted machines, tests, or statuses.
  They do not affect the overall result.

  * igt@i915_module_load@reload-with-fault-injection:
    - {fi-icl-y}:         PASS -> WARN +3

  * igt@i915_pm_rpm@module-reload:
    - {fi-skl-lmem}:      PASS -> WARN +3

  
Known issues
------------

  Here are the changes found in IGTPW_2616 that come from known issues:

### IGT changes ###

#### Issues hit ####

  * igt@gem_exec_basic@gtt-bsd:
    - fi-bwr-2160:        NOTRUN -> SKIP [fdo#109271] +103

  * igt@i915_selftest@live_execlists:
    - fi-apl-guc:         PASS -> INCOMPLETE [fdo#103927] / [fdo#109720]

  * igt@kms_busy@basic-flip-c:
    - fi-bwr-2160:        NOTRUN -> SKIP [fdo#109271] / [fdo#109278]

  * igt@kms_chamelium@common-hpd-after-suspend:
    - fi-kbl-7567u:       NOTRUN -> WARN [fdo#109380]

  * igt@kms_force_connector_basic@force-load-detect:
    - fi-kbl-7560u:       NOTRUN -> SKIP [fdo#109271] +33

  * igt@kms_pipe_crc_basic@nonblocking-crc-pipe-c:
    - fi-kbl-7567u:       NOTRUN -> SKIP [fdo#109271] +67

  * igt@kms_pipe_crc_basic@suspend-read-crc-pipe-a:
    - fi-blb-e6850:       PASS -> INCOMPLETE [fdo#107718]

  
#### Possible fixes ####

  * igt@gem_ctx_create@basic-files:
    - fi-kbl-7560u:       INCOMPLETE [fdo#103665] -> PASS

  
  {name}: This element is suppressed. This means it is ignored when computing
          the status of the difference (SUCCESS, WARNING, or FAILURE).

  [fdo#103665]: https://bugs.freedesktop.org/show_bug.cgi?id=103665
  [fdo#103927]: https://bugs.freedesktop.org/show_bug.cgi?id=103927
  [fdo#107718]: https://bugs.freedesktop.org/show_bug.cgi?id=107718
  [fdo#109271]: https://bugs.freedesktop.org/show_bug.cgi?id=109271
  [fdo#109278]: https://bugs.freedesktop.org/show_bug.cgi?id=109278
  [fdo#109380]: https://bugs.freedesktop.org/show_bug.cgi?id=109380
  [fdo#109720]: https://bugs.freedesktop.org/show_bug.cgi?id=109720


Participating hosts (47 -> 37)
------------------------------

  Additional (2): fi-kbl-7567u fi-bwr-2160 
  Missing    (12): fi-kbl-soraka fi-hsw-4770r fi-ilk-m540 fi-bsw-n3050 fi-hsw-4200u fi-byt-squawks fi-icl-u2 fi-bsw-cyan fi-gdg-551 fi-pnv-d510 fi-byt-clapper fi-bdw-samus 


Build changes
-------------

    * IGT: IGT_4884 -> IGTPW_2616

  CI_DRM_5743: e167a588f3614da02999797b9816744e39e31ad7 @ git://anongit.freedesktop.org/gfx-ci/linux
  IGTPW_2616: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_2616/
  IGT_4884: c46051337b972f8b5a302afb6f603df06fea527d @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_2616/
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

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

* Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Enable extra kernel logs for audio debug
  2019-03-14  5:09 [igt-dev] [PATCH i-g-t] lib/igt_core: Enable extra kernel logs for audio debug Ashutosh Dixit
  2019-03-14  5:43 ` [igt-dev] ✗ Fi.CI.BAT: failure for " Patchwork
@ 2019-03-14 10:12 ` Jani Nikula
  2019-03-19  5:05   ` Ashutosh Dixit
  1 sibling, 1 reply; 5+ messages in thread
From: Jani Nikula @ 2019-03-14 10:12 UTC (permalink / raw)
  To: Ashutosh Dixit, igt-dev; +Cc: Lakshminarayana Vudum

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

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

* Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Enable extra kernel logs for audio debug
  2019-03-14 10:12 ` [igt-dev] [PATCH i-g-t] " Jani Nikula
@ 2019-03-19  5:05   ` Ashutosh Dixit
  2019-03-19  7:36     ` Jani Nikula
  0 siblings, 1 reply; 5+ messages in thread
From: Ashutosh Dixit @ 2019-03-19  5:05 UTC (permalink / raw)
  To: Jani Nikula; +Cc: igt-dev, Lakshminarayana Vudum

On Thu, 14 Mar 2019 03:12:25 -0700, Jani Nikula wrote:
>
> 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.

Actually the v1 commit message is misleading. The real reason for the
"subtest granularity" is mentioned in the v2 commit message:

    "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."

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

I think there is no real way to enable such granularity with the approach
taken in this patch. Dynamic debug and tracing functions can be separated
out. But there will have to be a single function which enables both of
these together as has been done here. Unless we change the approach taken
here. But then what is that approach?

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

Perhaps something like this is better?

echo "file drivers/sound/soc/intel/skylake/* +p" > \
     <debugfs>/dynamic_debug/control

> Another review comment: Please don't use system(). Implement this in C,
> not shell script

Agreed. But let us agree on the overall approach taken in this patch first
and also take Chris' patch into account. If we are in agreement about the
high level approach making such changes is not an issue.

Please note that this patch is in response to the request to generate the
sort of logs mentioned in [1] in CI, so that hard to reproduce audio issues
can be debugged.

Thanks for the reviews!

[1] https://bugs.freedesktop.org/show_bug.cgi?id=109189#c4

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

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

* Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Enable extra kernel logs for audio debug
  2019-03-19  5:05   ` Ashutosh Dixit
@ 2019-03-19  7:36     ` Jani Nikula
  0 siblings, 0 replies; 5+ messages in thread
From: Jani Nikula @ 2019-03-19  7:36 UTC (permalink / raw)
  To: Ashutosh Dixit; +Cc: igt-dev, Lakshminarayana Vudum

On Mon, 18 Mar 2019, Ashutosh Dixit <ashutosh.dixit@intel.com> wrote:
> On Thu, 14 Mar 2019 03:12:25 -0700, Jani Nikula wrote:
>>
>> 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.
>
> Actually the v1 commit message is misleading. The real reason for the
> "subtest granularity" is mentioned in the v2 commit message:
>
>     "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."
>
>> OTOH I think we do need more granularity in enabling the dynamic debug
>> and the tracing separately.
>
> I think there is no real way to enable such granularity with the approach
> taken in this patch. Dynamic debug and tracing functions can be separated
> out. But there will have to be a single function which enables both of
> these together as has been done here. Unless we change the approach taken
> here. But then what is that approach?

I fail to see why enabling completely orthogonal features such as
dynamic debug and tracing should be conflated into a single function.

>> The *skl* style wildcard dynamid debug enables/disables also seem not
>> specific enough.
>
> Perhaps something like this is better?
>
> echo "file drivers/sound/soc/intel/skylake/* +p" > \
>      <debugfs>/dynamic_debug/control

I think it should include more than just skylake, but the point was, the
original wildcards included *everything*, not just sound.

>
>> Another review comment: Please don't use system(). Implement this in C,
>> not shell script
>
> Agreed. But let us agree on the overall approach taken in this patch first
> and also take Chris' patch into account. If we are in agreement about the
> high level approach making such changes is not an issue.
>
> Please note that this patch is in response to the request to generate the
> sort of logs mentioned in [1] in CI, so that hard to reproduce audio issues
> can be debugged.

That's fine and good, but please let's not restrict ourselves to the
audio use case. Imagine having to debug issues other than audio, with
different combinations of dynamic debug, tracing, and perhaps something
else required.

I don't think we want igt_subtest_extra_klog() which enables
*everything* when the extra debugs to be enabled are really test
specific. Audio tests need these. Some other tests might need something
else *without* any audio tracing/debugging. Etc.


BR,
Jani.



>
> Thanks for the reviews!
>
> [1] https://bugs.freedesktop.org/show_bug.cgi?id=109189#c4
>
> --
> Ashutosh Dixit, Intel Open Source Graphics Center

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

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

end of thread, other threads:[~2019-03-19  7:34 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-03-14  5:09 [igt-dev] [PATCH i-g-t] lib/igt_core: Enable extra kernel logs for audio debug Ashutosh Dixit
2019-03-14  5:43 ` [igt-dev] ✗ Fi.CI.BAT: failure for " Patchwork
2019-03-14 10:12 ` [igt-dev] [PATCH i-g-t] " Jani Nikula
2019-03-19  5:05   ` Ashutosh Dixit
2019-03-19  7:36     ` Jani Nikula

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.