Re: [PATCH i-g-t v4] lib/igt_core: Add kmsg capture and dumping

[Daniel Vetter <daniel@ffwll.ch>]

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