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

[Joonas Lahtinen]

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