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

[Daniel Vetter]

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