All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
@ 2015-11-16 13:22 Joonas Lahtinen
  2015-11-16 14:06 ` Chris Wilson
                   ` (2 more replies)
  0 siblings, 3 replies; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-16 13:22 UTC (permalink / raw)
  To: Intel graphics driver community testing & development; +Cc: Thomas Wood

Cc: Thomas Wood <thomas.wood@intel.com>
Cc: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Damien Lespiau <damien.lespiau@intel.com>
Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
---
 lib/igt_core.c         | 113 ++++++++++++++++++++++++++++++++++++++++++++++---
 tests/Makefile.sources |   1 +
 tests/igt_capture.c    |  93 ++++++++++++++++++++++++++++++++++++++++
 3 files changed, 200 insertions(+), 7 deletions(-)
 create mode 100644 tests/igt_capture.c

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 04a0ab2..e73175a 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -211,6 +211,8 @@
  * "--help" command line option.
  */
 
+#define IGT_KMSG_CAPTURE_DUMP_BUF_SIZE		4096
+
 static unsigned int exit_handler_count;
 const char *igt_interactive_debug;
 
@@ -247,6 +249,10 @@ enum {
 static int igt_exitcode = IGT_EXIT_SUCCESS;
 static const char *command_str;
 
+static int igt_kmsg_capture_fd;
+static char* igt_kmsg_capture_dump_buf;
+static pthread_mutex_t kmsg_mutex = PTHREAD_MUTEX_INITIALIZER;
+
 static char* igt_log_domain_filter;
 static struct {
 	char *entries[256];
@@ -312,6 +318,71 @@ static void _igt_log_buffer_dump(void)
 	pthread_mutex_unlock(&log_buffer_mutex);
 }
 
+static void _igt_kmsg_capture_reset(void)
+{
+	if (igt_kmsg_capture_fd == -1)
+		return;
+
+	pthread_mutex_lock(&kmsg_mutex);
+
+	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
+
+	pthread_mutex_unlock(&kmsg_mutex);
+}
+
+static void _igt_kmsg_capture_dump(void)
+{
+	size_t nbytes;
+	int nlines;
+	char *p;
+	char *p0;
+	int c;
+
+	if (igt_kmsg_capture_fd == -1 ||
+	    igt_kmsg_capture_dump_buf == NULL)
+		return;
+
+	pthread_mutex_lock(&kmsg_mutex);
+
+
+	nlines = 0;
+	do {
+		errno = 0;
+		nbytes = read(igt_kmsg_capture_fd,
+			      igt_kmsg_capture_dump_buf,
+			      IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
+
+		if (nbytes == -1)
+			continue;
+
+		if (!nlines)
+			fprintf(stderr, "**** KMSG ****\n");
+
+		p = p0 = strchr(igt_kmsg_capture_dump_buf, ';') + 1;
+		while (p - p0 < nbytes) {
+			if (*p != '\\') {
+				fputc(*p++, stderr);
+				continue;
+			}
+			sscanf(p, "\\x%x", &c);
+			fputc(c, stderr);
+			p += 4;
+		}
+		//fputs(strchr(igt_kmsg_capture_dump_buf, ';') + 1, stderr);
+		nlines++;
+	} while(errno == 0);
+
+	if (nlines)
+		fprintf(stderr, "****  END  ****\n");
+	else
+		fprintf(stderr, "No kmsg.\n");
+
+	if (errno != EAGAIN)
+		fprintf(stderr, "Incomplete kmsg.\n");
+
+	pthread_mutex_unlock(&kmsg_mutex);
+}
+
 __attribute__((format(printf, 1, 2)))
 static void kmsg(const char *format, ...)
 #define KERN_EMER	"<0>"
@@ -330,11 +401,15 @@ static void kmsg(const char *format, ...)
 	if (file == NULL)
 		return;
 
+	pthread_mutex_lock(&kmsg_mutex);
+
 	va_start(ap, format);
 	vfprintf(file, format, ap);
 	va_end(ap);
 
 	fclose(file);
+
+	pthread_mutex_unlock(&kmsg_mutex);
 }
 
 static void gettime(struct timespec *ts)
@@ -527,6 +602,15 @@ static int common_init(int *argc, char **argv,
 	int ret = 0;
 	const char *env;
 
+	igt_kmsg_capture_fd = open("/dev/kmsg", O_RDWR | O_NONBLOCK);
+	if (igt_kmsg_capture_fd != -1) {
+		igt_kmsg_capture_dump_buf =
+			malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
+		if(igt_kmsg_capture_dump_buf == NULL)
+			igt_warn("Unable to allocate memory, "
+				 "will not dump kmsg.\n");
+	}
+
 	if (!isatty(STDOUT_FILENO) || getenv("IGT_PLAIN_OUTPUT"))
 		__igt_plain_output = true;
 
@@ -796,6 +880,7 @@ bool __igt_run_subtest(const char *subtest_name)
 	igt_debug("Starting subtest: %s\n", subtest_name);
 
 	_igt_log_buffer_reset();
+	_igt_kmsg_capture_reset();
 
 	gettime(&subtest_time);
 	return (in_subtest = subtest_name);
@@ -972,6 +1057,7 @@ void igt_fail(int exitcode)
 		exit(exitcode);
 
 	_igt_log_buffer_dump();
+	_igt_kmsg_capture_dump();
 
 	if (in_subtest) {
 		if (exitcode == IGT_EXIT_TIMEOUT)
@@ -1072,16 +1158,21 @@ void __igt_fail_assert(const char *domain, const char *file, const int line,
  */
 void igt_exit(void)
 {
+	int status = IGT_EXIT_SUCCESS;
+
 	igt_exit_called = true;
 
 	if (run_single_subtest && !run_single_subtest_found) {
 		igt_warn("Unknown subtest: %s\n", run_single_subtest);
-		exit(IGT_EXIT_INVALID);
+		status = IGT_EXIT_INVALID;
+		goto do_exit;
 	}
 
 
-	if (igt_only_list_subtests())
-		exit(IGT_EXIT_SUCCESS);
+	if (igt_only_list_subtests()) {
+		status = IGT_EXIT_SUCCESS;
+		goto do_exit;
+	}
 
 	kmsg(KERN_INFO "%s: exiting, ret=%d\n", command_str, igt_exitcode);
 	igt_debug("Exiting with status code %d\n", igt_exitcode);
@@ -1111,18 +1202,26 @@ void igt_exit(void)
 
 
 		printf("%s (%.3fs)\n", result, elapsed);
-		exit(igt_exitcode);
+		status = igt_exitcode;
+		goto do_exit;
 	}
 
 	/* Calling this without calling one of the above is a failure */
 	assert(skipped_one || succeeded_one || failed_one);
 
 	if (failed_one)
-		exit(igt_exitcode);
+		status = igt_exitcode;
 	else if (succeeded_one)
-		exit(IGT_EXIT_SUCCESS);
+		status = IGT_EXIT_SUCCESS;
 	else
-		exit(IGT_EXIT_SKIP);
+		status = IGT_EXIT_SKIP;
+do_exit:
+	if (igt_kmsg_capture_fd != -1)
+		close(igt_kmsg_capture_fd);
+	if (igt_kmsg_capture_dump_buf != NULL)
+		free(igt_kmsg_capture_dump_buf);
+
+	exit(status);
 }
 
 /* fork support code */
diff --git a/tests/Makefile.sources b/tests/Makefile.sources
index 8fb2de8..25f0c4a 100644
--- a/tests/Makefile.sources
+++ b/tests/Makefile.sources
@@ -62,6 +62,7 @@ TESTS_progs_M = \
 	gem_tiled_partial_pwrite_pread \
 	gem_userptr_blits \
 	gem_write_read_ring_switch \
+	igt_capture \
 	kms_addfb_basic \
 	kms_atomic \
 	kms_cursor_crc \
diff --git a/tests/igt_capture.c b/tests/igt_capture.c
new file mode 100644
index 0000000..fd008d0
--- /dev/null
+++ b/tests/igt_capture.c
@@ -0,0 +1,93 @@
+/*
+ * Copyright © 2015 Intel Corporation
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a
+ * copy of this software and associated documentation files (the "Software"),
+ * to deal in the Software without restriction, including without limitation
+ * the rights to use, copy, modify, merge, publish, distribute, sublicense,
+ * and/or sell copies of the Software, and to permit persons to whom the
+ * Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice (including the next
+ * paragraph) shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
+ * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
+ * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
+ * IN THE SOFTWARE.
+ *
+ * Authors:
+ *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
+ *
+ */
+
+#include "igt.h"
+#include <unistd.h>
+#include <stdlib.h>
+#include <stdio.h>
+#include <string.h>
+#include <fcntl.h>
+#include <inttypes.h>
+#include <errno.h>
+#include <sys/stat.h>
+#include <sys/ioctl.h>
+
+static FILE* kmsg;
+
+static void
+test_kmsg(void)
+{
+	fputs("TEST (KMSG)\n", kmsg);
+	fflush(kmsg);
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_warn(void)
+{
+	igt_warn("TEST (WARN)\n");
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_debug(void)
+{
+	igt_debug("TEST (DEBUG)\n");
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_combined(void)
+{
+	igt_warn("TEST #1 (WARN)\n");
+	fputs("TEST #1\n", kmsg);
+	igt_warn("TEST #2 (WARN)\n");
+	fputs("TEST #2\n", kmsg);
+	fflush(kmsg);
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+igt_main
+{
+	igt_fixture {
+		kmsg = fopen("/dev/kmsg", "w");
+		igt_require(kmsg != NULL);
+	}
+
+	igt_subtest("kmsg")
+		test_kmsg();
+	igt_subtest("warn")
+		test_warn();
+	igt_subtest("debug")
+		test_debug();
+	igt_subtest("combined")
+		test_combined();
+
+	igt_fixture {
+		fclose(kmsg);
+	}
+}
-- 
2.4.3

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-16 13:22 [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it Joonas Lahtinen
@ 2015-11-16 14:06 ` Chris Wilson
  2015-11-17  8:24   ` Joonas Lahtinen
  2015-11-17 13:05 ` Thomas Wood
  2015-11-18 15:44 ` Daniel Vetter
  2 siblings, 1 reply; 23+ messages in thread
From: Chris Wilson @ 2015-11-16 14:06 UTC (permalink / raw)
  To: Joonas Lahtinen
  Cc: Intel graphics driver community testing & development, Thomas Wood

On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen wrote:
> Cc: Thomas Wood <thomas.wood@intel.com>
> Cc: Chris Wilson <chris@chris-wilson.co.uk>
> Cc: Damien Lespiau <damien.lespiau@intel.com>
> Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> ---
>  lib/igt_core.c         | 113 ++++++++++++++++++++++++++++++++++++++++++++++---
>  tests/Makefile.sources |   1 +
>  tests/igt_capture.c    |  93 ++++++++++++++++++++++++++++++++++++++++
>  3 files changed, 200 insertions(+), 7 deletions(-)
>  create mode 100644 tests/igt_capture.c
> 
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index 04a0ab2..e73175a 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -211,6 +211,8 @@
>   * "--help" command line option.
>   */
>  
> +#define IGT_KMSG_CAPTURE_DUMP_BUF_SIZE		4096
> +
>  static unsigned int exit_handler_count;
>  const char *igt_interactive_debug;
>  
> @@ -247,6 +249,10 @@ enum {
>  static int igt_exitcode = IGT_EXIT_SUCCESS;
>  static const char *command_str;
>  
> +static int igt_kmsg_capture_fd;
> +static char* igt_kmsg_capture_dump_buf;
> +static pthread_mutex_t kmsg_mutex = PTHREAD_MUTEX_INITIALIZER;
> +
>  static char* igt_log_domain_filter;
>  static struct {
>  	char *entries[256];
> @@ -312,6 +318,71 @@ static void _igt_log_buffer_dump(void)
>  	pthread_mutex_unlock(&log_buffer_mutex);
>  }
>  
> +static void _igt_kmsg_capture_reset(void)
> +{
> +	if (igt_kmsg_capture_fd == -1)
> +		return;
> +
> +	pthread_mutex_lock(&kmsg_mutex);
> +
> +	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> +
> +	pthread_mutex_unlock(&kmsg_mutex);
> +}

Since close() is signal-safe, you can avoid the mutex (which is not
signal-safe, but we can hope not to generate reentrancy here!) by
opening /dev/kmsg for each subtest, and close it again in
exit_subtest().

Note that we also want to detect dmesg spew during igt when the tests
report all is well. Having the full log associated with a fail,
preferrably with --debug is good, but filtering the <prio> for errors is
also useful.
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-16 14:06 ` Chris Wilson
@ 2015-11-17  8:24   ` Joonas Lahtinen
  0 siblings, 0 replies; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-17  8:24 UTC (permalink / raw)
  To: Chris Wilson
  Cc: Intel graphics driver community testing & development, Thomas Wood

On ma, 2015-11-16 at 14:06 +0000, Chris Wilson wrote:
> On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen wrote:
> > Cc: Thomas Wood <thomas.wood@intel.com>
> > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> > ---
> >  lib/igt_core.c         | 113
> > ++++++++++++++++++++++++++++++++++++++++++++++---
> >  tests/Makefile.sources |   1 +
> >  tests/igt_capture.c    |  93
> > ++++++++++++++++++++++++++++++++++++++++
> >  3 files changed, 200 insertions(+), 7 deletions(-)
> >  create mode 100644 tests/igt_capture.c
> > 
> > diff --git a/lib/igt_core.c b/lib/igt_core.c
> > index 04a0ab2..e73175a 100644
> > --- a/lib/igt_core.c
> > +++ b/lib/igt_core.c
> > @@ -211,6 +211,8 @@
> >   * "--help" command line option.
> >   */
> >  
> > +#define IGT_KMSG_CAPTURE_DUMP_BUF_SIZE		4096
> > +
> >  static unsigned int exit_handler_count;
> >  const char *igt_interactive_debug;
> >  
> > @@ -247,6 +249,10 @@ enum {
> >  static int igt_exitcode = IGT_EXIT_SUCCESS;
> >  static const char *command_str;
> >  
> > +static int igt_kmsg_capture_fd;
> > +static char* igt_kmsg_capture_dump_buf;
> > +static pthread_mutex_t kmsg_mutex = PTHREAD_MUTEX_INITIALIZER;
> > +
> >  static char* igt_log_domain_filter;
> >  static struct {
> >  	char *entries[256];
> > @@ -312,6 +318,71 @@ static void _igt_log_buffer_dump(void)
> >  	pthread_mutex_unlock(&log_buffer_mutex);
> >  }
> >  
> > +static void _igt_kmsg_capture_reset(void)
> > +{
> > +	if (igt_kmsg_capture_fd == -1)
> > +		return;
> > +
> > +	pthread_mutex_lock(&kmsg_mutex);
> > +
> > +	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> > +
> > +	pthread_mutex_unlock(&kmsg_mutex);
> > +}
> 
> Since close() is signal-safe, you can avoid the mutex (which is not
> signal-safe, but we can hope not to generate reentrancy here!) by
> opening /dev/kmsg for each subtest, and close it again in
> exit_subtest().
> 

I actually put the mutex around that block while it was still using
FILE*, when I was trying to cope with one open /dev/kmsg for reading
and writing for duration of the whole run, so it's a left over (it was
doing SEEK_CUR and storing that value etc.). Your suggestion sounds
cleaner.

> Note that we also want to detect dmesg spew during igt when the tests
> report all is well. Having the full log associated with a fail,
> preferrably with --debug is good, but filtering the <prio> for errors
> is
> also useful.

Yes, exactly what I was thinking too, because there were tests in the
SKL hang cases where the test would seem to run OK, but kmsg was full
of errors.

I wasn't sure if I should enable the kmsg logging with own command line
flag (or environment variable, like Thomas added for disabling colors)
or by default, as I am not exactly sure how many consumers we have that
try to parse the IGT outputs. It would be a breaking change there.

Maybe filtering the dmesg by locality kernel, and further with priority
and then displaying the log if there are warning or more serious output
during the test, in that case make the test fail and dump the kmsg? I
think this is also what piglit does (status DMESG fail), so add an own
return value for that, too.

Regards, Joonas

> -Chris
> 
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-16 13:22 [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it Joonas Lahtinen
  2015-11-16 14:06 ` Chris Wilson
@ 2015-11-17 13:05 ` Thomas Wood
  2015-11-17 13:34   ` Joonas Lahtinen
  2015-11-18 15:44 ` Daniel Vetter
  2 siblings, 1 reply; 23+ messages in thread
From: Thomas Wood @ 2015-11-17 13:05 UTC (permalink / raw)
  To: Joonas Lahtinen; +Cc: Intel graphics driver community testing & development

On 16 November 2015 at 13:22, Joonas Lahtinen
<joonas.lahtinen@linux.intel.com> wrote:
> Cc: Thomas Wood <thomas.wood@intel.com>
> Cc: Chris Wilson <chris@chris-wilson.co.uk>
> Cc: Damien Lespiau <damien.lespiau@intel.com>
> Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> ---
>  lib/igt_core.c         | 113 ++++++++++++++++++++++++++++++++++++++++++++++---
>  tests/Makefile.sources |   1 +
>  tests/igt_capture.c    |  93 ++++++++++++++++++++++++++++++++++++++++
>  3 files changed, 200 insertions(+), 7 deletions(-)
>  create mode 100644 tests/igt_capture.c
>
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index 04a0ab2..e73175a 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -211,6 +211,8 @@
>   * "--help" command line option.
>   */
>
> +#define IGT_KMSG_CAPTURE_DUMP_BUF_SIZE         4096
> +
>  static unsigned int exit_handler_count;
>  const char *igt_interactive_debug;
>
> @@ -247,6 +249,10 @@ enum {
>  static int igt_exitcode = IGT_EXIT_SUCCESS;
>  static const char *command_str;
>
> +static int igt_kmsg_capture_fd;
> +static char* igt_kmsg_capture_dump_buf;
> +static pthread_mutex_t kmsg_mutex = PTHREAD_MUTEX_INITIALIZER;
> +
>  static char* igt_log_domain_filter;
>  static struct {
>         char *entries[256];
> @@ -312,6 +318,71 @@ static void _igt_log_buffer_dump(void)
>         pthread_mutex_unlock(&log_buffer_mutex);
>  }
>
> +static void _igt_kmsg_capture_reset(void)
> +{
> +       if (igt_kmsg_capture_fd == -1)
> +               return;
> +
> +       pthread_mutex_lock(&kmsg_mutex);
> +
> +       lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> +
> +       pthread_mutex_unlock(&kmsg_mutex);
> +}
> +
> +static void _igt_kmsg_capture_dump(void)
> +{
> +       size_t nbytes;
> +       int nlines;
> +       char *p;
> +       char *p0;
> +       int c;
> +
> +       if (igt_kmsg_capture_fd == -1 ||
> +           igt_kmsg_capture_dump_buf == NULL)
> +               return;
> +
> +       pthread_mutex_lock(&kmsg_mutex);
> +
> +
> +       nlines = 0;
> +       do {
> +               errno = 0;
> +               nbytes = read(igt_kmsg_capture_fd,
> +                             igt_kmsg_capture_dump_buf,
> +                             IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> +
> +               if (nbytes == -1)
> +                       continue;
> +
> +               if (!nlines)
> +                       fprintf(stderr, "**** KMSG ****\n");
> +
> +               p = p0 = strchr(igt_kmsg_capture_dump_buf, ';') + 1;
> +               while (p - p0 < nbytes) {
> +                       if (*p != '\\') {
> +                               fputc(*p++, stderr);
> +                               continue;
> +                       }
> +                       sscanf(p, "\\x%x", &c);
> +                       fputc(c, stderr);
> +                       p += 4;
> +               }
> +               //fputs(strchr(igt_kmsg_capture_dump_buf, ';') + 1, stderr);

This line can be removed if it is no longer needed.


> +               nlines++;
> +       } while(errno == 0);
> +
> +       if (nlines)
> +               fprintf(stderr, "****  END  ****\n");
> +       else
> +               fprintf(stderr, "No kmsg.\n");
> +
> +       if (errno != EAGAIN)
> +               fprintf(stderr, "Incomplete kmsg.\n");
> +
> +       pthread_mutex_unlock(&kmsg_mutex);
> +}
> +
>  __attribute__((format(printf, 1, 2)))
>  static void kmsg(const char *format, ...)
>  #define KERN_EMER      "<0>"
> @@ -330,11 +401,15 @@ static void kmsg(const char *format, ...)
>         if (file == NULL)
>                 return;
>
> +       pthread_mutex_lock(&kmsg_mutex);
> +
>         va_start(ap, format);
>         vfprintf(file, format, ap);
>         va_end(ap);
>
>         fclose(file);
> +
> +       pthread_mutex_unlock(&kmsg_mutex);
>  }
>
>  static void gettime(struct timespec *ts)
> @@ -527,6 +602,15 @@ static int common_init(int *argc, char **argv,
>         int ret = 0;
>         const char *env;
>
> +       igt_kmsg_capture_fd = open("/dev/kmsg", O_RDWR | O_NONBLOCK);
> +       if (igt_kmsg_capture_fd != -1) {
> +               igt_kmsg_capture_dump_buf =
> +                       malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> +               if(igt_kmsg_capture_dump_buf == NULL)
> +                       igt_warn("Unable to allocate memory, "
> +                                "will not dump kmsg.\n");
> +       }
> +
>         if (!isatty(STDOUT_FILENO) || getenv("IGT_PLAIN_OUTPUT"))
>                 __igt_plain_output = true;
>
> @@ -796,6 +880,7 @@ bool __igt_run_subtest(const char *subtest_name)
>         igt_debug("Starting subtest: %s\n", subtest_name);
>
>         _igt_log_buffer_reset();
> +       _igt_kmsg_capture_reset();
>
>         gettime(&subtest_time);
>         return (in_subtest = subtest_name);
> @@ -972,6 +1057,7 @@ void igt_fail(int exitcode)
>                 exit(exitcode);
>
>         _igt_log_buffer_dump();
> +       _igt_kmsg_capture_dump();
>
>         if (in_subtest) {
>                 if (exitcode == IGT_EXIT_TIMEOUT)
> @@ -1072,16 +1158,21 @@ void __igt_fail_assert(const char *domain, const char *file, const int line,
>   */
>  void igt_exit(void)
>  {
> +       int status = IGT_EXIT_SUCCESS;
> +
>         igt_exit_called = true;
>
>         if (run_single_subtest && !run_single_subtest_found) {
>                 igt_warn("Unknown subtest: %s\n", run_single_subtest);
> -               exit(IGT_EXIT_INVALID);
> +               status = IGT_EXIT_INVALID;
> +               goto do_exit;
>         }
>
>
> -       if (igt_only_list_subtests())
> -               exit(IGT_EXIT_SUCCESS);
> +       if (igt_only_list_subtests()) {
> +               status = IGT_EXIT_SUCCESS;
> +               goto do_exit;

It might be good to avoid allocating the kmsg buffer and file
descriptor altogether if only listing subtests. There are also a few
cases where igt_exit won't be called, such as when using the help
options or when a test has no subtests and one of the subtest options
is specified.


> +       }
>
>         kmsg(KERN_INFO "%s: exiting, ret=%d\n", command_str, igt_exitcode);
>         igt_debug("Exiting with status code %d\n", igt_exitcode);
> @@ -1111,18 +1202,26 @@ void igt_exit(void)
>
>
>                 printf("%s (%.3fs)\n", result, elapsed);
> -               exit(igt_exitcode);
> +               status = igt_exitcode;
> +               goto do_exit;
>         }
>
>         /* Calling this without calling one of the above is a failure */
>         assert(skipped_one || succeeded_one || failed_one);
>
>         if (failed_one)
> -               exit(igt_exitcode);
> +               status = igt_exitcode;
>         else if (succeeded_one)
> -               exit(IGT_EXIT_SUCCESS);
> +               status = IGT_EXIT_SUCCESS;
>         else
> -               exit(IGT_EXIT_SKIP);
> +               status = IGT_EXIT_SKIP;
> +do_exit:
> +       if (igt_kmsg_capture_fd != -1)
> +               close(igt_kmsg_capture_fd);
> +       if (igt_kmsg_capture_dump_buf != NULL)
> +               free(igt_kmsg_capture_dump_buf);

Since this always needs to be run, would it be simpler to move it to
the top of this function?


> +
> +       exit(status);
>  }
>
>  /* fork support code */
> diff --git a/tests/Makefile.sources b/tests/Makefile.sources
> index 8fb2de8..25f0c4a 100644
> --- a/tests/Makefile.sources
> +++ b/tests/Makefile.sources
> @@ -62,6 +62,7 @@ TESTS_progs_M = \
>         gem_tiled_partial_pwrite_pread \
>         gem_userptr_blits \
>         gem_write_read_ring_switch \
> +       igt_capture \
>         kms_addfb_basic \
>         kms_atomic \
>         kms_cursor_crc \
> diff --git a/tests/igt_capture.c b/tests/igt_capture.c
> new file mode 100644
> index 0000000..fd008d0
> --- /dev/null
> +++ b/tests/igt_capture.c

Since this is an infrastructure test, it would be better placed in
lib/tests. The binary will also need adding to .gitignore.


> @@ -0,0 +1,93 @@
> +/*
> + * Copyright © 2015 Intel Corporation
> + *
> + * Permission is hereby granted, free of charge, to any person obtaining a
> + * copy of this software and associated documentation files (the "Software"),
> + * to deal in the Software without restriction, including without limitation
> + * the rights to use, copy, modify, merge, publish, distribute, sublicense,
> + * and/or sell copies of the Software, and to permit persons to whom the
> + * Software is furnished to do so, subject to the following conditions:
> + *
> + * The above copyright notice and this permission notice (including the next
> + * paragraph) shall be included in all copies or substantial portions of the
> + * Software.
> + *
> + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
> + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
> + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
> + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
> + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
> + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
> + * IN THE SOFTWARE.
> + *
> + * Authors:
> + *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> + *
> + */
> +
> +#include "igt.h"
> +#include <unistd.h>
> +#include <stdlib.h>
> +#include <stdio.h>
> +#include <string.h>
> +#include <fcntl.h>
> +#include <inttypes.h>
> +#include <errno.h>
> +#include <sys/stat.h>
> +#include <sys/ioctl.h>
> +
> +static FILE* kmsg;
> +
> +static void
> +test_kmsg(void)
> +{
> +       fputs("TEST (KMSG)\n", kmsg);
> +       fflush(kmsg);
> +       igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_warn(void)
> +{
> +       igt_warn("TEST (WARN)\n");
> +       igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_debug(void)
> +{
> +       igt_debug("TEST (DEBUG)\n");
> +       igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_combined(void)
> +{
> +       igt_warn("TEST #1 (WARN)\n");
> +       fputs("TEST #1\n", kmsg);
> +       igt_warn("TEST #2 (WARN)\n");
> +       fputs("TEST #2\n", kmsg);
> +       fflush(kmsg);
> +       igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +igt_main
> +{
> +       igt_fixture {
> +               kmsg = fopen("/dev/kmsg", "w");
> +               igt_require(kmsg != NULL);
> +       }
> +
> +       igt_subtest("kmsg")
> +               test_kmsg();
> +       igt_subtest("warn")
> +               test_warn();
> +       igt_subtest("debug")
> +               test_debug();
> +       igt_subtest("combined")
> +               test_combined();
> +
> +       igt_fixture {
> +               fclose(kmsg);
> +       }
> +}
> --
> 2.4.3
>
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-17 13:05 ` Thomas Wood
@ 2015-11-17 13:34   ` Joonas Lahtinen
  0 siblings, 0 replies; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-17 13:34 UTC (permalink / raw)
  To: Thomas Wood; +Cc: Intel graphics driver community testing & development

On ti, 2015-11-17 at 13:05 +0000, Thomas Wood wrote:
> On 16 November 2015 at 13:22, Joonas Lahtinen
> <joonas.lahtinen@linux.intel.com> wrote:
> > +static void _igt_kmsg_capture_dump(void)
> > +{
> > 
<SNIP>
> > +               //fputs(strchr(igt_kmsg_capture_dump_buf, ';') + 1,
> > stderr);
> 
> This line can be removed if it is no longer needed.
> 

Yeah, already removed from my v2.

> 
> > @@ -1072,16 +1158,21 @@ void __igt_fail_assert(const char *domain,
> > const char *file, const int line,
> >   */
> >  void igt_exit(void)
> >  {
> > +       int status = IGT_EXIT_SUCCESS;
> > +
> >         igt_exit_called = true;
> > 
> >         if (run_single_subtest && !run_single_subtest_found) {
> >                 igt_warn("Unknown subtest: %s\n",
> > run_single_subtest);
> > -               exit(IGT_EXIT_INVALID);
> > +               status = IGT_EXIT_INVALID;
> > +               goto do_exit;
> >         }
> > 
> > 
> > -       if (igt_only_list_subtests())
> > -               exit(IGT_EXIT_SUCCESS);
> > +       if (igt_only_list_subtests()) {
> > +               status = IGT_EXIT_SUCCESS;
> > +               goto do_exit;
> 
> It might be good to avoid allocating the kmsg buffer and file
> descriptor altogether if only listing subtests. There are also a few
> cases where igt_exit won't be called, such as when using the help
> options or when a test has no subtests and one of the subtest options
> is specified.

Yes, Chris suggested only opening the FD when a subtest starts and
closing after each one. Which comes to the point that the "single test
or 1 or more subtests" leads to quite a few different codepaths, and I
think it should be considered converting all the single tests to tests
with only one subtest, to make the code maintainable.


> >         if (failed_one)
> > -               exit(igt_exitcode);
> > +               status = igt_exitcode;
> >         else if (succeeded_one)
> > -               exit(IGT_EXIT_SUCCESS);
> > +               status = IGT_EXIT_SUCCESS;
> >         else
> > -               exit(IGT_EXIT_SKIP);
> > +               status = IGT_EXIT_SKIP;
> > +do_exit:
> > +       if (igt_kmsg_capture_fd != -1)
> > +               close(igt_kmsg_capture_fd);
> > +       if (igt_kmsg_capture_dump_buf != NULL)
> > +               free(igt_kmsg_capture_dump_buf);
> 
> Since this always needs to be run, would it be simpler to move it to
> the top of this function?
> 

True, originally I did the dumping in this function so the position is
kind of leftover from there.

> 
> > +
> > +       exit(status);
> >  }
> > 
> >  /* fork support code */
> > diff --git a/tests/Makefile.sources b/tests/Makefile.sources
> > index 8fb2de8..25f0c4a 100644
> > --- a/tests/Makefile.sources
> > +++ b/tests/Makefile.sources
> > @@ -62,6 +62,7 @@ TESTS_progs_M = \
> >         gem_tiled_partial_pwrite_pread \
> >         gem_userptr_blits \
> >         gem_write_read_ring_switch \
> > +       igt_capture \
> >         kms_addfb_basic \
> >         kms_atomic \
> >         kms_cursor_crc \
> > diff --git a/tests/igt_capture.c b/tests/igt_capture.c
> > new file mode 100644
> > index 0000000..fd008d0
> > --- /dev/null
> > +++ b/tests/igt_capture.c
> 
> Since this is an infrastructure test, it would be better placed in
> lib/tests. The binary will also need adding to .gitignore.
> 

Ok, will move it. I do notice there already is igt_stats in there.

Regards, Joonas

> 
> > @@ -0,0 +1,93 @@
> > +/*
> > + * Copyright © 2015 Intel Corporation
> > + *
> > + * Permission is hereby granted, free of charge, to any person
> > obtaining a
> > + * copy of this software and associated documentation files (the
> > "Software"),
> > + * to deal in the Software without restriction, including without
> > limitation
> > + * the rights to use, copy, modify, merge, publish, distribute,
> > sublicense,
> > + * and/or sell copies of the Software, and to permit persons to
> > whom the
> > + * Software is furnished to do so, subject to the following
> > conditions:
> > + *
> > + * The above copyright notice and this permission notice
> > (including the next
> > + * paragraph) shall be included in all copies or substantial
> > portions of the
> > + * Software.
> > + *
> > + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
> > EXPRESS OR
> > + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
> > MERCHANTABILITY,
> > + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO
> > EVENT SHALL
> > + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM,
> > DAMAGES OR OTHER
> > + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE,
> > ARISING
> > + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR
> > OTHER DEALINGS
> > + * IN THE SOFTWARE.
> > + *
> > + * Authors:
> > + *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> > + *
> > + */
> > +
> > +#include "igt.h"
> > +#include <unistd.h>
> > +#include <stdlib.h>
> > +#include <stdio.h>
> > +#include <string.h>
> > +#include <fcntl.h>
> > +#include <inttypes.h>
> > +#include <errno.h>
> > +#include <sys/stat.h>
> > +#include <sys/ioctl.h>
> > +
> > +static FILE* kmsg;
> > +
> > +static void
> > +test_kmsg(void)
> > +{
> > +       fputs("TEST (KMSG)\n", kmsg);
> > +       fflush(kmsg);
> > +       igt_fail(IGT_EXIT_FAILURE);
> > +}
> > +
> > +static void
> > +test_warn(void)
> > +{
> > +       igt_warn("TEST (WARN)\n");
> > +       igt_fail(IGT_EXIT_FAILURE);
> > +}
> > +
> > +static void
> > +test_debug(void)
> > +{
> > +       igt_debug("TEST (DEBUG)\n");
> > +       igt_fail(IGT_EXIT_FAILURE);
> > +}
> > +
> > +static void
> > +test_combined(void)
> > +{
> > +       igt_warn("TEST #1 (WARN)\n");
> > +       fputs("TEST #1\n", kmsg);
> > +       igt_warn("TEST #2 (WARN)\n");
> > +       fputs("TEST #2\n", kmsg);
> > +       fflush(kmsg);
> > +       igt_fail(IGT_EXIT_FAILURE);
> > +}
> > +
> > +igt_main
> > +{
> > +       igt_fixture {
> > +               kmsg = fopen("/dev/kmsg", "w");
> > +               igt_require(kmsg != NULL);
> > +       }
> > +
> > +       igt_subtest("kmsg")
> > +               test_kmsg();
> > +       igt_subtest("warn")
> > +               test_warn();
> > +       igt_subtest("debug")
> > +               test_debug();
> > +       igt_subtest("combined")
> > +               test_combined();
> > +
> > +       igt_fixture {
> > +               fclose(kmsg);
> > +       }
> > +}
> > --
> > 2.4.3
> > 
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-16 13:22 [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it Joonas Lahtinen
  2015-11-16 14:06 ` Chris Wilson
  2015-11-17 13:05 ` Thomas Wood
@ 2015-11-18 15:44 ` Daniel Vetter
  2015-11-18 17:32   ` Chris Wilson
  2015-11-18 17:41   ` [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it Thomas Wood
  2 siblings, 2 replies; 23+ messages in thread
From: Daniel Vetter @ 2015-11-18 15:44 UTC (permalink / raw)
  To: Joonas Lahtinen
  Cc: Intel graphics driver community testing & development, Thomas Wood

On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen wrote:
> Cc: Thomas Wood <thomas.wood@intel.com>
> Cc: Chris Wilson <chris@chris-wilson.co.uk>
> Cc: Damien Lespiau <damien.lespiau@intel.com>
> Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>

Given that we have all that in piglit already the commit message is a bit
thin on justification. Why do we need this in igt too? How does this
interact with the piglit dmesg capture?

> ---
>  lib/igt_core.c         | 113 ++++++++++++++++++++++++++++++++++++++++++++++---
>  tests/Makefile.sources |   1 +
>  tests/igt_capture.c    |  93 ++++++++++++++++++++++++++++++++++++++++
>  3 files changed, 200 insertions(+), 7 deletions(-)
>  create mode 100644 tests/igt_capture.c
> 
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index 04a0ab2..e73175a 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -211,6 +211,8 @@
>   * "--help" command line option.
>   */
>  
> +#define IGT_KMSG_CAPTURE_DUMP_BUF_SIZE		4096
> +
>  static unsigned int exit_handler_count;
>  const char *igt_interactive_debug;
>  
> @@ -247,6 +249,10 @@ enum {
>  static int igt_exitcode = IGT_EXIT_SUCCESS;
>  static const char *command_str;
>  
> +static int igt_kmsg_capture_fd;
> +static char* igt_kmsg_capture_dump_buf;
> +static pthread_mutex_t kmsg_mutex = PTHREAD_MUTEX_INITIALIZER;
> +
>  static char* igt_log_domain_filter;
>  static struct {
>  	char *entries[256];
> @@ -312,6 +318,71 @@ static void _igt_log_buffer_dump(void)
>  	pthread_mutex_unlock(&log_buffer_mutex);
>  }
>  
> +static void _igt_kmsg_capture_reset(void)
> +{
> +	if (igt_kmsg_capture_fd == -1)
> +		return;
> +
> +	pthread_mutex_lock(&kmsg_mutex);
> +
> +	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> +
> +	pthread_mutex_unlock(&kmsg_mutex);
> +}
> +
> +static void _igt_kmsg_capture_dump(void)
> +{
> +	size_t nbytes;
> +	int nlines;
> +	char *p;
> +	char *p0;
> +	int c;
> +
> +	if (igt_kmsg_capture_fd == -1 ||
> +	    igt_kmsg_capture_dump_buf == NULL)
> +		return;
> +
> +	pthread_mutex_lock(&kmsg_mutex);
> +
> +
> +	nlines = 0;
> +	do {
> +		errno = 0;
> +		nbytes = read(igt_kmsg_capture_fd,
> +			      igt_kmsg_capture_dump_buf,
> +			      IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> +
> +		if (nbytes == -1)
> +			continue;
> +
> +		if (!nlines)
> +			fprintf(stderr, "**** KMSG ****\n");
> +
> +		p = p0 = strchr(igt_kmsg_capture_dump_buf, ';') + 1;
> +		while (p - p0 < nbytes) {
> +			if (*p != '\\') {
> +				fputc(*p++, stderr);
> +				continue;
> +			}
> +			sscanf(p, "\\x%x", &c);
> +			fputc(c, stderr);
> +			p += 4;
> +		}
> +		//fputs(strchr(igt_kmsg_capture_dump_buf, ';') + 1, stderr);
> +		nlines++;
> +	} while(errno == 0);
> +
> +	if (nlines)
> +		fprintf(stderr, "****  END  ****\n");
> +	else
> +		fprintf(stderr, "No kmsg.\n");
> +
> +	if (errno != EAGAIN)
> +		fprintf(stderr, "Incomplete kmsg.\n");
> +
> +	pthread_mutex_unlock(&kmsg_mutex);
> +}
> +
>  __attribute__((format(printf, 1, 2)))
>  static void kmsg(const char *format, ...)
>  #define KERN_EMER	"<0>"
> @@ -330,11 +401,15 @@ static void kmsg(const char *format, ...)
>  	if (file == NULL)
>  		return;
>  
> +	pthread_mutex_lock(&kmsg_mutex);
> +
>  	va_start(ap, format);
>  	vfprintf(file, format, ap);
>  	va_end(ap);
>  
>  	fclose(file);
> +
> +	pthread_mutex_unlock(&kmsg_mutex);
>  }
>  
>  static void gettime(struct timespec *ts)
> @@ -527,6 +602,15 @@ static int common_init(int *argc, char **argv,
>  	int ret = 0;
>  	const char *env;
>  
> +	igt_kmsg_capture_fd = open("/dev/kmsg", O_RDWR | O_NONBLOCK);
> +	if (igt_kmsg_capture_fd != -1) {
> +		igt_kmsg_capture_dump_buf =
> +			malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> +		if(igt_kmsg_capture_dump_buf == NULL)
> +			igt_warn("Unable to allocate memory, "
> +				 "will not dump kmsg.\n");
> +	}
> +
>  	if (!isatty(STDOUT_FILENO) || getenv("IGT_PLAIN_OUTPUT"))
>  		__igt_plain_output = true;
>  
> @@ -796,6 +880,7 @@ bool __igt_run_subtest(const char *subtest_name)
>  	igt_debug("Starting subtest: %s\n", subtest_name);
>  
>  	_igt_log_buffer_reset();
> +	_igt_kmsg_capture_reset();
>  
>  	gettime(&subtest_time);
>  	return (in_subtest = subtest_name);
> @@ -972,6 +1057,7 @@ void igt_fail(int exitcode)
>  		exit(exitcode);
>  
>  	_igt_log_buffer_dump();
> +	_igt_kmsg_capture_dump();
>  
>  	if (in_subtest) {
>  		if (exitcode == IGT_EXIT_TIMEOUT)
> @@ -1072,16 +1158,21 @@ void __igt_fail_assert(const char *domain, const char *file, const int line,
>   */
>  void igt_exit(void)
>  {
> +	int status = IGT_EXIT_SUCCESS;
> +
>  	igt_exit_called = true;
>  
>  	if (run_single_subtest && !run_single_subtest_found) {
>  		igt_warn("Unknown subtest: %s\n", run_single_subtest);
> -		exit(IGT_EXIT_INVALID);
> +		status = IGT_EXIT_INVALID;
> +		goto do_exit;
>  	}
>  
>  
> -	if (igt_only_list_subtests())
> -		exit(IGT_EXIT_SUCCESS);
> +	if (igt_only_list_subtests()) {
> +		status = IGT_EXIT_SUCCESS;
> +		goto do_exit;
> +	}
>  
>  	kmsg(KERN_INFO "%s: exiting, ret=%d\n", command_str, igt_exitcode);
>  	igt_debug("Exiting with status code %d\n", igt_exitcode);
> @@ -1111,18 +1202,26 @@ void igt_exit(void)
>  
>  
>  		printf("%s (%.3fs)\n", result, elapsed);
> -		exit(igt_exitcode);
> +		status = igt_exitcode;
> +		goto do_exit;
>  	}
>  
>  	/* Calling this without calling one of the above is a failure */
>  	assert(skipped_one || succeeded_one || failed_one);
>  
>  	if (failed_one)
> -		exit(igt_exitcode);
> +		status = igt_exitcode;
>  	else if (succeeded_one)
> -		exit(IGT_EXIT_SUCCESS);
> +		status = IGT_EXIT_SUCCESS;
>  	else
> -		exit(IGT_EXIT_SKIP);
> +		status = IGT_EXIT_SKIP;
> +do_exit:
> +	if (igt_kmsg_capture_fd != -1)
> +		close(igt_kmsg_capture_fd);
> +	if (igt_kmsg_capture_dump_buf != NULL)
> +		free(igt_kmsg_capture_dump_buf);
> +
> +	exit(status);
>  }
>  
>  /* fork support code */
> diff --git a/tests/Makefile.sources b/tests/Makefile.sources
> index 8fb2de8..25f0c4a 100644
> --- a/tests/Makefile.sources
> +++ b/tests/Makefile.sources
> @@ -62,6 +62,7 @@ TESTS_progs_M = \
>  	gem_tiled_partial_pwrite_pread \
>  	gem_userptr_blits \
>  	gem_write_read_ring_switch \
> +	igt_capture \
>  	kms_addfb_basic \
>  	kms_atomic \
>  	kms_cursor_crc \
> diff --git a/tests/igt_capture.c b/tests/igt_capture.c
> new file mode 100644
> index 0000000..fd008d0
> --- /dev/null
> +++ b/tests/igt_capture.c
> @@ -0,0 +1,93 @@
> +/*
> + * Copyright © 2015 Intel Corporation
> + *
> + * Permission is hereby granted, free of charge, to any person obtaining a
> + * copy of this software and associated documentation files (the "Software"),
> + * to deal in the Software without restriction, including without limitation
> + * the rights to use, copy, modify, merge, publish, distribute, sublicense,
> + * and/or sell copies of the Software, and to permit persons to whom the
> + * Software is furnished to do so, subject to the following conditions:
> + *
> + * The above copyright notice and this permission notice (including the next
> + * paragraph) shall be included in all copies or substantial portions of the
> + * Software.
> + *
> + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
> + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
> + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
> + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
> + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
> + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
> + * IN THE SOFTWARE.
> + *
> + * Authors:
> + *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> + *
> + */
> +
> +#include "igt.h"
> +#include <unistd.h>
> +#include <stdlib.h>
> +#include <stdio.h>
> +#include <string.h>
> +#include <fcntl.h>
> +#include <inttypes.h>
> +#include <errno.h>
> +#include <sys/stat.h>
> +#include <sys/ioctl.h>
> +
> +static FILE* kmsg;
> +
> +static void
> +test_kmsg(void)
> +{
> +	fputs("TEST (KMSG)\n", kmsg);
> +	fflush(kmsg);
> +	igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_warn(void)
> +{
> +	igt_warn("TEST (WARN)\n");
> +	igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_debug(void)
> +{
> +	igt_debug("TEST (DEBUG)\n");
> +	igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_combined(void)
> +{
> +	igt_warn("TEST #1 (WARN)\n");
> +	fputs("TEST #1\n", kmsg);
> +	igt_warn("TEST #2 (WARN)\n");
> +	fputs("TEST #2\n", kmsg);
> +	fflush(kmsg);
> +	igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +igt_main
> +{
> +	igt_fixture {
> +		kmsg = fopen("/dev/kmsg", "w");
> +		igt_require(kmsg != NULL);
> +	}
> +
> +	igt_subtest("kmsg")
> +		test_kmsg();
> +	igt_subtest("warn")
> +		test_warn();
> +	igt_subtest("debug")
> +		test_debug();
> +	igt_subtest("combined")
> +		test_combined();
> +
> +	igt_fixture {
> +		fclose(kmsg);
> +	}
> +}
> -- 
> 2.4.3
> 
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx@lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/intel-gfx

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-18 15:44 ` Daniel Vetter
@ 2015-11-18 17:32   ` Chris Wilson
  2015-11-19  9:38     ` Daniel Vetter
  2015-11-19 10:35     ` [PATCH i-g-t v2] lib/igt_core: Add kmsg capture and dumping Joonas Lahtinen
  2015-11-18 17:41   ` [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it Thomas Wood
  1 sibling, 2 replies; 23+ messages in thread
From: Chris Wilson @ 2015-11-18 17:32 UTC (permalink / raw)
  To: Daniel Vetter
  Cc: Intel graphics driver community testing & development, Thomas Wood

On Wed, Nov 18, 2015 at 04:44:20PM +0100, Daniel Vetter wrote:
> On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen wrote:
> > Cc: Thomas Wood <thomas.wood@intel.com>
> > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> 
> Given that we have all that in piglit already the commit message is a bit
> thin on justification. Why do we need this in igt too? How does this
> interact with the piglit dmesg capture?

It's doesn't interfere with anyone else parsing kmsg/dmesg for
themselves, but it adds very useful functionality to standalone igt.
Which to me is significantly more valuable and I have been patching it
into igt for over a year and wished it was taken more seriously given
the number of incorrect bug reports generated.
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-18 15:44 ` Daniel Vetter
  2015-11-18 17:32   ` Chris Wilson
@ 2015-11-18 17:41   ` Thomas Wood
  2015-11-18 18:12     ` Joonas Lahtinen
  1 sibling, 1 reply; 23+ messages in thread
From: Thomas Wood @ 2015-11-18 17:41 UTC (permalink / raw)
  To: Daniel Vetter; +Cc: Intel graphics driver community testing & development

On 18 November 2015 at 15:44, Daniel Vetter <daniel@ffwll.ch> wrote:
> On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen wrote:
>> Cc: Thomas Wood <thomas.wood@intel.com>
>> Cc: Chris Wilson <chris@chris-wilson.co.uk>
>> Cc: Damien Lespiau <damien.lespiau@intel.com>
>> Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
>
> Given that we have all that in piglit already the commit message is a bit
> thin on justification. Why do we need this in igt too? How does this
> interact with the piglit dmesg capture?

There are a few tests that rely on checking dmesg to determine if the
test failed (such as gem_hangcheck_forcewake and kms_flip_event_leak).
Although not implemented in this patch, it might be useful to use this
feature to actually report a failure in those cases.


>
>> ---
>>  lib/igt_core.c         | 113 ++++++++++++++++++++++++++++++++++++++++++++++---
>>  tests/Makefile.sources |   1 +
>>  tests/igt_capture.c    |  93 ++++++++++++++++++++++++++++++++++++++++
>>  3 files changed, 200 insertions(+), 7 deletions(-)
>>  create mode 100644 tests/igt_capture.c
>>
>> diff --git a/lib/igt_core.c b/lib/igt_core.c
>> index 04a0ab2..e73175a 100644
>> --- a/lib/igt_core.c
>> +++ b/lib/igt_core.c
>> @@ -211,6 +211,8 @@
>>   * "--help" command line option.
>>   */
>>
>> +#define IGT_KMSG_CAPTURE_DUMP_BUF_SIZE               4096
>> +
>>  static unsigned int exit_handler_count;
>>  const char *igt_interactive_debug;
>>
>> @@ -247,6 +249,10 @@ enum {
>>  static int igt_exitcode = IGT_EXIT_SUCCESS;
>>  static const char *command_str;
>>
>> +static int igt_kmsg_capture_fd;
>> +static char* igt_kmsg_capture_dump_buf;
>> +static pthread_mutex_t kmsg_mutex = PTHREAD_MUTEX_INITIALIZER;
>> +
>>  static char* igt_log_domain_filter;
>>  static struct {
>>       char *entries[256];
>> @@ -312,6 +318,71 @@ static void _igt_log_buffer_dump(void)
>>       pthread_mutex_unlock(&log_buffer_mutex);
>>  }
>>
>> +static void _igt_kmsg_capture_reset(void)
>> +{
>> +     if (igt_kmsg_capture_fd == -1)
>> +             return;
>> +
>> +     pthread_mutex_lock(&kmsg_mutex);
>> +
>> +     lseek(igt_kmsg_capture_fd, 0, SEEK_END);
>> +
>> +     pthread_mutex_unlock(&kmsg_mutex);
>> +}
>> +
>> +static void _igt_kmsg_capture_dump(void)
>> +{
>> +     size_t nbytes;
>> +     int nlines;
>> +     char *p;
>> +     char *p0;
>> +     int c;
>> +
>> +     if (igt_kmsg_capture_fd == -1 ||
>> +         igt_kmsg_capture_dump_buf == NULL)
>> +             return;
>> +
>> +     pthread_mutex_lock(&kmsg_mutex);
>> +
>> +
>> +     nlines = 0;
>> +     do {
>> +             errno = 0;
>> +             nbytes = read(igt_kmsg_capture_fd,
>> +                           igt_kmsg_capture_dump_buf,
>> +                           IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
>> +
>> +             if (nbytes == -1)
>> +                     continue;
>> +
>> +             if (!nlines)
>> +                     fprintf(stderr, "**** KMSG ****\n");
>> +
>> +             p = p0 = strchr(igt_kmsg_capture_dump_buf, ';') + 1;
>> +             while (p - p0 < nbytes) {
>> +                     if (*p != '\\') {
>> +                             fputc(*p++, stderr);
>> +                             continue;
>> +                     }
>> +                     sscanf(p, "\\x%x", &c);
>> +                     fputc(c, stderr);
>> +                     p += 4;
>> +             }
>> +             //fputs(strchr(igt_kmsg_capture_dump_buf, ';') + 1, stderr);
>> +             nlines++;
>> +     } while(errno == 0);
>> +
>> +     if (nlines)
>> +             fprintf(stderr, "****  END  ****\n");
>> +     else
>> +             fprintf(stderr, "No kmsg.\n");
>> +
>> +     if (errno != EAGAIN)
>> +             fprintf(stderr, "Incomplete kmsg.\n");
>> +
>> +     pthread_mutex_unlock(&kmsg_mutex);
>> +}
>> +
>>  __attribute__((format(printf, 1, 2)))
>>  static void kmsg(const char *format, ...)
>>  #define KERN_EMER    "<0>"
>> @@ -330,11 +401,15 @@ static void kmsg(const char *format, ...)
>>       if (file == NULL)
>>               return;
>>
>> +     pthread_mutex_lock(&kmsg_mutex);
>> +
>>       va_start(ap, format);
>>       vfprintf(file, format, ap);
>>       va_end(ap);
>>
>>       fclose(file);
>> +
>> +     pthread_mutex_unlock(&kmsg_mutex);
>>  }
>>
>>  static void gettime(struct timespec *ts)
>> @@ -527,6 +602,15 @@ static int common_init(int *argc, char **argv,
>>       int ret = 0;
>>       const char *env;
>>
>> +     igt_kmsg_capture_fd = open("/dev/kmsg", O_RDWR | O_NONBLOCK);
>> +     if (igt_kmsg_capture_fd != -1) {
>> +             igt_kmsg_capture_dump_buf =
>> +                     malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
>> +             if(igt_kmsg_capture_dump_buf == NULL)
>> +                     igt_warn("Unable to allocate memory, "
>> +                              "will not dump kmsg.\n");
>> +     }
>> +
>>       if (!isatty(STDOUT_FILENO) || getenv("IGT_PLAIN_OUTPUT"))
>>               __igt_plain_output = true;
>>
>> @@ -796,6 +880,7 @@ bool __igt_run_subtest(const char *subtest_name)
>>       igt_debug("Starting subtest: %s\n", subtest_name);
>>
>>       _igt_log_buffer_reset();
>> +     _igt_kmsg_capture_reset();
>>
>>       gettime(&subtest_time);
>>       return (in_subtest = subtest_name);
>> @@ -972,6 +1057,7 @@ void igt_fail(int exitcode)
>>               exit(exitcode);
>>
>>       _igt_log_buffer_dump();
>> +     _igt_kmsg_capture_dump();
>>
>>       if (in_subtest) {
>>               if (exitcode == IGT_EXIT_TIMEOUT)
>> @@ -1072,16 +1158,21 @@ void __igt_fail_assert(const char *domain, const char *file, const int line,
>>   */
>>  void igt_exit(void)
>>  {
>> +     int status = IGT_EXIT_SUCCESS;
>> +
>>       igt_exit_called = true;
>>
>>       if (run_single_subtest && !run_single_subtest_found) {
>>               igt_warn("Unknown subtest: %s\n", run_single_subtest);
>> -             exit(IGT_EXIT_INVALID);
>> +             status = IGT_EXIT_INVALID;
>> +             goto do_exit;
>>       }
>>
>>
>> -     if (igt_only_list_subtests())
>> -             exit(IGT_EXIT_SUCCESS);
>> +     if (igt_only_list_subtests()) {
>> +             status = IGT_EXIT_SUCCESS;
>> +             goto do_exit;
>> +     }
>>
>>       kmsg(KERN_INFO "%s: exiting, ret=%d\n", command_str, igt_exitcode);
>>       igt_debug("Exiting with status code %d\n", igt_exitcode);
>> @@ -1111,18 +1202,26 @@ void igt_exit(void)
>>
>>
>>               printf("%s (%.3fs)\n", result, elapsed);
>> -             exit(igt_exitcode);
>> +             status = igt_exitcode;
>> +             goto do_exit;
>>       }
>>
>>       /* Calling this without calling one of the above is a failure */
>>       assert(skipped_one || succeeded_one || failed_one);
>>
>>       if (failed_one)
>> -             exit(igt_exitcode);
>> +             status = igt_exitcode;
>>       else if (succeeded_one)
>> -             exit(IGT_EXIT_SUCCESS);
>> +             status = IGT_EXIT_SUCCESS;
>>       else
>> -             exit(IGT_EXIT_SKIP);
>> +             status = IGT_EXIT_SKIP;
>> +do_exit:
>> +     if (igt_kmsg_capture_fd != -1)
>> +             close(igt_kmsg_capture_fd);
>> +     if (igt_kmsg_capture_dump_buf != NULL)
>> +             free(igt_kmsg_capture_dump_buf);
>> +
>> +     exit(status);
>>  }
>>
>>  /* fork support code */
>> diff --git a/tests/Makefile.sources b/tests/Makefile.sources
>> index 8fb2de8..25f0c4a 100644
>> --- a/tests/Makefile.sources
>> +++ b/tests/Makefile.sources
>> @@ -62,6 +62,7 @@ TESTS_progs_M = \
>>       gem_tiled_partial_pwrite_pread \
>>       gem_userptr_blits \
>>       gem_write_read_ring_switch \
>> +     igt_capture \
>>       kms_addfb_basic \
>>       kms_atomic \
>>       kms_cursor_crc \
>> diff --git a/tests/igt_capture.c b/tests/igt_capture.c
>> new file mode 100644
>> index 0000000..fd008d0
>> --- /dev/null
>> +++ b/tests/igt_capture.c
>> @@ -0,0 +1,93 @@
>> +/*
>> + * Copyright © 2015 Intel Corporation
>> + *
>> + * Permission is hereby granted, free of charge, to any person obtaining a
>> + * copy of this software and associated documentation files (the "Software"),
>> + * to deal in the Software without restriction, including without limitation
>> + * the rights to use, copy, modify, merge, publish, distribute, sublicense,
>> + * and/or sell copies of the Software, and to permit persons to whom the
>> + * Software is furnished to do so, subject to the following conditions:
>> + *
>> + * The above copyright notice and this permission notice (including the next
>> + * paragraph) shall be included in all copies or substantial portions of the
>> + * Software.
>> + *
>> + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
>> + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
>> + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
>> + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
>> + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
>> + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
>> + * IN THE SOFTWARE.
>> + *
>> + * Authors:
>> + *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
>> + *
>> + */
>> +
>> +#include "igt.h"
>> +#include <unistd.h>
>> +#include <stdlib.h>
>> +#include <stdio.h>
>> +#include <string.h>
>> +#include <fcntl.h>
>> +#include <inttypes.h>
>> +#include <errno.h>
>> +#include <sys/stat.h>
>> +#include <sys/ioctl.h>
>> +
>> +static FILE* kmsg;
>> +
>> +static void
>> +test_kmsg(void)
>> +{
>> +     fputs("TEST (KMSG)\n", kmsg);
>> +     fflush(kmsg);
>> +     igt_fail(IGT_EXIT_FAILURE);
>> +}
>> +
>> +static void
>> +test_warn(void)
>> +{
>> +     igt_warn("TEST (WARN)\n");
>> +     igt_fail(IGT_EXIT_FAILURE);
>> +}
>> +
>> +static void
>> +test_debug(void)
>> +{
>> +     igt_debug("TEST (DEBUG)\n");
>> +     igt_fail(IGT_EXIT_FAILURE);
>> +}
>> +
>> +static void
>> +test_combined(void)
>> +{
>> +     igt_warn("TEST #1 (WARN)\n");
>> +     fputs("TEST #1\n", kmsg);
>> +     igt_warn("TEST #2 (WARN)\n");
>> +     fputs("TEST #2\n", kmsg);
>> +     fflush(kmsg);
>> +     igt_fail(IGT_EXIT_FAILURE);
>> +}
>> +
>> +igt_main
>> +{
>> +     igt_fixture {
>> +             kmsg = fopen("/dev/kmsg", "w");
>> +             igt_require(kmsg != NULL);
>> +     }
>> +
>> +     igt_subtest("kmsg")
>> +             test_kmsg();
>> +     igt_subtest("warn")
>> +             test_warn();
>> +     igt_subtest("debug")
>> +             test_debug();
>> +     igt_subtest("combined")
>> +             test_combined();
>> +
>> +     igt_fixture {
>> +             fclose(kmsg);
>> +     }
>> +}
>> --
>> 2.4.3
>>
>> _______________________________________________
>> Intel-gfx mailing list
>> Intel-gfx@lists.freedesktop.org
>> http://lists.freedesktop.org/mailman/listinfo/intel-gfx
>
> --
> Daniel Vetter
> Software Engineer, Intel Corporation
> http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-18 17:41   ` [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it Thomas Wood
@ 2015-11-18 18:12     ` Joonas Lahtinen
  0 siblings, 0 replies; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-18 18:12 UTC (permalink / raw)
  To: Thomas Wood, Daniel Vetter
  Cc: Intel graphics driver community testing & development

On ke, 2015-11-18 at 17:41 +0000, Thomas Wood wrote:
> On 18 November 2015 at 15:44, Daniel Vetter <daniel@ffwll.ch> wrote:
> > On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen wrote:
> > > Cc: Thomas Wood <thomas.wood@intel.com>
> > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > > Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> > 
> > Given that we have all that in piglit already the commit message is
> > a bit
> > thin on justification. Why do we need this in igt too? How does
> > this
> > interact with the piglit dmesg capture?
> 

In short, it makes IGT be able to run the tests on its own with only
small additions to the current code, and the output can then be parsed
with piglit outside of the DUT. I will add a canonical option to
produce a CSV-like output. It's just about moving a small bit of the
test running logic to IGT to make it produce meaningful output on its
own.

> There are a few tests that rely on checking dmesg to determine if the
> test failed (such as gem_hangcheck_forcewake and
> kms_flip_event_leak).
> Although not implemented in this patch, it might be useful to use
> this
> feature to actually report a failure in those cases.
> 

Next version makes any test fail if kernel domain messages with
priority LOG_NOTICE or higher are output during test.

Regards, Joonas

> 
> > 
> > > ---
> > >  lib/igt_core.c         | 113
> > > ++++++++++++++++++++++++++++++++++++++++++++++---
> > >  tests/Makefile.sources |   1 +
> > >  tests/igt_capture.c    |  93
> > > ++++++++++++++++++++++++++++++++++++++++
> > >  3 files changed, 200 insertions(+), 7 deletions(-)
> > >  create mode 100644 tests/igt_capture.c
> > > 
> > > diff --git a/lib/igt_core.c b/lib/igt_core.c
> > > index 04a0ab2..e73175a 100644
> > > --- a/lib/igt_core.c
> > > +++ b/lib/igt_core.c
> > > @@ -211,6 +211,8 @@
> > >   * "--help" command line option.
> > >   */
> > > 
> > > +#define IGT_KMSG_CAPTURE_DUMP_BUF_SIZE               4096
> > > +
> > >  static unsigned int exit_handler_count;
> > >  const char *igt_interactive_debug;
> > > 
> > > @@ -247,6 +249,10 @@ enum {
> > >  static int igt_exitcode = IGT_EXIT_SUCCESS;
> > >  static const char *command_str;
> > > 
> > > +static int igt_kmsg_capture_fd;
> > > +static char* igt_kmsg_capture_dump_buf;
> > > +static pthread_mutex_t kmsg_mutex = PTHREAD_MUTEX_INITIALIZER;
> > > +
> > >  static char* igt_log_domain_filter;
> > >  static struct {
> > >       char *entries[256];
> > > @@ -312,6 +318,71 @@ static void _igt_log_buffer_dump(void)
> > >       pthread_mutex_unlock(&log_buffer_mutex);
> > >  }
> > > 
> > > +static void _igt_kmsg_capture_reset(void)
> > > +{
> > > +     if (igt_kmsg_capture_fd == -1)
> > > +             return;
> > > +
> > > +     pthread_mutex_lock(&kmsg_mutex);
> > > +
> > > +     lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> > > +
> > > +     pthread_mutex_unlock(&kmsg_mutex);
> > > +}
> > > +
> > > +static void _igt_kmsg_capture_dump(void)
> > > +{
> > > +     size_t nbytes;
> > > +     int nlines;
> > > +     char *p;
> > > +     char *p0;
> > > +     int c;
> > > +
> > > +     if (igt_kmsg_capture_fd == -1 ||
> > > +         igt_kmsg_capture_dump_buf == NULL)
> > > +             return;
> > > +
> > > +     pthread_mutex_lock(&kmsg_mutex);
> > > +
> > > +
> > > +     nlines = 0;
> > > +     do {
> > > +             errno = 0;
> > > +             nbytes = read(igt_kmsg_capture_fd,
> > > +                           igt_kmsg_capture_dump_buf,
> > > +                           IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> > > +
> > > +             if (nbytes == -1)
> > > +                     continue;
> > > +
> > > +             if (!nlines)
> > > +                     fprintf(stderr, "**** KMSG ****\n");
> > > +
> > > +             p = p0 = strchr(igt_kmsg_capture_dump_buf, ';') +
> > > 1;
> > > +             while (p - p0 < nbytes) {
> > > +                     if (*p != '\\') {
> > > +                             fputc(*p++, stderr);
> > > +                             continue;
> > > +                     }
> > > +                     sscanf(p, "\\x%x", &c);
> > > +                     fputc(c, stderr);
> > > +                     p += 4;
> > > +             }
> > > +             //fputs(strchr(igt_kmsg_capture_dump_buf, ';') + 1,
> > > stderr);
> > > +             nlines++;
> > > +     } while(errno == 0);
> > > +
> > > +     if (nlines)
> > > +             fprintf(stderr, "****  END  ****\n");
> > > +     else
> > > +             fprintf(stderr, "No kmsg.\n");
> > > +
> > > +     if (errno != EAGAIN)
> > > +             fprintf(stderr, "Incomplete kmsg.\n");
> > > +
> > > +     pthread_mutex_unlock(&kmsg_mutex);
> > > +}
> > > +
> > >  __attribute__((format(printf, 1, 2)))
> > >  static void kmsg(const char *format, ...)
> > >  #define KERN_EMER    "<0>"
> > > @@ -330,11 +401,15 @@ static void kmsg(const char *format, ...)
> > >       if (file == NULL)
> > >               return;
> > > 
> > > +     pthread_mutex_lock(&kmsg_mutex);
> > > +
> > >       va_start(ap, format);
> > >       vfprintf(file, format, ap);
> > >       va_end(ap);
> > > 
> > >       fclose(file);
> > > +
> > > +     pthread_mutex_unlock(&kmsg_mutex);
> > >  }
> > > 
> > >  static void gettime(struct timespec *ts)
> > > @@ -527,6 +602,15 @@ static int common_init(int *argc, char
> > > **argv,
> > >       int ret = 0;
> > >       const char *env;
> > > 
> > > +     igt_kmsg_capture_fd = open("/dev/kmsg", O_RDWR |
> > > O_NONBLOCK);
> > > +     if (igt_kmsg_capture_fd != -1) {
> > > +             igt_kmsg_capture_dump_buf =
> > > +                     malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> > > +             if(igt_kmsg_capture_dump_buf == NULL)
> > > +                     igt_warn("Unable to allocate memory, "
> > > +                              "will not dump kmsg.\n");
> > > +     }
> > > +
> > >       if (!isatty(STDOUT_FILENO) || getenv("IGT_PLAIN_OUTPUT"))
> > >               __igt_plain_output = true;
> > > 
> > > @@ -796,6 +880,7 @@ bool __igt_run_subtest(const char
> > > *subtest_name)
> > >       igt_debug("Starting subtest: %s\n", subtest_name);
> > > 
> > >       _igt_log_buffer_reset();
> > > +     _igt_kmsg_capture_reset();
> > > 
> > >       gettime(&subtest_time);
> > >       return (in_subtest = subtest_name);
> > > @@ -972,6 +1057,7 @@ void igt_fail(int exitcode)
> > >               exit(exitcode);
> > > 
> > >       _igt_log_buffer_dump();
> > > +     _igt_kmsg_capture_dump();
> > > 
> > >       if (in_subtest) {
> > >               if (exitcode == IGT_EXIT_TIMEOUT)
> > > @@ -1072,16 +1158,21 @@ void __igt_fail_assert(const char
> > > *domain, const char *file, const int line,
> > >   */
> > >  void igt_exit(void)
> > >  {
> > > +     int status = IGT_EXIT_SUCCESS;
> > > +
> > >       igt_exit_called = true;
> > > 
> > >       if (run_single_subtest && !run_single_subtest_found) {
> > >               igt_warn("Unknown subtest: %s\n",
> > > run_single_subtest);
> > > -             exit(IGT_EXIT_INVALID);
> > > +             status = IGT_EXIT_INVALID;
> > > +             goto do_exit;
> > >       }
> > > 
> > > 
> > > -     if (igt_only_list_subtests())
> > > -             exit(IGT_EXIT_SUCCESS);
> > > +     if (igt_only_list_subtests()) {
> > > +             status = IGT_EXIT_SUCCESS;
> > > +             goto do_exit;
> > > +     }
> > > 
> > >       kmsg(KERN_INFO "%s: exiting, ret=%d\n", command_str,
> > > igt_exitcode);
> > >       igt_debug("Exiting with status code %d\n", igt_exitcode);
> > > @@ -1111,18 +1202,26 @@ void igt_exit(void)
> > > 
> > > 
> > >               printf("%s (%.3fs)\n", result, elapsed);
> > > -             exit(igt_exitcode);
> > > +             status = igt_exitcode;
> > > +             goto do_exit;
> > >       }
> > > 
> > >       /* Calling this without calling one of the above is a
> > > failure */
> > >       assert(skipped_one || succeeded_one || failed_one);
> > > 
> > >       if (failed_one)
> > > -             exit(igt_exitcode);
> > > +             status = igt_exitcode;
> > >       else if (succeeded_one)
> > > -             exit(IGT_EXIT_SUCCESS);
> > > +             status = IGT_EXIT_SUCCESS;
> > >       else
> > > -             exit(IGT_EXIT_SKIP);
> > > +             status = IGT_EXIT_SKIP;
> > > +do_exit:
> > > +     if (igt_kmsg_capture_fd != -1)
> > > +             close(igt_kmsg_capture_fd);
> > > +     if (igt_kmsg_capture_dump_buf != NULL)
> > > +             free(igt_kmsg_capture_dump_buf);
> > > +
> > > +     exit(status);
> > >  }
> > > 
> > >  /* fork support code */
> > > diff --git a/tests/Makefile.sources b/tests/Makefile.sources
> > > index 8fb2de8..25f0c4a 100644
> > > --- a/tests/Makefile.sources
> > > +++ b/tests/Makefile.sources
> > > @@ -62,6 +62,7 @@ TESTS_progs_M = \
> > >       gem_tiled_partial_pwrite_pread \
> > >       gem_userptr_blits \
> > >       gem_write_read_ring_switch \
> > > +     igt_capture \
> > >       kms_addfb_basic \
> > >       kms_atomic \
> > >       kms_cursor_crc \
> > > diff --git a/tests/igt_capture.c b/tests/igt_capture.c
> > > new file mode 100644
> > > index 0000000..fd008d0
> > > --- /dev/null
> > > +++ b/tests/igt_capture.c
> > > @@ -0,0 +1,93 @@
> > > +/*
> > > + * Copyright © 2015 Intel Corporation
> > > + *
> > > + * Permission is hereby granted, free of charge, to any person
> > > obtaining a
> > > + * copy of this software and associated documentation files (the
> > > "Software"),
> > > + * to deal in the Software without restriction, including
> > > without limitation
> > > + * the rights to use, copy, modify, merge, publish, distribute,
> > > sublicense,
> > > + * and/or sell copies of the Software, and to permit persons to
> > > whom the
> > > + * Software is furnished to do so, subject to the following
> > > conditions:
> > > + *
> > > + * The above copyright notice and this permission notice
> > > (including the next
> > > + * paragraph) shall be included in all copies or substantial
> > > portions of the
> > > + * Software.
> > > + *
> > > + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY
> > > KIND, EXPRESS OR
> > > + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
> > > MERCHANTABILITY,
> > > + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO
> > > EVENT SHALL
> > > + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM,
> > > DAMAGES OR OTHER
> > > + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR
> > > OTHERWISE, ARISING
> > > + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR
> > > OTHER DEALINGS
> > > + * IN THE SOFTWARE.
> > > + *
> > > + * Authors:
> > > + *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> > > + *
> > > + */
> > > +
> > > +#include "igt.h"
> > > +#include <unistd.h>
> > > +#include <stdlib.h>
> > > +#include <stdio.h>
> > > +#include <string.h>
> > > +#include <fcntl.h>
> > > +#include <inttypes.h>
> > > +#include <errno.h>
> > > +#include <sys/stat.h>
> > > +#include <sys/ioctl.h>
> > > +
> > > +static FILE* kmsg;
> > > +
> > > +static void
> > > +test_kmsg(void)
> > > +{
> > > +     fputs("TEST (KMSG)\n", kmsg);
> > > +     fflush(kmsg);
> > > +     igt_fail(IGT_EXIT_FAILURE);
> > > +}
> > > +
> > > +static void
> > > +test_warn(void)
> > > +{
> > > +     igt_warn("TEST (WARN)\n");
> > > +     igt_fail(IGT_EXIT_FAILURE);
> > > +}
> > > +
> > > +static void
> > > +test_debug(void)
> > > +{
> > > +     igt_debug("TEST (DEBUG)\n");
> > > +     igt_fail(IGT_EXIT_FAILURE);
> > > +}
> > > +
> > > +static void
> > > +test_combined(void)
> > > +{
> > > +     igt_warn("TEST #1 (WARN)\n");
> > > +     fputs("TEST #1\n", kmsg);
> > > +     igt_warn("TEST #2 (WARN)\n");
> > > +     fputs("TEST #2\n", kmsg);
> > > +     fflush(kmsg);
> > > +     igt_fail(IGT_EXIT_FAILURE);
> > > +}
> > > +
> > > +igt_main
> > > +{
> > > +     igt_fixture {
> > > +             kmsg = fopen("/dev/kmsg", "w");
> > > +             igt_require(kmsg != NULL);
> > > +     }
> > > +
> > > +     igt_subtest("kmsg")
> > > +             test_kmsg();
> > > +     igt_subtest("warn")
> > > +             test_warn();
> > > +     igt_subtest("debug")
> > > +             test_debug();
> > > +     igt_subtest("combined")
> > > +             test_combined();
> > > +
> > > +     igt_fixture {
> > > +             fclose(kmsg);
> > > +     }
> > > +}
> > > --
> > > 2.4.3
> > > 
> > > _______________________________________________
> > > Intel-gfx mailing list
> > > Intel-gfx@lists.freedesktop.org
> > > http://lists.freedesktop.org/mailman/listinfo/intel-gfx
> > 
> > --
> > Daniel Vetter
> > Software Engineer, Intel Corporation
> > http://blog.ffwll.ch
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-18 17:32   ` Chris Wilson
@ 2015-11-19  9:38     ` Daniel Vetter
  2015-11-19  9:41       ` Daniel Vetter
  2015-11-19 10:35     ` [PATCH i-g-t v2] lib/igt_core: Add kmsg capture and dumping Joonas Lahtinen
  1 sibling, 1 reply; 23+ messages in thread
From: Daniel Vetter @ 2015-11-19  9:38 UTC (permalink / raw)
  To: Chris Wilson, Daniel Vetter, Joonas Lahtinen,
	Intel graphics driver community testing & development,
	Thomas Wood

On Wed, Nov 18, 2015 at 05:32:59PM +0000, Chris Wilson wrote:
> On Wed, Nov 18, 2015 at 04:44:20PM +0100, Daniel Vetter wrote:
> > On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen wrote:
> > > Cc: Thomas Wood <thomas.wood@intel.com>
> > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > > Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> > 
> > Given that we have all that in piglit already the commit message is a bit
> > thin on justification. Why do we need this in igt too? How does this
> > interact with the piglit dmesg capture?
> 
> It's doesn't interfere with anyone else parsing kmsg/dmesg for
> themselves, but it adds very useful functionality to standalone igt.
> Which to me is significantly more valuable and I have been patching it
> into igt for over a year and wished it was taken more seriously given
> the number of incorrect bug reports generated.

Ah, the "It doesn't interfere ..." is the crucial part I missed, I didn't
know you could read dmesg in parallel without eating message for other
consumers. Jonaas, with the above used as commit message (or something
similar) this is Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>

Cheers, Daniel
-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-19  9:38     ` Daniel Vetter
@ 2015-11-19  9:41       ` Daniel Vetter
  2015-11-20 11:22         ` Joonas Lahtinen
  0 siblings, 1 reply; 23+ messages in thread
From: Daniel Vetter @ 2015-11-19  9:41 UTC (permalink / raw)
  To: Chris Wilson, Daniel Vetter, Joonas Lahtinen,
	Intel graphics driver community testing & development,
	Thomas Wood

On Thu, Nov 19, 2015 at 10:38 AM, Daniel Vetter <daniel@ffwll.ch> wrote:
> On Wed, Nov 18, 2015 at 05:32:59PM +0000, Chris Wilson wrote:
>> On Wed, Nov 18, 2015 at 04:44:20PM +0100, Daniel Vetter wrote:
>> > On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen wrote:
>> > > Cc: Thomas Wood <thomas.wood@intel.com>
>> > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
>> > > Cc: Damien Lespiau <damien.lespiau@intel.com>
>> > > Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
>> >
>> > Given that we have all that in piglit already the commit message is a bit
>> > thin on justification. Why do we need this in igt too? How does this
>> > interact with the piglit dmesg capture?
>>
>> It's doesn't interfere with anyone else parsing kmsg/dmesg for
>> themselves, but it adds very useful functionality to standalone igt.
>> Which to me is significantly more valuable and I have been patching it
>> into igt for over a year and wished it was taken more seriously given
>> the number of incorrect bug reports generated.
>
> Ah, the "It doesn't interfere ..." is the crucial part I missed, I didn't
> know you could read dmesg in parallel without eating message for other
> consumers. Jonaas, with the above used as commit message (or something
> similar) this is Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>

Ok, I need to retract this. piglit does some dmesg filtering, how do
we make sure these two definitions of what's considered failing dmesg
noise match up?
-Daniel
-- 
Daniel Vetter
Software Engineer, Intel Corporation
+41 (0) 79 365 57 48 - http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* [PATCH i-g-t v2] lib/igt_core: Add kmsg capture and dumping
  2015-11-18 17:32   ` Chris Wilson
  2015-11-19  9:38     ` Daniel Vetter
@ 2015-11-19 10:35     ` Joonas Lahtinen
  2015-11-19 11:32       ` Chris Wilson
  1 sibling, 1 reply; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-19 10:35 UTC (permalink / raw)
  To: Intel graphics driver community testing & development; +Cc: Thomas Wood

Capture the output from /dev/kmsg during test execution independantly
of other concurrent watchers like Piglit test runner.

The captured output is analyzed and the test will fail if log messages
with higher priority than LOG_NOTICE are emitted from any domain.

Also adding igt_capture to lib/tests which will fail and produce kmsg
output which should be captured by the new code and also demonstrate
failing just due to /dev/kmsg.

v2:
- Reopen/close the kmsg FD per each test (Chris)
- Better commit mesage (Daniel)
- Display failure due to kmsg only as FAIL (KMSG)

Cc: Thomas Wood <thomas.wood@intel.com>
Cc: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Damien Lespiau <damien.lespiau@intel.com>
Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>
Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
---
 lib/igt_core.c             | 113 +++++++++++++++++++++++++++++++++++++++++++--
 lib/igt_core.h             |   7 +++
 lib/tests/.gitignore       |   1 +
 lib/tests/Makefile.sources |   1 +
 lib/tests/igt_capture.c    |  88 +++++++++++++++++++++++++++++++++++
 5 files changed, 207 insertions(+), 3 deletions(-)
 create mode 100644 lib/tests/igt_capture.c

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 04a0ab2..cb782dc 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -43,6 +43,7 @@
 #include <getopt.h>
 #include <stdlib.h>
 #include <unistd.h>
+#include <syslog.h>
 #include <sys/wait.h>
 #include <sys/types.h>
 #ifdef __linux__
@@ -211,6 +212,8 @@
  * "--help" command line option.
  */
 
+#define IGT_KMSG_CAPTURE_DUMP_BUF_SIZE		4096
+
 static unsigned int exit_handler_count;
 const char *igt_interactive_debug;
 
@@ -247,6 +250,9 @@ enum {
 static int igt_exitcode = IGT_EXIT_SUCCESS;
 static const char *command_str;
 
+static int igt_kmsg_capture_fd = -1;
+static char* igt_kmsg_capture_dump_buf = NULL;
+
 static char* igt_log_domain_filter;
 static struct {
 	char *entries[256];
@@ -312,6 +318,93 @@ static void _igt_log_buffer_dump(void)
 	pthread_mutex_unlock(&log_buffer_mutex);
 }
 
+static void _igt_kmsg_capture_reset(void)
+{
+	if (igt_kmsg_capture_fd != -1)
+		close(igt_kmsg_capture_fd);
+
+	igt_kmsg_capture_fd = open("/dev/kmsg",
+				   O_RDONLY | O_NONBLOCK);
+
+	if (igt_kmsg_capture_fd == -1)
+		return;
+
+	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
+
+	if (igt_kmsg_capture_dump_buf == NULL)
+		igt_kmsg_capture_dump_buf =
+			malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
+
+	if (igt_kmsg_capture_dump_buf == NULL)
+		igt_warn("Unable to allocate memory, "
+			 "will not dump kmsg.\n");
+}
+
+static int _igt_kmsg_capture_dump(bool notify_empty, int show_priority)
+{
+	size_t nbytes;
+	int nlines;
+	int prefix;
+	int facility;
+	int priority;
+	char *p;
+	int c;
+
+	if (igt_kmsg_capture_fd == -1 ||
+	    igt_kmsg_capture_dump_buf == NULL)
+		return 0;
+
+	nlines = 0;
+	do {
+		errno = 0;
+		nbytes = read(igt_kmsg_capture_fd,
+			      igt_kmsg_capture_dump_buf,
+			      IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
+
+		if (nbytes == -1)
+			continue;
+
+		sscanf(igt_kmsg_capture_dump_buf, "%d;", &prefix);
+		priority = prefix & 0x7;
+
+		if (priority > show_priority)
+			continue;
+
+		if (!nlines)
+			fprintf(stderr, "**** KMSG ****\n");
+
+		p = strchr(igt_kmsg_capture_dump_buf, ';') + 1;
+		while (p - igt_kmsg_capture_dump_buf < nbytes) {
+			if (*p != '\\') {
+				fputc(*p++, stderr);
+				continue;
+			}
+			sscanf(p, "\\x%x", &c);
+			fputc(c, stderr);
+			p += 4;
+		}
+		nlines++;
+	} while(errno == 0);
+
+	if (nlines) {
+		fprintf(stderr, "****  END  ****\n");
+	} else {
+		if (notify_empty)
+			fprintf(stderr, "No kmsg.\n");
+	}
+
+	if (errno != EAGAIN)
+		fprintf(stderr, "Error: Incomplete kmsg!\n");
+
+	close(igt_kmsg_capture_fd);
+	igt_kmsg_capture_fd = -1;
+
+	free(igt_kmsg_capture_dump_buf);
+	igt_kmsg_capture_dump_buf = NULL;
+
+	return nlines;
+}
+
 __attribute__((format(printf, 1, 2)))
 static void kmsg(const char *format, ...)
 #define KERN_EMER	"<0>"
@@ -676,8 +769,10 @@ out:
 	/* install exit handler, to ensure we clean up */
 	igt_install_exit_handler(common_exit_handler);
 
-	if (!test_with_subtests)
+	if (!test_with_subtests) {
 		gettime(&subtest_time);
+		_igt_kmsg_capture_reset();
+	}
 
 	for (i = 0; (optind + i) < *argc; i++)
 		argv[i + 1] = argv[optind + i];
@@ -796,8 +891,9 @@ bool __igt_run_subtest(const char *subtest_name)
 	igt_debug("Starting subtest: %s\n", subtest_name);
 
 	_igt_log_buffer_reset();
-
+	_igt_kmsg_capture_reset();
 	gettime(&subtest_time);
+
 	return (in_subtest = subtest_name);
 }
 
@@ -931,6 +1027,9 @@ void __igt_skip_check(const char *file, const int line,
  */
 void igt_success(void)
 {
+	if (_igt_kmsg_capture_dump(false, LOG_NOTICE))
+		return igt_fail(IGT_EXIT_FAILURE_KMSG);
+
 	succeeded_one = true;
 	if (in_subtest)
 		exit_subtest("SUCCESS");
@@ -971,11 +1070,17 @@ void igt_fail(int exitcode)
 	if (test_child)
 		exit(exitcode);
 
+	/* Show kmsg if not already shown. */
+	if (exitcode != IGT_EXIT_FAILURE_KMSG)
+		_igt_kmsg_capture_dump(true, LOG_DEBUG);
+
 	_igt_log_buffer_dump();
 
 	if (in_subtest) {
 		if (exitcode == IGT_EXIT_TIMEOUT)
 			exit_subtest("TIMEOUT");
+		else if (exitcode == IGT_EXIT_FAILURE_KMSG)
+			exit_subtest("FAIL (KMSG)");
 		else
 			exit_subtest("FAIL");
 	} else {
@@ -1079,7 +1184,6 @@ void igt_exit(void)
 		exit(IGT_EXIT_INVALID);
 	}
 
-
 	if (igt_only_list_subtests())
 		exit(IGT_EXIT_SUCCESS);
 
@@ -1105,6 +1209,9 @@ void igt_exit(void)
 			case IGT_EXIT_SKIP:
 				result = "SKIP";
 				break;
+			case IGT_EXIT_FAILURE_KMSG:
+				result = "FAIL (KMSG)";
+				break;
 			default:
 				result = "FAIL";
 		}
diff --git a/lib/igt_core.h b/lib/igt_core.h
index a244fc3..3a9f41b 100644
--- a/lib/igt_core.h
+++ b/lib/igt_core.h
@@ -93,6 +93,13 @@ extern bool __igt_plain_output;
  */
 #define IGT_EXIT_FAILURE 99
 
+/**
+ * IGT_EXIT_FAILURE_KMSG
+ *
+ * Exit status indicing printk warnings/errors during test
+ */
+#define IGT_EXIT_FAILURE_KMSG 98
+
 bool __igt_fixture(void);
 void __igt_fixture_complete(void);
 void __igt_fixture_end(void) __attribute__((noreturn));
diff --git a/lib/tests/.gitignore b/lib/tests/.gitignore
index a4f1080..c49c178 100644
--- a/lib/tests/.gitignore
+++ b/lib/tests/.gitignore
@@ -1,5 +1,6 @@
 # Please keep sorted alphabetically
 igt_assert
+igt_capture
 igt_fork_helper
 igt_invalid_subtest_name
 igt_list_only
diff --git a/lib/tests/Makefile.sources b/lib/tests/Makefile.sources
index 777b9c1..d2b5e08 100644
--- a/lib/tests/Makefile.sources
+++ b/lib/tests/Makefile.sources
@@ -1,4 +1,5 @@
 check_PROGRAMS = \
+	igt_capture \
 	igt_no_exit \
 	igt_no_exit_list_only \
 	igt_fork_helper \
diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
new file mode 100644
index 0000000..3a9c528
--- /dev/null
+++ b/lib/tests/igt_capture.c
@@ -0,0 +1,88 @@
+/*
+ * Copyright © 2015 Intel Corporation
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a
+ * copy of this software and associated documentation files (the "Software"),
+ * to deal in the Software without restriction, including without limitation
+ * the rights to use, copy, modify, merge, publish, distribute, sublicense,
+ * and/or sell copies of the Software, and to permit persons to whom the
+ * Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice (including the next
+ * paragraph) shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
+ * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
+ * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
+ * IN THE SOFTWARE.
+ *
+ * Authors:
+ *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
+ *
+ */
+
+#include "igt_core.h"
+#include <stdio.h>
+
+static FILE* kmsg;
+
+static void
+test_kmsg(bool fail)
+{
+	fputs("TEST (KMSG)\n", kmsg);
+	fflush(kmsg);
+	if (fail)
+		igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_warn(void)
+{
+	igt_warn("TEST (WARN)\n");
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_debug(void)
+{
+	igt_debug("TEST (DEBUG)\n");
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_combined(void)
+{
+	igt_warn("TEST #1 (WARN)\n");
+	fputs("TEST #1\n", kmsg);
+	igt_warn("TEST #2 (WARN)\n");
+	fputs("TEST #2\n", kmsg);
+	fflush(kmsg);
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+igt_main
+{
+	igt_fixture {
+		kmsg = fopen("/dev/kmsg", "w");
+		igt_require(kmsg != NULL);
+	}
+
+	igt_subtest("kmsg")
+		test_kmsg(true);
+	igt_subtest("kmsg-success")
+		test_kmsg(false);
+	igt_subtest("warn")
+		test_warn();
+	igt_subtest("debug")
+		test_debug();
+	igt_subtest("combined")
+		test_combined();
+
+	igt_fixture {
+		fclose(kmsg);
+	}
+}
-- 
2.4.3

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t v2] lib/igt_core: Add kmsg capture and dumping
  2015-11-19 10:35     ` [PATCH i-g-t v2] lib/igt_core: Add kmsg capture and dumping Joonas Lahtinen
@ 2015-11-19 11:32       ` Chris Wilson
  2015-11-20 11:46         ` Joonas Lahtinen
  0 siblings, 1 reply; 23+ messages in thread
From: Chris Wilson @ 2015-11-19 11:32 UTC (permalink / raw)
  To: Joonas Lahtinen
  Cc: Intel graphics driver community testing & development, Thomas Wood

On Thu, Nov 19, 2015 at 12:35:23PM +0200, Joonas Lahtinen wrote:
> +static void _igt_kmsg_capture_reset(void)
> +{
> +	if (igt_kmsg_capture_fd != -1)
> +		close(igt_kmsg_capture_fd);
> +
> +	igt_kmsg_capture_fd = open("/dev/kmsg",
> +				   O_RDONLY | O_NONBLOCK);

We should O_CLOEXEC as well.

> +
> +	if (igt_kmsg_capture_fd == -1)
> +		return;
> +
> +	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> +
> +	if (igt_kmsg_capture_dump_buf == NULL)
> +		igt_kmsg_capture_dump_buf =
> +			malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> +
> +	if (igt_kmsg_capture_dump_buf == NULL)
> +		igt_warn("Unable to allocate memory, "
> +			 "will not dump kmsg.\n");

If we allocate first, then bail, we know if we have the fd we have the
buffer as well.

> +}
> +
> +static int _igt_kmsg_capture_dump(bool notify_empty, int show_priority)
> +{
> +	size_t nbytes;
> +	int nlines;
> +	int prefix;
> +	int facility;
> +	int priority;
> +	char *p;
> +	int c;
> +
> +	if (igt_kmsg_capture_fd == -1 ||
> +	    igt_kmsg_capture_dump_buf == NULL)
> +		return 0;

i.e. we can just do if (fd == -1) return 0;

> +
> +	nlines = 0;
> +	do {
> +		errno = 0;
> +		nbytes = read(igt_kmsg_capture_fd,
> +			      igt_kmsg_capture_dump_buf,
> +			      IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> +
> +		if (nbytes == -1)
> +			continue;
> +
> +		sscanf(igt_kmsg_capture_dump_buf, "%d;", &prefix);
> +		priority = prefix & 0x7;
> +
> +		if (priority > show_priority)
> +			continue;
> +
> +		if (!nlines)
> +			fprintf(stderr, "**** KMSG ****\n");
> +
> +		p = strchr(igt_kmsg_capture_dump_buf, ';') + 1;
> +		while (p - igt_kmsg_capture_dump_buf < nbytes) {
> +			if (*p != '\\') {
> +				fputc(*p++, stderr);
> +				continue;
> +			}
> +			sscanf(p, "\\x%x", &c);
> +			fputc(c, stderr);
> +			p += 4;

Maybe:
	/* Decode non-printable characters escaped by '\x01' */
	int c = *p++;
	if (c == '\\') {
		if (p - igt_kmgs_capture_dump_buf > nbytes - 3)
			break;
		sscanf(p+1, "%x", &c);
		p += 3;
	}
	fputc(c, stderr);

> +		}
> +		nlines++;
> +	} while(errno == 0);
> +
> +	if (nlines) {
> +		fprintf(stderr, "****  END  ****\n");
> +	} else {
> +		if (notify_empty)
> +			fprintf(stderr, "No kmsg.\n");
> +	}
> +
> +	if (errno != EAGAIN)
> +		fprintf(stderr, "Error: Incomplete kmsg!\n");
> +
> +	close(igt_kmsg_capture_fd);
> +	igt_kmsg_capture_fd = -1;
> +
> +	free(igt_kmsg_capture_dump_buf);
> +	igt_kmsg_capture_dump_buf = NULL;

Hmm, single-shot.

I have in mind more of an automatic debug feature coupled with error
detection like how we automatically go back and print the debug log if
the test fails. As I understand it, with a FAIL (KMSG) we currently lose
any lower priority output.

The integration looks good to me otherwise. But someone else will have
to vouch for test-runner/piglit handling of "FAIL (KMSG)" (I used WARN).
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-19  9:41       ` Daniel Vetter
@ 2015-11-20 11:22         ` Joonas Lahtinen
  2015-11-20 11:34           ` Chris Wilson
  0 siblings, 1 reply; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-20 11:22 UTC (permalink / raw)
  To: Daniel Vetter, Chris Wilson,
	Intel graphics driver community testing & development,
	Thomas Wood

On to, 2015-11-19 at 10:41 +0100, Daniel Vetter wrote:
> On Thu, Nov 19, 2015 at 10:38 AM, Daniel Vetter <daniel@ffwll.ch>
> wrote:
> > On Wed, Nov 18, 2015 at 05:32:59PM +0000, Chris Wilson wrote:
> > > On Wed, Nov 18, 2015 at 04:44:20PM +0100, Daniel Vetter wrote:
> > > > On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen
> > > > wrote:
> > > > > Cc: Thomas Wood <thomas.wood@intel.com>
> > > > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > > > > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > > > > Signed-off-by: Joonas Lahtinen <
> > > > > joonas.lahtinen@linux.intel.com>
> > > > 
> > > > Given that we have all that in piglit already the commit
> > > > message is a bit
> > > > thin on justification. Why do we need this in igt too? How does
> > > > this
> > > > interact with the piglit dmesg capture?
> > > 
> > > It's doesn't interfere with anyone else parsing kmsg/dmesg for
> > > themselves, but it adds very useful functionality to standalone
> > > igt.
> > > Which to me is significantly more valuable and I have been
> > > patching it
> > > into igt for over a year and wished it was taken more seriously
> > > given
> > > the number of incorrect bug reports generated.
> > 
> > Ah, the "It doesn't interfere ..." is the crucial part I missed, I
> > didn't
> > know you could read dmesg in parallel without eating message for
> > other
> > consumers. Jonaas, with the above used as commit message (or
> > something
> > similar) this is Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>
> 
> Ok, I need to retract this. piglit does some dmesg filtering, how do
> we make sure these two definitions of what's considered failing dmesg
> noise match up?

I would move that decision to I-G-T, and just let piglit interpret the
FAIL (KMSG) status. Currently my proposal is that any LOG_NOTICE or
higher priority message (in any facility) causes the test to fail.

Regards, Joonas

> -Daniel
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-20 11:22         ` Joonas Lahtinen
@ 2015-11-20 11:34           ` Chris Wilson
  2015-11-23 10:31             ` Joonas Lahtinen
  0 siblings, 1 reply; 23+ messages in thread
From: Chris Wilson @ 2015-11-20 11:34 UTC (permalink / raw)
  To: Joonas Lahtinen
  Cc: Intel graphics driver community testing & development, Thomas Wood

On Fri, Nov 20, 2015 at 01:22:51PM +0200, Joonas Lahtinen wrote:
> On to, 2015-11-19 at 10:41 +0100, Daniel Vetter wrote:
> > On Thu, Nov 19, 2015 at 10:38 AM, Daniel Vetter <daniel@ffwll.ch>
> > wrote:
> > > On Wed, Nov 18, 2015 at 05:32:59PM +0000, Chris Wilson wrote:
> > > > On Wed, Nov 18, 2015 at 04:44:20PM +0100, Daniel Vetter wrote:
> > > > > On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen
> > > > > wrote:
> > > > > > Cc: Thomas Wood <thomas.wood@intel.com>
> > > > > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > > > > > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > > > > > Signed-off-by: Joonas Lahtinen <
> > > > > > joonas.lahtinen@linux.intel.com>
> > > > > 
> > > > > Given that we have all that in piglit already the commit
> > > > > message is a bit
> > > > > thin on justification. Why do we need this in igt too? How does
> > > > > this
> > > > > interact with the piglit dmesg capture?
> > > > 
> > > > It's doesn't interfere with anyone else parsing kmsg/dmesg for
> > > > themselves, but it adds very useful functionality to standalone
> > > > igt.
> > > > Which to me is significantly more valuable and I have been
> > > > patching it
> > > > into igt for over a year and wished it was taken more seriously
> > > > given
> > > > the number of incorrect bug reports generated.
> > > 
> > > Ah, the "It doesn't interfere ..." is the crucial part I missed, I
> > > didn't
> > > know you could read dmesg in parallel without eating message for
> > > other
> > > consumers. Jonaas, with the above used as commit message (or
> > > something
> > > similar) this is Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>
> > 
> > Ok, I need to retract this. piglit does some dmesg filtering, how do
> > we make sure these two definitions of what's considered failing dmesg
> > noise match up?
> 
> I would move that decision to I-G-T, and just let piglit interpret the
> FAIL (KMSG) status. Currently my proposal is that any LOG_NOTICE or
> higher priority message (in any facility) causes the test to fail.

Not NOTICE. WARN or above, since NOTICE is a "normal but significant
condition". I have been pushing for us to use NOTICE more effectively,
many of our ERRORs can just be NOTICEs since we are able to take
corrective action (and we expect to take such action).
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t v2] lib/igt_core: Add kmsg capture and dumping
  2015-11-19 11:32       ` Chris Wilson
@ 2015-11-20 11:46         ` Joonas Lahtinen
  2015-11-26 12:17           ` [PATCH i-g-t v4] " Joonas Lahtinen
  0 siblings, 1 reply; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-20 11:46 UTC (permalink / raw)
  To: Chris Wilson
  Cc: Intel graphics driver community testing & development, Thomas Wood

On to, 2015-11-19 at 11:32 +0000, Chris Wilson wrote:
> On Thu, Nov 19, 2015 at 12:35:23PM +0200, Joonas Lahtinen wrote:
> > +static void _igt_kmsg_capture_reset(void)
> > +{
> > +	if (igt_kmsg_capture_fd != -1)
> > +		close(igt_kmsg_capture_fd);
> > +
> > +	igt_kmsg_capture_fd = open("/dev/kmsg",
> > +				   O_RDONLY | O_NONBLOCK);
> 
> We should O_CLOEXEC as well.
> 

Fixed.

> > +
> > +	if (igt_kmsg_capture_fd == -1)
> > +		return;
> > +
> > +	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> > +
> > +	if (igt_kmsg_capture_dump_buf == NULL)
> > +		igt_kmsg_capture_dump_buf =
> > +			malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> > +
> > +	if (igt_kmsg_capture_dump_buf == NULL)
> > +		igt_warn("Unable to allocate memory, "
> > +			 "will not dump kmsg.\n");
> 
> If we allocate first, then bail, we know if we have the fd we have
> the
> buffer as well.
> 

I was thinking we would still perform as much of the actions that would
be done if we were able to dump the kmsg, for consistency. That is why
the buffer allocation is handled separately. But maybe it's bit
overkill.

> > +}
> > +
> > +static int _igt_kmsg_capture_dump(bool notify_empty, int
> > show_priority)
> > +{
> > +	size_t nbytes;
> > +	int nlines;
> > +	int prefix;
> > +	int facility;
> > +	int priority;
> > +	char *p;
> > +	int c;
> > +
> > +	if (igt_kmsg_capture_fd == -1 ||
> > +	    igt_kmsg_capture_dump_buf == NULL)
> > +		return 0;
> 
> i.e. we can just do if (fd == -1) return 0;
> 
> > +
> > +	nlines = 0;
> > +	do {
> > +		errno = 0;
> > +		nbytes = read(igt_kmsg_capture_fd,
> > +			      igt_kmsg_capture_dump_buf,
> > +			      IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
> > +
> > +		if (nbytes == -1)
> > +			continue;
> > +
> > +		sscanf(igt_kmsg_capture_dump_buf, "%d;", &prefix);
> > +		priority = prefix & 0x7;
> > +
> > +		if (priority > show_priority)
> > +			continue;
> > +
> > +		if (!nlines)
> > +			fprintf(stderr, "**** KMSG ****\n");
> > +
> > +		p = strchr(igt_kmsg_capture_dump_buf, ';') + 1;
> > +		while (p - igt_kmsg_capture_dump_buf < nbytes) {
> > +			if (*p != '\\') {
> > +				fputc(*p++, stderr);
> > +				continue;
> > +			}
> > +			sscanf(p, "\\x%x", &c);
> > +			fputc(c, stderr);
> > +			p += 4;
> 
> Maybe:
> 	/* Decode non-printable characters escaped by '\x01' */
> 	int c = *p++;
> 	if (c == '\\') {
> 		if (p - igt_kmgs_capture_dump_buf > nbytes - 3)
> 			break;
> 		sscanf(p+1, "%x", &c);
> 		p += 3;
> 	}
> 	fputc(c, stderr);
> 

I'll simplify this bit.

> > +		}
> > +		nlines++;
> > +	} while(errno == 0);
> > +
> > +	if (nlines) {
> > +		fprintf(stderr, "****  END  ****\n");
> > +	} else {
> > +		if (notify_empty)
> > +			fprintf(stderr, "No kmsg.\n");
> > +	}
> > +
> > +	if (errno != EAGAIN)
> > +		fprintf(stderr, "Error: Incomplete kmsg!\n");
> > +
> > +	close(igt_kmsg_capture_fd);
> > +	igt_kmsg_capture_fd = -1;
> > +
> > +	free(igt_kmsg_capture_dump_buf);
> > +	igt_kmsg_capture_dump_buf = NULL;
> 
> Hmm, single-shot.
> 
> I have in mind more of an automatic debug feature coupled with error
> detection like how we automatically go back and print the debug log
> if
> the test fails. As I understand it, with a FAIL (KMSG) we currently
> lose
> any lower priority output.
> 

Yeah, unless we allocate buffers and store when we start reading, it
has to be dumped as we read. This also causes the one thing I don't
like in the current implementation is that the KMSG appears before the
debug output. The /dev/kmsg doesn't want to be seeked (even the
documentation states that, attempted that initially regardless), so our
only option is to allocate buffers dynamically or estimate maximum
buffer size and go with that.

> The integration looks good to me otherwise. But someone else will
> have
> to vouch for test-runner/piglit handling of "FAIL (KMSG)" (I used
> WARN).

I think we could make NOTICE and WARN cause WARN (KMSG) and rest a FAIL
(KMSG) ?

Regards, Joonas

> -Chris
> 
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it.
  2015-11-20 11:34           ` Chris Wilson
@ 2015-11-23 10:31             ` Joonas Lahtinen
  0 siblings, 0 replies; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-23 10:31 UTC (permalink / raw)
  To: Chris Wilson
  Cc: Intel graphics driver community testing & development, Thomas Wood

On pe, 2015-11-20 at 11:34 +0000, Chris Wilson wrote:
> On Fri, Nov 20, 2015 at 01:22:51PM +0200, Joonas Lahtinen wrote:
> > On to, 2015-11-19 at 10:41 +0100, Daniel Vetter wrote:
> > > On Thu, Nov 19, 2015 at 10:38 AM, Daniel Vetter <daniel@ffwll.ch>
> > > wrote:
> > > > On Wed, Nov 18, 2015 at 05:32:59PM +0000, Chris Wilson wrote:
> > > > > On Wed, Nov 18, 2015 at 04:44:20PM +0100, Daniel Vetter
> > > > > wrote:
> > > > > > On Mon, Nov 16, 2015 at 03:22:23PM +0200, Joonas Lahtinen
> > > > > > wrote:
> > > > > > > Cc: Thomas Wood <thomas.wood@intel.com>
> > > > > > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > > > > > > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > > > > > > Signed-off-by: Joonas Lahtinen <
> > > > > > > joonas.lahtinen@linux.intel.com>
> > > > > > 
> > > > > > Given that we have all that in piglit already the commit
> > > > > > message is a bit
> > > > > > thin on justification. Why do we need this in igt too? How
> > > > > > does
> > > > > > this
> > > > > > interact with the piglit dmesg capture?
> > > > > 
> > > > > It's doesn't interfere with anyone else parsing kmsg/dmesg
> > > > > for
> > > > > themselves, but it adds very useful functionality to
> > > > > standalone
> > > > > igt.
> > > > > Which to me is significantly more valuable and I have been
> > > > > patching it
> > > > > into igt for over a year and wished it was taken more
> > > > > seriously
> > > > > given
> > > > > the number of incorrect bug reports generated.
> > > > 
> > > > Ah, the "It doesn't interfere ..." is the crucial part I
> > > > missed, I
> > > > didn't
> > > > know you could read dmesg in parallel without eating message
> > > > for
> > > > other
> > > > consumers. Jonaas, with the above used as commit message (or
> > > > something
> > > > similar) this is Acked-by: Daniel Vetter <
> > > > daniel.vetter@ffwll.ch>
> > > 
> > > Ok, I need to retract this. piglit does some dmesg filtering, how
> > > do
> > > we make sure these two definitions of what's considered failing
> > > dmesg
> > > noise match up?
> > 
> > I would move that decision to I-G-T, and just let piglit interpret
> > the
> > FAIL (KMSG) status. Currently my proposal is that any LOG_NOTICE or
> > higher priority message (in any facility) causes the test to fail.
> 
> Not NOTICE. WARN or above, since NOTICE is a "normal but significant
> condition". I have been pushing for us to use NOTICE more
> effectively,
> many of our ERRORs can just be NOTICEs since we are able to take
> corrective action (and we expect to take such action).
> -Chris
> 

We could have two FD's open on /dev/kmsg, we'd first scan out just the
message priorities and then at convenient display time all the messages
if the warn or above priority is in the log.

It's not ideal, but doesn't require allocating arbitary amount of
buffers.

Regards, Joonas

-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* [PATCH i-g-t v4] lib/igt_core: Add kmsg capture and dumping
  2015-11-20 11:46         ` Joonas Lahtinen
@ 2015-11-26 12:17           ` Joonas Lahtinen
  2015-11-26 14:34             ` Daniel Vetter
  0 siblings, 1 reply; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-26 12:17 UTC (permalink / raw)
  To: Intel graphics driver community testing & development
  Cc: Daniel Vetter, Thomas Wood

Capture the output from /dev/kmsg during test execution independantly
of other concurrent watchers like Piglit test runner.

The captured output is analyzed and the whole output dumped if message
with priority LOG_WARNING or higher is emitted from any domain.

Also adding igt_capture to lib/tests which will fail subtests and
produce kmsg output which should be captured by the new code.

v4:
- Do not effect return value of test, just dump (Daniel)

v3:
- Use O_CLOEXEC and clarify hex decoding (Chris)

v2:
- Reopen/close the kmsg FD per each test (Chris)
- Better commit mesage (Daniel)
- Display failure due to kmsg only as FAIL (KMSG)

Cc: Thomas Wood <thomas.wood@intel.com>
Cc: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Damien Lespiau <damien.lespiau@intel.com>
Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>
Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
---
 lib/igt_core.c             | 129 +++++++++++++++++++++++++++++++++++++++++++--
 lib/tests/.gitignore       |   1 +
 lib/tests/Makefile.sources |   2 +
 lib/tests/igt_capture.c    |  89 +++++++++++++++++++++++++++++++
 4 files changed, 218 insertions(+), 3 deletions(-)
 create mode 100644 lib/tests/igt_capture.c

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 84cf8d2..b1aa750 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -43,6 +43,7 @@
 #include <getopt.h>
 #include <stdlib.h>
 #include <unistd.h>
+#include <syslog.h>
 #include <sys/wait.h>
 #include <sys/types.h>
 #ifdef __linux__
@@ -211,6 +212,8 @@
  * "--help" command line option.
  */
 
+#define IGT_KMSG_DUMP_BUF_SIZE		4096
+
 static unsigned int exit_handler_count;
 const char *igt_interactive_debug;
 
@@ -248,6 +251,10 @@ enum {
 static int igt_exitcode = IGT_EXIT_SUCCESS;
 static const char *command_str;
 
+static int igt_kmsg_capture_fd = -1;
+static int igt_kmsg_check_fd = -1;
+static char* igt_kmsg_dump_buf = NULL;
+
 static char* igt_log_domain_filter;
 static struct {
 	char *entries[256];
@@ -313,6 +320,112 @@ static void _igt_log_buffer_dump(void)
 	pthread_mutex_unlock(&log_buffer_mutex);
 }
 
+static void _igt_kmsg_reset(void)
+{
+	if (igt_kmsg_dump_buf == NULL)
+		igt_kmsg_dump_buf = malloc(IGT_KMSG_DUMP_BUF_SIZE);
+
+	if (igt_kmsg_dump_buf == NULL) {
+		igt_warn("Unable to allocate memory, "
+			 "can not dump kmsg.\n");
+		return;
+	}
+
+	if (igt_kmsg_capture_fd == -1)
+		igt_kmsg_capture_fd = open("/dev/kmsg",
+					   O_RDONLY | O_NONBLOCK | O_CLOEXEC);
+
+	if (igt_kmsg_capture_fd == -1)
+		goto err_capture;
+
+	if (igt_kmsg_check_fd == -1)
+		igt_kmsg_check_fd = open("/dev/kmsg",
+					 O_RDONLY | O_NONBLOCK | O_CLOEXEC);
+
+	if (igt_kmsg_check_fd == -1)
+		goto err_check;
+
+	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
+	lseek(igt_kmsg_check_fd, 0, SEEK_END);
+	return;
+
+err_check:
+	close(igt_kmsg_capture_fd);
+	igt_kmsg_capture_fd = -1;
+err_capture:
+	free(igt_kmsg_dump_buf);
+	igt_kmsg_dump_buf = NULL;
+	return;
+}
+
+static int _igt_kmsg_dump(bool print, int filter_priority)
+{
+	size_t nbytes;
+	int nlines;
+	int prefix;
+	int priority;
+	char *p;
+	int fd;
+
+	fd = print ? igt_kmsg_capture_fd : igt_kmsg_check_fd;
+	if (fd == -1)
+		return 0;
+
+	nlines = 0;
+	do {
+		errno = 0;
+		nbytes = read(fd, igt_kmsg_dump_buf, IGT_KMSG_DUMP_BUF_SIZE);
+
+		if (nbytes == -1)
+			continue;
+
+		sscanf(igt_kmsg_dump_buf, "%d;", &prefix);
+		priority = prefix & 0x7;
+
+		if (priority > filter_priority)
+			continue;
+
+		nlines++;
+
+		if (!print)
+			continue;
+
+		if (nlines == 1)
+			fprintf(stderr, "**** KMSG ****\n");
+
+		p = strchr(igt_kmsg_dump_buf, ';') + 1;
+		while (p - igt_kmsg_dump_buf < nbytes) {
+			int c = *p++;
+			/* Decode non-printable characters escaped in
+			 * hex form (\x0f). */
+			if (c == '\\') {
+				igt_assert(*p++ == 'x');
+				igt_assert(sscanf(p, "%x", &c) == 1);
+				p += 2;
+			}
+			fputc(c, stderr);
+		}
+	} while(errno == 0);
+
+	if (print && nlines)
+		fprintf(stderr, "****  END  ****\n");
+
+	if (errno != EAGAIN)
+		fprintf(stderr, "Error: Incomplete kmsg!\n");
+
+	close(fd);
+
+	if (print) {
+		igt_kmsg_capture_fd = -1;
+		free(igt_kmsg_dump_buf);
+		igt_kmsg_dump_buf = NULL;
+	} else {
+		igt_kmsg_check_fd = -1;
+	}
+
+	return nlines;
+}
+
 __attribute__((format(printf, 1, 2)))
 static void kmsg(const char *format, ...)
 #define KERN_EMER	"<0>"
@@ -712,8 +825,10 @@ out:
 	/* install exit handler, to ensure we clean up */
 	igt_install_exit_handler(common_exit_handler);
 
-	if (!test_with_subtests)
+	if (!test_with_subtests) {
 		gettime(&subtest_time);
+		_igt_kmsg_reset();
+	}
 
 	for (i = 0; (optind + i) < *argc; i++)
 		argv[i + 1] = argv[optind + i];
@@ -832,8 +947,9 @@ bool __igt_run_subtest(const char *subtest_name)
 	igt_debug("Starting subtest: %s\n", subtest_name);
 
 	_igt_log_buffer_reset();
-
+	_igt_kmsg_reset();
 	gettime(&subtest_time);
+
 	return (in_subtest = subtest_name);
 }
 
@@ -963,6 +1079,9 @@ void __igt_skip_check(const char *file, const int line,
  */
 void igt_success(void)
 {
+	if (_igt_kmsg_dump(false, LOG_WARNING))
+		_igt_kmsg_dump(true, LOG_DEBUG);
+
 	succeeded_one = true;
 	if (in_subtest)
 		exit_subtest("SUCCESS");
@@ -1005,6 +1124,11 @@ void igt_fail(int exitcode)
 
 	_igt_log_buffer_dump();
 
+	/* Show kmsg if not already shown. */
+	if (_igt_kmsg_dump(true, LOG_DEBUG) < 1)
+		fprintf(stderr, "No kmsg.\n");
+
+
 	if (in_subtest) {
 		if (exitcode == IGT_EXIT_TIMEOUT)
 			exit_subtest("TIMEOUT");
@@ -1111,7 +1235,6 @@ void igt_exit(void)
 		exit(IGT_EXIT_INVALID);
 	}
 
-
 	if (igt_only_list_subtests())
 		exit(IGT_EXIT_SUCCESS);
 
diff --git a/lib/tests/.gitignore b/lib/tests/.gitignore
index a4f1080..c49c178 100644
--- a/lib/tests/.gitignore
+++ b/lib/tests/.gitignore
@@ -1,5 +1,6 @@
 # Please keep sorted alphabetically
 igt_assert
+igt_capture
 igt_fork_helper
 igt_invalid_subtest_name
 igt_list_only
diff --git a/lib/tests/Makefile.sources b/lib/tests/Makefile.sources
index 777b9c1..6506baf 100644
--- a/lib/tests/Makefile.sources
+++ b/lib/tests/Makefile.sources
@@ -1,4 +1,5 @@
 check_PROGRAMS = \
+	igt_capture \
 	igt_no_exit \
 	igt_no_exit_list_only \
 	igt_fork_helper \
@@ -32,4 +33,5 @@ XFAIL_TESTS = \
 	igt_simple_test_subtests \
 	igt_timeout \
 	igt_invalid_subtest_name \
+	igt_capture \
 	$(NULL)
diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
new file mode 100644
index 0000000..28ffce1
--- /dev/null
+++ b/lib/tests/igt_capture.c
@@ -0,0 +1,89 @@
+/*
+ * Copyright © 2015 Intel Corporation
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a
+ * copy of this software and associated documentation files (the "Software"),
+ * to deal in the Software without restriction, including without limitation
+ * the rights to use, copy, modify, merge, publish, distribute, sublicense,
+ * and/or sell copies of the Software, and to permit persons to whom the
+ * Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice (including the next
+ * paragraph) shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
+ * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
+ * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
+ * IN THE SOFTWARE.
+ *
+ * Authors:
+ *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
+ *
+ */
+
+#include "igt_core.h"
+#include <stdio.h>
+#include <syslog.h>
+
+static FILE* kmsg;
+
+static void
+test_kmsg(bool fail)
+{
+	fprintf(kmsg, "<%d>TEST (KMSG)\n", LOG_WARNING);
+	fflush(kmsg);
+	if (fail)
+		igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_warn(void)
+{
+	igt_warn("TEST (WARN)\n");
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_debug(void)
+{
+	igt_debug("TEST (DEBUG)\n");
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_combined(void)
+{
+	igt_warn("TEST #1 (WARN)\n");
+	fputs("TEST #1\n", kmsg);
+	igt_warn("TEST #2 (WARN)\n");
+	fputs("TEST #2\n", kmsg);
+	fflush(kmsg);
+	igt_fail(IGT_EXIT_FAILURE);
+}
+
+igt_main
+{
+	igt_fixture {
+		kmsg = fopen("/dev/kmsg", "w");
+		igt_require(kmsg != NULL);
+	}
+
+	igt_subtest("kmsg")
+		test_kmsg(true);
+	igt_subtest("kmsg-success")
+		test_kmsg(false);
+	igt_subtest("warn")
+		test_warn();
+	igt_subtest("debug")
+		test_debug();
+	igt_subtest("combined")
+		test_combined();
+
+	igt_fixture {
+		fclose(kmsg);
+	}
+}
-- 
2.4.3

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t v4] lib/igt_core: Add kmsg capture and dumping
  2015-11-26 12:17           ` [PATCH i-g-t v4] " Joonas Lahtinen
@ 2015-11-26 14:34             ` Daniel Vetter
  2015-11-26 15:00               ` Joonas Lahtinen
  0 siblings, 1 reply; 23+ messages in thread
From: Daniel Vetter @ 2015-11-26 14:34 UTC (permalink / raw)
  To: Joonas Lahtinen
  Cc: Daniel Vetter,
	Intel graphics driver community testing & development,
	Thomas Wood

On Thu, Nov 26, 2015 at 02:17:53PM +0200, Joonas Lahtinen wrote:
> Capture the output from /dev/kmsg during test execution independantly
> of other concurrent watchers like Piglit test runner.
> 
> The captured output is analyzed and the whole output dumped if message
> with priority LOG_WARNING or higher is emitted from any domain.
> 
> Also adding igt_capture to lib/tests which will fail subtests and
> produce kmsg output which should be captured by the new code.
> 
> v4:
> - Do not effect return value of test, just dump (Daniel)
> 
> v3:
> - Use O_CLOEXEC and clarify hex decoding (Chris)
> 
> v2:
> - Reopen/close the kmsg FD per each test (Chris)
> - Better commit mesage (Daniel)
> - Display failure due to kmsg only as FAIL (KMSG)
> 
> Cc: Thomas Wood <thomas.wood@intel.com>
> Cc: Chris Wilson <chris@chris-wilson.co.uk>
> Cc: Damien Lespiau <damien.lespiau@intel.com>
> Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
> Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>

Hm I guess we need to strike that ack again, more comments below.

> Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> ---
>  lib/igt_core.c             | 129 +++++++++++++++++++++++++++++++++++++++++++--
>  lib/tests/.gitignore       |   1 +
>  lib/tests/Makefile.sources |   2 +
>  lib/tests/igt_capture.c    |  89 +++++++++++++++++++++++++++++++
>  4 files changed, 218 insertions(+), 3 deletions(-)
>  create mode 100644 lib/tests/igt_capture.c
> 
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index 84cf8d2..b1aa750 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -43,6 +43,7 @@
>  #include <getopt.h>
>  #include <stdlib.h>
>  #include <unistd.h>
> +#include <syslog.h>
>  #include <sys/wait.h>
>  #include <sys/types.h>
>  #ifdef __linux__
> @@ -211,6 +212,8 @@
>   * "--help" command line option.
>   */
>  
> +#define IGT_KMSG_DUMP_BUF_SIZE		4096
> +
>  static unsigned int exit_handler_count;
>  const char *igt_interactive_debug;
>  
> @@ -248,6 +251,10 @@ enum {
>  static int igt_exitcode = IGT_EXIT_SUCCESS;
>  static const char *command_str;
>  
> +static int igt_kmsg_capture_fd = -1;
> +static int igt_kmsg_check_fd = -1;
> +static char* igt_kmsg_dump_buf = NULL;
> +
>  static char* igt_log_domain_filter;
>  static struct {
>  	char *entries[256];
> @@ -313,6 +320,112 @@ static void _igt_log_buffer_dump(void)
>  	pthread_mutex_unlock(&log_buffer_mutex);
>  }
>  
> +static void _igt_kmsg_reset(void)
> +{
> +	if (igt_kmsg_dump_buf == NULL)
> +		igt_kmsg_dump_buf = malloc(IGT_KMSG_DUMP_BUF_SIZE);
> +
> +	if (igt_kmsg_dump_buf == NULL) {
> +		igt_warn("Unable to allocate memory, "
> +			 "can not dump kmsg.\n");
> +		return;
> +	}
> +
> +	if (igt_kmsg_capture_fd == -1)
> +		igt_kmsg_capture_fd = open("/dev/kmsg",
> +					   O_RDONLY | O_NONBLOCK | O_CLOEXEC);
> +
> +	if (igt_kmsg_capture_fd == -1)
> +		goto err_capture;
> +
> +	if (igt_kmsg_check_fd == -1)
> +		igt_kmsg_check_fd = open("/dev/kmsg",
> +					 O_RDONLY | O_NONBLOCK | O_CLOEXEC);
> +
> +	if (igt_kmsg_check_fd == -1)
> +		goto err_check;
> +
> +	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> +	lseek(igt_kmsg_check_fd, 0, SEEK_END);
> +	return;
> +
> +err_check:
> +	close(igt_kmsg_capture_fd);
> +	igt_kmsg_capture_fd = -1;
> +err_capture:
> +	free(igt_kmsg_dump_buf);
> +	igt_kmsg_dump_buf = NULL;
> +	return;
> +}
> +
> +static int _igt_kmsg_dump(bool print, int filter_priority)
> +{
> +	size_t nbytes;
> +	int nlines;
> +	int prefix;
> +	int priority;
> +	char *p;
> +	int fd;
> +
> +	fd = print ? igt_kmsg_capture_fd : igt_kmsg_check_fd;
> +	if (fd == -1)
> +		return 0;
> +
> +	nlines = 0;
> +	do {
> +		errno = 0;
> +		nbytes = read(fd, igt_kmsg_dump_buf, IGT_KMSG_DUMP_BUF_SIZE);
> +
> +		if (nbytes == -1)
> +			continue;
> +
> +		sscanf(igt_kmsg_dump_buf, "%d;", &prefix);
> +		priority = prefix & 0x7;
> +
> +		if (priority > filter_priority)
> +			continue;
> +
> +		nlines++;
> +
> +		if (!print)
> +			continue;
> +
> +		if (nlines == 1)
> +			fprintf(stderr, "**** KMSG ****\n");

Please use the igt logging functions we have. This holds in general,
please don't use any of the raw output functions and instead use the
igt_warn/info/debug stuff in your entire patch for logging.

Also the problem with dumping into stderr is that this is at the igt_warn
level, which means if this happens your test will be considered a failure
in CI.

And there's plenty of drivers and other stuff that dump random crap at
this level into dmesg, especially over system suspend resume. Which means
your patch will regress a pile of BAT igts.

We really, really need to filter dmesg the same way as piglit does. And I
mean _exactly_ the same way. Otherwise there's differences in test status,
and that means noise in CI and frustration all around.

Other option is to dump at igt_info or igt_debug level.

> +
> +		p = strchr(igt_kmsg_dump_buf, ';') + 1;
> +		while (p - igt_kmsg_dump_buf < nbytes) {
> +			int c = *p++;
> +			/* Decode non-printable characters escaped in
> +			 * hex form (\x0f). */
> +			if (c == '\\') {
> +				igt_assert(*p++ == 'x');
> +				igt_assert(sscanf(p, "%x", &c) == 1);
> +				p += 2;
> +			}
> +			fputc(c, stderr);
> +		}
> +	} while(errno == 0);
> +
> +	if (print && nlines)
> +		fprintf(stderr, "****  END  ****\n");
> +
> +	if (errno != EAGAIN)
> +		fprintf(stderr, "Error: Incomplete kmsg!\n");
> +
> +	close(fd);
> +
> +	if (print) {
> +		igt_kmsg_capture_fd = -1;
> +		free(igt_kmsg_dump_buf);
> +		igt_kmsg_dump_buf = NULL;
> +	} else {
> +		igt_kmsg_check_fd = -1;
> +	}
> +
> +	return nlines;
> +}
> +
>  __attribute__((format(printf, 1, 2)))
>  static void kmsg(const char *format, ...)
>  #define KERN_EMER	"<0>"
> @@ -712,8 +825,10 @@ out:
>  	/* install exit handler, to ensure we clean up */
>  	igt_install_exit_handler(common_exit_handler);
>  
> -	if (!test_with_subtests)
> +	if (!test_with_subtests) {
>  		gettime(&subtest_time);
> +		_igt_kmsg_reset();
> +	}
>  
>  	for (i = 0; (optind + i) < *argc; i++)
>  		argv[i + 1] = argv[optind + i];
> @@ -832,8 +947,9 @@ bool __igt_run_subtest(const char *subtest_name)
>  	igt_debug("Starting subtest: %s\n", subtest_name);
>  
>  	_igt_log_buffer_reset();
> -
> +	_igt_kmsg_reset();
>  	gettime(&subtest_time);
> +
>  	return (in_subtest = subtest_name);
>  }
>  
> @@ -963,6 +1079,9 @@ void __igt_skip_check(const char *file, const int line,
>   */
>  void igt_success(void)
>  {
> +	if (_igt_kmsg_dump(false, LOG_WARNING))
> +		_igt_kmsg_dump(true, LOG_DEBUG);
> +
>  	succeeded_one = true;
>  	if (in_subtest)
>  		exit_subtest("SUCCESS");
> @@ -1005,6 +1124,11 @@ void igt_fail(int exitcode)
>  
>  	_igt_log_buffer_dump();
>  
> +	/* Show kmsg if not already shown. */
> +	if (_igt_kmsg_dump(true, LOG_DEBUG) < 1)
> +		fprintf(stderr, "No kmsg.\n");
> +
> +
>  	if (in_subtest) {
>  		if (exitcode == IGT_EXIT_TIMEOUT)
>  			exit_subtest("TIMEOUT");
> @@ -1111,7 +1235,6 @@ void igt_exit(void)
>  		exit(IGT_EXIT_INVALID);
>  	}
>  
> -
>  	if (igt_only_list_subtests())
>  		exit(IGT_EXIT_SUCCESS);
>  
> diff --git a/lib/tests/.gitignore b/lib/tests/.gitignore
> index a4f1080..c49c178 100644
> --- a/lib/tests/.gitignore
> +++ b/lib/tests/.gitignore
> @@ -1,5 +1,6 @@
>  # Please keep sorted alphabetically
>  igt_assert
> +igt_capture
>  igt_fork_helper
>  igt_invalid_subtest_name
>  igt_list_only
> diff --git a/lib/tests/Makefile.sources b/lib/tests/Makefile.sources
> index 777b9c1..6506baf 100644
> --- a/lib/tests/Makefile.sources
> +++ b/lib/tests/Makefile.sources
> @@ -1,4 +1,5 @@
>  check_PROGRAMS = \
> +	igt_capture \
>  	igt_no_exit \
>  	igt_no_exit_list_only \
>  	igt_fork_helper \
> @@ -32,4 +33,5 @@ XFAIL_TESTS = \
>  	igt_simple_test_subtests \
>  	igt_timeout \
>  	igt_invalid_subtest_name \
> +	igt_capture \
>  	$(NULL)
> diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
> new file mode 100644
> index 0000000..28ffce1
> --- /dev/null
> +++ b/lib/tests/igt_capture.c

igt_dmesg_capture?

Cheers, Daniel

> @@ -0,0 +1,89 @@
> +/*
> + * Copyright © 2015 Intel Corporation
> + *
> + * Permission is hereby granted, free of charge, to any person obtaining a
> + * copy of this software and associated documentation files (the "Software"),
> + * to deal in the Software without restriction, including without limitation
> + * the rights to use, copy, modify, merge, publish, distribute, sublicense,
> + * and/or sell copies of the Software, and to permit persons to whom the
> + * Software is furnished to do so, subject to the following conditions:
> + *
> + * The above copyright notice and this permission notice (including the next
> + * paragraph) shall be included in all copies or substantial portions of the
> + * Software.
> + *
> + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
> + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
> + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
> + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
> + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
> + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
> + * IN THE SOFTWARE.
> + *
> + * Authors:
> + *    Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> + *
> + */
> +
> +#include "igt_core.h"
> +#include <stdio.h>
> +#include <syslog.h>
> +
> +static FILE* kmsg;
> +
> +static void
> +test_kmsg(bool fail)
> +{
> +	fprintf(kmsg, "<%d>TEST (KMSG)\n", LOG_WARNING);
> +	fflush(kmsg);
> +	if (fail)
> +		igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_warn(void)
> +{
> +	igt_warn("TEST (WARN)\n");
> +	igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_debug(void)
> +{
> +	igt_debug("TEST (DEBUG)\n");
> +	igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +static void
> +test_combined(void)
> +{
> +	igt_warn("TEST #1 (WARN)\n");
> +	fputs("TEST #1\n", kmsg);
> +	igt_warn("TEST #2 (WARN)\n");
> +	fputs("TEST #2\n", kmsg);
> +	fflush(kmsg);
> +	igt_fail(IGT_EXIT_FAILURE);
> +}
> +
> +igt_main
> +{
> +	igt_fixture {
> +		kmsg = fopen("/dev/kmsg", "w");
> +		igt_require(kmsg != NULL);
> +	}
> +
> +	igt_subtest("kmsg")
> +		test_kmsg(true);
> +	igt_subtest("kmsg-success")
> +		test_kmsg(false);
> +	igt_subtest("warn")
> +		test_warn();
> +	igt_subtest("debug")
> +		test_debug();
> +	igt_subtest("combined")
> +		test_combined();
> +
> +	igt_fixture {
> +		fclose(kmsg);
> +	}
> +}
> -- 
> 2.4.3
> 

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t v4] lib/igt_core: Add kmsg capture and dumping
  2015-11-26 14:34             ` Daniel Vetter
@ 2015-11-26 15:00               ` Joonas Lahtinen
  2015-11-27 10:31                 ` Daniel Vetter
  0 siblings, 1 reply; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-26 15:00 UTC (permalink / raw)
  To: Daniel Vetter
  Cc: Daniel Vetter,
	Intel graphics driver community testing & development,
	Thomas Wood

On to, 2015-11-26 at 15:34 +0100, Daniel Vetter wrote:
> On Thu, Nov 26, 2015 at 02:17:53PM +0200, Joonas Lahtinen wrote:
> > Capture the output from /dev/kmsg during test execution
> > independantly
> > of other concurrent watchers like Piglit test runner.
> > 
> > The captured output is analyzed and the whole output dumped if
> > message
> > with priority LOG_WARNING or higher is emitted from any domain.
> > 
> > Also adding igt_capture to lib/tests which will fail subtests and
> > produce kmsg output which should be captured by the new code.
> > 
> > v4:
> > - Do not effect return value of test, just dump (Daniel)
> > 
> > v3:
> > - Use O_CLOEXEC and clarify hex decoding (Chris)
> > 
> > v2:
> > - Reopen/close the kmsg FD per each test (Chris)
> > - Better commit mesage (Daniel)
> > - Display failure due to kmsg only as FAIL (KMSG)
> > 
> > Cc: Thomas Wood <thomas.wood@intel.com>
> > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
> > Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>
> 
> Hm I guess we need to strike that ack again, more comments below.
> 
> > Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> > ---
> >  lib/igt_core.c             | 129
> > +++++++++++++++++++++++++++++++++++++++++++--
> >  lib/tests/.gitignore       |   1 +
> >  lib/tests/Makefile.sources |   2 +
> >  lib/tests/igt_capture.c    |  89 +++++++++++++++++++++++++++++++
> >  4 files changed, 218 insertions(+), 3 deletions(-)
> >  create mode 100644 lib/tests/igt_capture.c
> > 
> > diff --git a/lib/igt_core.c b/lib/igt_core.c
> > index 84cf8d2..b1aa750 100644
> > --- a/lib/igt_core.c
> > +++ b/lib/igt_core.c
> > @@ -43,6 +43,7 @@
> >  #include <getopt.h>
> >  #include <stdlib.h>
> >  #include <unistd.h>
> > +#include <syslog.h>
> >  #include <sys/wait.h>
> >  #include <sys/types.h>
> >  #ifdef __linux__
> > @@ -211,6 +212,8 @@
> >   * "--help" command line option.
> >   */
> >  
> > +#define IGT_KMSG_DUMP_BUF_SIZE		4096
> > +
> >  static unsigned int exit_handler_count;
> >  const char *igt_interactive_debug;
> >  
> > @@ -248,6 +251,10 @@ enum {
> >  static int igt_exitcode = IGT_EXIT_SUCCESS;
> >  static const char *command_str;
> >  
> > +static int igt_kmsg_capture_fd = -1;
> > +static int igt_kmsg_check_fd = -1;
> > +static char* igt_kmsg_dump_buf = NULL;
> > +
> >  static char* igt_log_domain_filter;
> >  static struct {
> >  	char *entries[256];
> > @@ -313,6 +320,112 @@ static void _igt_log_buffer_dump(void)
> >  	pthread_mutex_unlock(&log_buffer_mutex);
> >  }
> >  
> > +static void _igt_kmsg_reset(void)
> > +{
> > +	if (igt_kmsg_dump_buf == NULL)
> > +		igt_kmsg_dump_buf =
> > malloc(IGT_KMSG_DUMP_BUF_SIZE);
> > +
> > +	if (igt_kmsg_dump_buf == NULL) {
> > +		igt_warn("Unable to allocate memory, "
> > +			 "can not dump kmsg.\n");
> > +		return;
> > +	}
> > +
> > +	if (igt_kmsg_capture_fd == -1)
> > +		igt_kmsg_capture_fd = open("/dev/kmsg",
> > +					   O_RDONLY | O_NONBLOCK |
> > O_CLOEXEC);
> > +
> > +	if (igt_kmsg_capture_fd == -1)
> > +		goto err_capture;
> > +
> > +	if (igt_kmsg_check_fd == -1)
> > +		igt_kmsg_check_fd = open("/dev/kmsg",
> > +					 O_RDONLY | O_NONBLOCK |
> > O_CLOEXEC);
> > +
> > +	if (igt_kmsg_check_fd == -1)
> > +		goto err_check;
> > +
> > +	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> > +	lseek(igt_kmsg_check_fd, 0, SEEK_END);
> > +	return;
> > +
> > +err_check:
> > +	close(igt_kmsg_capture_fd);
> > +	igt_kmsg_capture_fd = -1;
> > +err_capture:
> > +	free(igt_kmsg_dump_buf);
> > +	igt_kmsg_dump_buf = NULL;
> > +	return;
> > +}
> > +
> > +static int _igt_kmsg_dump(bool print, int filter_priority)
> > +{
> > +	size_t nbytes;
> > +	int nlines;
> > +	int prefix;
> > +	int priority;
> > +	char *p;
> > +	int fd;
> > +
> > +	fd = print ? igt_kmsg_capture_fd : igt_kmsg_check_fd;
> > +	if (fd == -1)
> > +		return 0;
> > +
> > +	nlines = 0;
> > +	do {
> > +		errno = 0;
> > +		nbytes = read(fd, igt_kmsg_dump_buf,
> > IGT_KMSG_DUMP_BUF_SIZE);
> > +
> > +		if (nbytes == -1)
> > +			continue;
> > +
> > +		sscanf(igt_kmsg_dump_buf, "%d;", &prefix);
> > +		priority = prefix & 0x7;
> > +
> > +		if (priority > filter_priority)
> > +			continue;
> > +
> > +		nlines++;
> > +
> > +		if (!print)
> > +			continue;
> > +
> > +		if (nlines == 1)
> > +			fprintf(stderr, "**** KMSG ****\n");
> 
> Please use the igt logging functions we have. This holds in general,
> please don't use any of the raw output functions and instead use the
> igt_warn/info/debug stuff in your entire patch for logging.
> 

Actually, if you look at the code I copied;

fprintf(stderr, "**** DEBUG ****\n");

So, I was just trying to make it consistent with the existing output.

Would you like both converted to use igt_warn or igt_debug?

> Also the problem with dumping into stderr is that this is at the
> igt_warn
> level, which means if this happens your test will be considered a
> failure
> in CI.
> 
> And there's plenty of drivers and other stuff that dump random crap
> at
> this level into dmesg, especially over system suspend resume. Which
> means
> your patch will regress a pile of BAT igts.
> 
> We really, really need to filter dmesg the same way as piglit does.
> And I
> mean _exactly_ the same way. Otherwise there's differences in test
> status,
> and that means noise in CI and frustration all around.
> 
> Other option is to dump at igt_info or igt_debug level.
> 

Should I just make it optional runtime flag --dmesg for the time being?

> > diff --git a/lib/tests/Makefile.sources
> > b/lib/tests/Makefile.sources
> > index 777b9c1..6506baf 100644
> > --- a/lib/tests/Makefile.sources
> > +++ b/lib/tests/Makefile.sources
> > @@ -1,4 +1,5 @@
> >  check_PROGRAMS = \
> > +	igt_capture \
> >  	igt_no_exit \
> >  	igt_no_exit_list_only \
> >  	igt_fork_helper \
> > @@ -32,4 +33,5 @@ XFAIL_TESTS = \
> >  	igt_simple_test_subtests \
> >  	igt_timeout \
> >  	igt_invalid_subtest_name \
> > +	igt_capture \
> >  	$(NULL)
> > diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
> > new file mode 100644
> > index 0000000..28ffce1
> > --- /dev/null
> > +++ b/lib/tests/igt_capture.c
> 
> igt_dmesg_capture?
> 

It actually tests the igt_warn and igt_debug too, so figured it could
be a generic name.

Regards, Joonas

-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t v4] lib/igt_core: Add kmsg capture and dumping
  2015-11-26 15:00               ` Joonas Lahtinen
@ 2015-11-27 10:31                 ` Daniel Vetter
  2015-11-27 11:46                   ` Joonas Lahtinen
  0 siblings, 1 reply; 23+ messages in thread
From: Daniel Vetter @ 2015-11-27 10:31 UTC (permalink / raw)
  To: Joonas Lahtinen
  Cc: Daniel Vetter,
	Intel graphics driver community testing & development,
	Thomas Wood

On Thu, Nov 26, 2015 at 05:00:14PM +0200, Joonas Lahtinen wrote:
> On to, 2015-11-26 at 15:34 +0100, Daniel Vetter wrote:
> > On Thu, Nov 26, 2015 at 02:17:53PM +0200, Joonas Lahtinen wrote:
> > > Capture the output from /dev/kmsg during test execution
> > > independantly
> > > of other concurrent watchers like Piglit test runner.
> > > 
> > > The captured output is analyzed and the whole output dumped if
> > > message
> > > with priority LOG_WARNING or higher is emitted from any domain.
> > > 
> > > Also adding igt_capture to lib/tests which will fail subtests and
> > > produce kmsg output which should be captured by the new code.
> > > 
> > > v4:
> > > - Do not effect return value of test, just dump (Daniel)
> > > 
> > > v3:
> > > - Use O_CLOEXEC and clarify hex decoding (Chris)
> > > 
> > > v2:
> > > - Reopen/close the kmsg FD per each test (Chris)
> > > - Better commit mesage (Daniel)
> > > - Display failure due to kmsg only as FAIL (KMSG)
> > > 
> > > Cc: Thomas Wood <thomas.wood@intel.com>
> > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > > Cc: Damien Lespiau <damien.lespiau@intel.com>
> > > Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
> > > Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>
> > 
> > Hm I guess we need to strike that ack again, more comments below.
> > 
> > > Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> > > ---
> > >  lib/igt_core.c             | 129
> > > +++++++++++++++++++++++++++++++++++++++++++--
> > >  lib/tests/.gitignore       |   1 +
> > >  lib/tests/Makefile.sources |   2 +
> > >  lib/tests/igt_capture.c    |  89 +++++++++++++++++++++++++++++++
> > >  4 files changed, 218 insertions(+), 3 deletions(-)
> > >  create mode 100644 lib/tests/igt_capture.c
> > > 
> > > diff --git a/lib/igt_core.c b/lib/igt_core.c
> > > index 84cf8d2..b1aa750 100644
> > > --- a/lib/igt_core.c
> > > +++ b/lib/igt_core.c
> > > @@ -43,6 +43,7 @@
> > >  #include <getopt.h>
> > >  #include <stdlib.h>
> > >  #include <unistd.h>
> > > +#include <syslog.h>
> > >  #include <sys/wait.h>
> > >  #include <sys/types.h>
> > >  #ifdef __linux__
> > > @@ -211,6 +212,8 @@
> > >   * "--help" command line option.
> > >   */
> > >  
> > > +#define IGT_KMSG_DUMP_BUF_SIZE		4096
> > > +
> > >  static unsigned int exit_handler_count;
> > >  const char *igt_interactive_debug;
> > >  
> > > @@ -248,6 +251,10 @@ enum {
> > >  static int igt_exitcode = IGT_EXIT_SUCCESS;
> > >  static const char *command_str;
> > >  
> > > +static int igt_kmsg_capture_fd = -1;
> > > +static int igt_kmsg_check_fd = -1;
> > > +static char* igt_kmsg_dump_buf = NULL;
> > > +
> > >  static char* igt_log_domain_filter;
> > >  static struct {
> > >  	char *entries[256];
> > > @@ -313,6 +320,112 @@ static void _igt_log_buffer_dump(void)
> > >  	pthread_mutex_unlock(&log_buffer_mutex);
> > >  }
> > >  
> > > +static void _igt_kmsg_reset(void)
> > > +{
> > > +	if (igt_kmsg_dump_buf == NULL)
> > > +		igt_kmsg_dump_buf =
> > > malloc(IGT_KMSG_DUMP_BUF_SIZE);
> > > +
> > > +	if (igt_kmsg_dump_buf == NULL) {
> > > +		igt_warn("Unable to allocate memory, "
> > > +			 "can not dump kmsg.\n");
> > > +		return;
> > > +	}
> > > +
> > > +	if (igt_kmsg_capture_fd == -1)
> > > +		igt_kmsg_capture_fd = open("/dev/kmsg",
> > > +					   O_RDONLY | O_NONBLOCK |
> > > O_CLOEXEC);
> > > +
> > > +	if (igt_kmsg_capture_fd == -1)
> > > +		goto err_capture;
> > > +
> > > +	if (igt_kmsg_check_fd == -1)
> > > +		igt_kmsg_check_fd = open("/dev/kmsg",
> > > +					 O_RDONLY | O_NONBLOCK |
> > > O_CLOEXEC);
> > > +
> > > +	if (igt_kmsg_check_fd == -1)
> > > +		goto err_check;
> > > +
> > > +	lseek(igt_kmsg_capture_fd, 0, SEEK_END);
> > > +	lseek(igt_kmsg_check_fd, 0, SEEK_END);
> > > +	return;
> > > +
> > > +err_check:
> > > +	close(igt_kmsg_capture_fd);
> > > +	igt_kmsg_capture_fd = -1;
> > > +err_capture:
> > > +	free(igt_kmsg_dump_buf);
> > > +	igt_kmsg_dump_buf = NULL;
> > > +	return;
> > > +}
> > > +
> > > +static int _igt_kmsg_dump(bool print, int filter_priority)
> > > +{
> > > +	size_t nbytes;
> > > +	int nlines;
> > > +	int prefix;
> > > +	int priority;
> > > +	char *p;
> > > +	int fd;
> > > +
> > > +	fd = print ? igt_kmsg_capture_fd : igt_kmsg_check_fd;
> > > +	if (fd == -1)
> > > +		return 0;
> > > +
> > > +	nlines = 0;
> > > +	do {
> > > +		errno = 0;
> > > +		nbytes = read(fd, igt_kmsg_dump_buf,
> > > IGT_KMSG_DUMP_BUF_SIZE);
> > > +
> > > +		if (nbytes == -1)
> > > +			continue;
> > > +
> > > +		sscanf(igt_kmsg_dump_buf, "%d;", &prefix);
> > > +		priority = prefix & 0x7;
> > > +
> > > +		if (priority > filter_priority)
> > > +			continue;
> > > +
> > > +		nlines++;
> > > +
> > > +		if (!print)
> > > +			continue;
> > > +
> > > +		if (nlines == 1)
> > > +			fprintf(stderr, "**** KMSG ****\n");
> > 
> > Please use the igt logging functions we have. This holds in general,
> > please don't use any of the raw output functions and instead use the
> > igt_warn/info/debug stuff in your entire patch for logging.
> > 
> 
> Actually, if you look at the code I copied;
> 
> fprintf(stderr, "**** DEBUG ****\n");
> 
> So, I was just trying to make it consistent with the existing output.
> 
> Would you like both converted to use igt_warn or igt_debug?

Hm right, we do raw printing there since that dumps the igt log - would
recurse otherwise.

> > Also the problem with dumping into stderr is that this is at the
> > igt_warn
> > level, which means if this happens your test will be considered a
> > failure
> > in CI.
> > 
> > And there's plenty of drivers and other stuff that dump random crap
> > at
> > this level into dmesg, especially over system suspend resume. Which
> > means
> > your patch will regress a pile of BAT igts.
> > 
> > We really, really need to filter dmesg the same way as piglit does.
> > And I
> > mean _exactly_ the same way. Otherwise there's differences in test
> > status,
> > and that means noise in CI and frustration all around.
> > 
> > Other option is to dump at igt_info or igt_debug level.
> > 
> 
> Should I just make it optional runtime flag --dmesg for the time being?

One option would be to dump it all with igt_debug() with an IGT_LOG_DOMAIN
of "dmesg" right before the (sub)test stops, and before we do the logfile
record dumping (in case of failure). With that
- You could see it when enabling full debug (fancy version could even dump
  dmesg in realtime in a separate thread so that dmesg and igt log
  interleave, that would be really useful).
- If the test fails we'll also dump dmesg.

Only problem is that if there's lots of dmesg spew the dmesg might flush
out all the useful log messages from igt itself. We might need to do the
interleaving right away.

Aside: IGT_LOG_DOMAIN is kinda meant for testcases, for the library it
might be better to use the low-level function:

	igt_log("dmesg", IGT_LOG_DEBUG, ...);

> 
> > > diff --git a/lib/tests/Makefile.sources
> > > b/lib/tests/Makefile.sources
> > > index 777b9c1..6506baf 100644
> > > --- a/lib/tests/Makefile.sources
> > > +++ b/lib/tests/Makefile.sources
> > > @@ -1,4 +1,5 @@
> > >  check_PROGRAMS = \
> > > +	igt_capture \
> > >  	igt_no_exit \
> > >  	igt_no_exit_list_only \
> > >  	igt_fork_helper \
> > > @@ -32,4 +33,5 @@ XFAIL_TESTS = \
> > >  	igt_simple_test_subtests \
> > >  	igt_timeout \
> > >  	igt_invalid_subtest_name \
> > > +	igt_capture \
> > >  	$(NULL)
> > > diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
> > > new file mode 100644
> > > index 0000000..28ffce1
> > > --- /dev/null
> > > +++ b/lib/tests/igt_capture.c
> > 
> > igt_dmesg_capture?
> > 
> 
> It actually tests the igt_warn and igt_debug too, so figured it could
> be a generic name.

Oh, totally missed that, sorry. But then looking at the testcase it
doesn't seem to do all that much really - there's no tests that e.g.
igt_warn does what we expect it too. And we have lots of igt_warn and
similar all over the place.

Real functional testcase for dmesg would be to inject something into kms
and make sure we log it. But that unfortunately requires root to run, so
not suitable as a library unit test.
-Daniel
-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t v4] lib/igt_core: Add kmsg capture and dumping
  2015-11-27 10:31                 ` Daniel Vetter
@ 2015-11-27 11:46                   ` Joonas Lahtinen
  2015-11-30  8:09                     ` Daniel Vetter
  0 siblings, 1 reply; 23+ messages in thread
From: Joonas Lahtinen @ 2015-11-27 11:46 UTC (permalink / raw)
  To: Daniel Vetter
  Cc: Daniel Vetter,
	Intel graphics driver community testing & development,
	Thomas Wood

On pe, 2015-11-27 at 11:31 +0100, Daniel Vetter wrote:
> On Thu, Nov 26, 2015 at 05:00:14PM +0200, Joonas Lahtinen wrote:
> > On to, 2015-11-26 at 15:34 +0100, Daniel Vetter wrote:
> > > On Thu, Nov 26, 2015 at 02:17:53PM +0200, Joonas Lahtinen wrote:
<SNIP>
> > > > +		if (nlines == 1)
> > > > +			fprintf(stderr, "**** KMSG ****\n");
> > > 
> > > Please use the igt logging functions we have. This holds in
> > > general,
> > > please don't use any of the raw output functions and instead use
> > > the
> > > igt_warn/info/debug stuff in your entire patch for logging.
> > > 
> > 
> > Actually, if you look at the code I copied;
> > 
> > fprintf(stderr, "**** DEBUG ****\n");
> > 
> > So, I was just trying to make it consistent with the existing
> > output.
> > 
> > Would you like both converted to use igt_warn or igt_debug?
> 
> Hm right, we do raw printing there since that dumps the igt log -
> would
> recurse otherwise.
> 
> > > Also the problem with dumping into stderr is that this is at the
> > > igt_warn
> > > level, which means if this happens your test will be considered a
> > > failure
> > > in CI.
> > > 
> > > And there's plenty of drivers and other stuff that dump random
> > > crap
> > > at
> > > this level into dmesg, especially over system suspend resume.
> > > Which
> > > means
> > > your patch will regress a pile of BAT igts.
> > > 
> > > We really, really need to filter dmesg the same way as piglit
> > > does.
> > > And I
> > > mean _exactly_ the same way. Otherwise there's differences in
> > > test
> > > status,
> > > and that means noise in CI and frustration all around.
> > > 
> > > Other option is to dump at igt_info or igt_debug level.
> > > 
> > 
> > Should I just make it optional runtime flag --dmesg for the time
> > being?
> 
> One option would be to dump it all with igt_debug() with an
> IGT_LOG_DOMAIN
> of "dmesg" right before the (sub)test stops, and before we do the
> logfile
> record dumping (in case of failure). With that
> - You could see it when enabling full debug (fancy version could even
> dump
>   dmesg in realtime in a separate thread so that dmesg and igt log
>   interleave, that would be really useful).
> - If the test fails we'll also dump dmesg.
> 

I wouldn't push dmesg into igt log, because it's just moving same bytes
from one place to another, kernel already buffers the dmesg for us and
it doesn't have to be read realtime. The FD's can be thought of as
glorified pointers, really.

With my now merged monotonic raw patches, we should be able to
timestamp each igt_warn and igt_debug call and it can be afterwards
interleaved with the kernel messages.

But this functionality as is, is already nice, because you don't have
to keep track of the kmsg in a separate window when running a single
test. Maybe we should decide on how to merge this function, and then
add the timestamping and interleaved output.

> Only problem is that if there's lots of dmesg spew the dmesg might
> flush
> out all the useful log messages from igt itself. We might need to do
> the
> interleaving right away.
> 
> Aside: IGT_LOG_DOMAIN is kinda meant for testcases, for the library
> it
> might be better to use the low-level function:
> 
> 	igt_log("dmesg", IGT_LOG_DEBUG, ...);
> 
> > 
> > > > diff --git a/lib/tests/Makefile.sources
> > > > b/lib/tests/Makefile.sources
> > > > index 777b9c1..6506baf 100644
> > > > --- a/lib/tests/Makefile.sources
> > > > +++ b/lib/tests/Makefile.sources
> > > > @@ -1,4 +1,5 @@
> > > >  check_PROGRAMS = \
> > > > +	igt_capture \
> > > >  	igt_no_exit \
> > > >  	igt_no_exit_list_only \
> > > >  	igt_fork_helper \
> > > > @@ -32,4 +33,5 @@ XFAIL_TESTS = \
> > > >  	igt_simple_test_subtests \
> > > >  	igt_timeout \
> > > >  	igt_invalid_subtest_name \
> > > > +	igt_capture \
> > > >  	$(NULL)
> > > > diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
> > > > new file mode 100644
> > > > index 0000000..28ffce1
> > > > --- /dev/null
> > > > +++ b/lib/tests/igt_capture.c
> > > 
> > > igt_dmesg_capture?
> > > 
> > 
> > It actually tests the igt_warn and igt_debug too, so figured it
> > could
> > be a generic name.
> 
> Oh, totally missed that, sorry. But then looking at the testcase it
> doesn't seem to do all that much really - there's no tests that e.g.
> igt_warn does what we expect it too. And we have lots of igt_warn and
> similar all over the place.
> 
> Real functional testcase for dmesg would be to inject something into
> kms
> and make sure we log it. But that unfortunately requires root to run,
> so
> not suitable as a library unit test.

It currently does inject to dmesg (and thus requires root to run), as
well as igt_debug and igt_warn, it's just that the test output needs to
be visually inspected by a human being. I could of course add a wrapper
that executes the binary and makes sure the test output is what it
should. Then it would be a test that is self diagnosing.

Regards, Joonas

> -Daniel
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

* Re: [PATCH i-g-t v4] lib/igt_core: Add kmsg capture and dumping
  2015-11-27 11:46                   ` Joonas Lahtinen
@ 2015-11-30  8:09                     ` Daniel Vetter
  0 siblings, 0 replies; 23+ messages in thread
From: Daniel Vetter @ 2015-11-30  8:09 UTC (permalink / raw)
  To: Joonas Lahtinen
  Cc: Daniel Vetter,
	Intel graphics driver community testing & development,
	Thomas Wood

On Fri, Nov 27, 2015 at 01:46:23PM +0200, Joonas Lahtinen wrote:
> On pe, 2015-11-27 at 11:31 +0100, Daniel Vetter wrote:
> > On Thu, Nov 26, 2015 at 05:00:14PM +0200, Joonas Lahtinen wrote:
> > > On to, 2015-11-26 at 15:34 +0100, Daniel Vetter wrote:
> > > > On Thu, Nov 26, 2015 at 02:17:53PM +0200, Joonas Lahtinen wrote:
> <SNIP>
> > > > > +		if (nlines == 1)
> > > > > +			fprintf(stderr, "**** KMSG ****\n");
> > > > 
> > > > Please use the igt logging functions we have. This holds in
> > > > general,
> > > > please don't use any of the raw output functions and instead use
> > > > the
> > > > igt_warn/info/debug stuff in your entire patch for logging.
> > > > 
> > > 
> > > Actually, if you look at the code I copied;
> > > 
> > > fprintf(stderr, "**** DEBUG ****\n");
> > > 
> > > So, I was just trying to make it consistent with the existing
> > > output.
> > > 
> > > Would you like both converted to use igt_warn or igt_debug?
> > 
> > Hm right, we do raw printing there since that dumps the igt log -
> > would
> > recurse otherwise.
> > 
> > > > Also the problem with dumping into stderr is that this is at the
> > > > igt_warn
> > > > level, which means if this happens your test will be considered a
> > > > failure
> > > > in CI.
> > > > 
> > > > And there's plenty of drivers and other stuff that dump random
> > > > crap
> > > > at
> > > > this level into dmesg, especially over system suspend resume.
> > > > Which
> > > > means
> > > > your patch will regress a pile of BAT igts.
> > > > 
> > > > We really, really need to filter dmesg the same way as piglit
> > > > does.
> > > > And I
> > > > mean _exactly_ the same way. Otherwise there's differences in
> > > > test
> > > > status,
> > > > and that means noise in CI and frustration all around.
> > > > 
> > > > Other option is to dump at igt_info or igt_debug level.
> > > > 
> > > 
> > > Should I just make it optional runtime flag --dmesg for the time
> > > being?
> > 
> > One option would be to dump it all with igt_debug() with an
> > IGT_LOG_DOMAIN
> > of "dmesg" right before the (sub)test stops, and before we do the
> > logfile
> > record dumping (in case of failure). With that
> > - You could see it when enabling full debug (fancy version could even
> > dump
> >   dmesg in realtime in a separate thread so that dmesg and igt log
> >   interleave, that would be really useful).
> > - If the test fails we'll also dump dmesg.
> > 
> 
> I wouldn't push dmesg into igt log, because it's just moving same bytes
> from one place to another, kernel already buffers the dmesg for us and
> it doesn't have to be read realtime. The FD's can be thought of as
> glorified pointers, really.

The upside is that the 2 logs get interleaved correctly, which I just so
absolutely wanted to have for debugging some feature last week ;-)

> With my now merged monotonic raw patches, we should be able to
> timestamp each igt_warn and igt_debug call and it can be afterwards
> interleaved with the kernel messages.

Interleaving afterwards is more work. At least manually.
 
> But this functionality as is, is already nice, because you don't have
> to keep track of the kmsg in a separate window when running a single
> test. Maybe we should decide on how to merge this function, and then
> add the timestamping and interleaved output.

Well for the interleaved kmsg capture the design would be entirely
different:

- in common_init launch a thread which captures kmsg in the background
  constantly and prints it using igt_debug with debug domain "dmesg"

- no need any more for dumping the buffer, core igt logging takes care of
  that. Same for dumping when the test failed, filtering or anything else.

- cleanup of that thread is best done with an igt exit handler.

Later on we can follow up with switching between igt_debug and igt_warn
depending upon log level.

Imo the above integrates much nicer into existing igt infrastructure and
has the benefit of giving us interleaving, too.

Cheers, Daniel

> 
> > Only problem is that if there's lots of dmesg spew the dmesg might
> > flush
> > out all the useful log messages from igt itself. We might need to do
> > the
> > interleaving right away.
> > 
> > Aside: IGT_LOG_DOMAIN is kinda meant for testcases, for the library
> > it
> > might be better to use the low-level function:
> > 
> > 	igt_log("dmesg", IGT_LOG_DEBUG, ...);
> > 
> > > 
> > > > > diff --git a/lib/tests/Makefile.sources
> > > > > b/lib/tests/Makefile.sources
> > > > > index 777b9c1..6506baf 100644
> > > > > --- a/lib/tests/Makefile.sources
> > > > > +++ b/lib/tests/Makefile.sources
> > > > > @@ -1,4 +1,5 @@
> > > > >  check_PROGRAMS = \
> > > > > +	igt_capture \
> > > > >  	igt_no_exit \
> > > > >  	igt_no_exit_list_only \
> > > > >  	igt_fork_helper \
> > > > > @@ -32,4 +33,5 @@ XFAIL_TESTS = \
> > > > >  	igt_simple_test_subtests \
> > > > >  	igt_timeout \
> > > > >  	igt_invalid_subtest_name \
> > > > > +	igt_capture \
> > > > >  	$(NULL)
> > > > > diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
> > > > > new file mode 100644
> > > > > index 0000000..28ffce1
> > > > > --- /dev/null
> > > > > +++ b/lib/tests/igt_capture.c
> > > > 
> > > > igt_dmesg_capture?
> > > > 
> > > 
> > > It actually tests the igt_warn and igt_debug too, so figured it
> > > could
> > > be a generic name.
> > 
> > Oh, totally missed that, sorry. But then looking at the testcase it
> > doesn't seem to do all that much really - there's no tests that e.g.
> > igt_warn does what we expect it too. And we have lots of igt_warn and
> > similar all over the place.
> > 
> > Real functional testcase for dmesg would be to inject something into
> > kms
> > and make sure we log it. But that unfortunately requires root to run,
> > so
> > not suitable as a library unit test.
> 
> It currently does inject to dmesg (and thus requires root to run), as
> well as igt_debug and igt_warn, it's just that the test output needs to
> be visually inspected by a human being. I could of course add a wrapper
> that executes the binary and makes sure the test output is what it
> should. Then it would be a test that is self diagnosing.
> 
> Regards, Joonas
> 
> > -Daniel
> -- 
> Joonas Lahtinen
> Open Source Technology Center
> Intel Corporation
> 

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

end of thread, other threads:[~2015-11-30  8:10 UTC | newest]

Thread overview: 23+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2015-11-16 13:22 [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it Joonas Lahtinen
2015-11-16 14:06 ` Chris Wilson
2015-11-17  8:24   ` Joonas Lahtinen
2015-11-17 13:05 ` Thomas Wood
2015-11-17 13:34   ` Joonas Lahtinen
2015-11-18 15:44 ` Daniel Vetter
2015-11-18 17:32   ` Chris Wilson
2015-11-19  9:38     ` Daniel Vetter
2015-11-19  9:41       ` Daniel Vetter
2015-11-20 11:22         ` Joonas Lahtinen
2015-11-20 11:34           ` Chris Wilson
2015-11-23 10:31             ` Joonas Lahtinen
2015-11-19 10:35     ` [PATCH i-g-t v2] lib/igt_core: Add kmsg capture and dumping Joonas Lahtinen
2015-11-19 11:32       ` Chris Wilson
2015-11-20 11:46         ` Joonas Lahtinen
2015-11-26 12:17           ` [PATCH i-g-t v4] " Joonas Lahtinen
2015-11-26 14:34             ` Daniel Vetter
2015-11-26 15:00               ` Joonas Lahtinen
2015-11-27 10:31                 ` Daniel Vetter
2015-11-27 11:46                   ` Joonas Lahtinen
2015-11-30  8:09                     ` Daniel Vetter
2015-11-18 17:41   ` [PATCH i-g-t] Add dmesg capture and dumping to tests and a test for it Thomas Wood
2015-11-18 18:12     ` Joonas Lahtinen

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.