[Intel-gfx] [PATCH i-g-t 1/5] lib: print recent log output if a test fails

[Chris Wilson]

On Wed, Dec 17, 2014 at 06:10:46PM +0000, Thomas Wood wrote:
> On 17 December 2014 at 17:19, Chris Wilson <chris at chris-wilson.co.uk> wrote:
> > On Wed, Dec 17, 2014 at 04:45:43PM +0000, Thomas Wood wrote:
> >> Print recent log entries if a test or subtest fails and the current log
> >> level is set to info.
> >>
> >> v2: Write log to stderr after test or subtest failure and make log
> >>     buffering thread safe.
> >>
> >> Signed-off-by: Thomas Wood <thomas.wood at intel.com>
> >> ---
> >>  lib/igt_core.c | 103 +++++++++++++++++++++++++++++++++++++++++++++++++++++----
> >>  1 file changed, 96 insertions(+), 7 deletions(-)
> >>
> >> diff --git a/lib/igt_core.c b/lib/igt_core.c
> >> index 08e0c47..457b3b1 100644
> >> --- a/lib/igt_core.c
> >> +++ b/lib/igt_core.c
> >> @@ -50,6 +50,8 @@
> >>  #include <termios.h>
> >>  #include <errno.h>
> >>  #include <time.h>
> >> +#include <limits.h>
> >> +#include <pthread.h>
> >>
> >>  #include "drmtest.h"
> >>  #include "intel_chipset.h"
> >> @@ -228,8 +230,18 @@ enum {
> >>   OPT_HELP = 'h'
> >>  };
> >>
> >> +static const char *command_str;
> >> +static int igt_exitcode = IGT_EXIT_SUCCESS;
> >> +
> >>  static char* igt_log_domain_filter;
> >>
> >> +static struct {
> >> +     char *entries[256];
> >> +     uint8_t start, end;
> >> +} log_buffer;
> >> +static pthread_mutex_t log_buffer_mutex = PTHREAD_MUTEX_INITIALIZER;
> >> +
> >> +
> >>  __attribute__((format(printf, 1, 2)))
> >>  static void kmsg(const char *format, ...)
> >>  #define KERN_EMER    "<0>"
> >> @@ -353,6 +365,52 @@ static void low_mem_killer_disable(bool disable)
> >>       chmod(adj_fname, buf.st_mode);
> >>  }
> >>
> >> +#define write_log_msg(x) write(STDERR_FILENO, x, strlen(x))
> >> +
> >> +/* this function must be safe to be called inside a signal handler */
> >> +static void write_log(void)
> >> +{
> >> +     uint8_t i;
> >> +     char *last_line;
> >> +
> >> +     pthread_mutex_lock(&log_buffer_mutex);
> >> +
> >> +     /* don't write an empty log */
> >> +     if (log_buffer.start == log_buffer.end) {
> >> +             pthread_mutex_unlock(&log_buffer_mutex);
> >> +             return;
> >> +     }
> >> +
> >> +     if (in_subtest) {
> >> +             write_log_msg("--- Subtest ");
> >> +             write_log_msg(in_subtest);
> >> +     } else {
> >> +             write_log_msg("--- Test ");
> >> +             write_log_msg(command_str);
> >> +     }
> >> +     write_log_msg(" failed.\n");
> >> +     write_log_msg("--- Log Start\n");
> >> +
> >> +     i = log_buffer.start;
> >> +     do {
> >> +             last_line = log_buffer.entries[i];
> >> +             write_log_msg(last_line);
> >
> > What happens if nothing is in the log:
> > log_buffer.start == log_buffer.end == 0
> >
> > last_line[pos] is a *NULL, as may strlen(NULL).
> >
> > When something is in the log, start != end, so this can just be a simple
> >
> > if (log_buffer.start == log_buffer.end)
> >         return;
> 
> Yes, this check is done at the start of the function.

But then won't you get different output if a subtest fails without
actually adding a log message? Is that desirable? (At least my primary
concern that there isn't a *NULL is addressed. And the looping logic is
correct, but I think we aren't using as many entries as possible...)

Maybe give an example of how the extra logging works in practice?
(Some before/after output of a failing igt test.)
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre