| Message ID | 1418834747-5598-1-git-send-email-thomas.wood@intel.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
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@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; i = log_buffer.start; do { > + > + /* ensure each line ends in a newline */ > + for (int pos = 0; last_line[pos] != '\0'; pos++) { > + if (last_line[pos] != '\n' > + && last_line[pos + 1] == '\0') > + write_log_msg("\n"); > + } pos = strlen(last_line); if (pos > 0 && last_line[pos-1] != '\n') write_log_msg("\n"); if (i == log_buffer.end) break; i++; } while (1); It's not the neatest of loops, but it should be effective. > + i++; > + } while (i != log_buffer.start && i != log_buffer.end); > + > + write_log_msg("--- Log End\n"); After it has dumped the log, do you want to reset the log_buffer? i.e. log_buffer.start = log_buffer.end; > + pthread_mutex_unlock(&log_buffer_mutex); I was worried by taking locks inside a signal handler, but this looks like it could be made safe, and with a bit more work, you can make the other half robust as well: char *new, *old; asprintf(&new, "(%s:%d) %s%s%s: %s", program_name, getpid(), (domain) ? domain : "", (domain) ? "-" : "", igt_log_level_str[level], line); pthread_mutex_lock(&log_buffer_mutex); old = log_buffer.entries[log_buffer.end]; log_bufffer.entries[log_buffer.end] = new; if (++log_buffer.end == log_buffer.start) log_buffer.start++; pthread_mutex_unlock(&log_buffer_mutex); free(old); i.e. only do the pointer head/tail assignment inside the lock to minimise exposure. -Chris
On Wed, Dec 17, 2014 at 05:19:21PM +0000, Chris Wilson wrote: > char *new, *old; sigset_t block_signals, save_signals; > asprintf(&new, > "(%s:%d) %s%s%s: %s", > program_name, getpid(), > (domain) ? domain : "", > (domain) ? "-" : "", > igt_log_level_str[level], > line); sigfillset(&block_signals); pthread_sigmask(SIG_SETMASK, &block_signals, &save_signals); > > pthread_mutex_lock(&log_buffer_mutex); > old = log_buffer.entries[log_buffer.end]; > log_bufffer.entries[log_buffer.end] = new; > if (++log_buffer.end == log_buffer.start) > log_buffer.start++; > pthread_mutex_unlock(&log_buffer_mutex); pthread_sigmask(SIG_SETMASK, &save_signals, NULL); > free(old); That will at least stop SIGARLM and friends firing whilst we poke around inside log_buffer. It might make a test result unstable, but will prevent that same instability from causing a lockup of igt. -Chris
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. More of a general style bikeshed: Would log_write(), __log_write_msg(), __log_write_char(), log_clear() be better, for they all operate on the implicit log_buffer. -Chris
On 17 December 2014 at 17:19, Chris Wilson <chris@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@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. > > i = log_buffer.start; > do { >> + >> + /* ensure each line ends in a newline */ >> + for (int pos = 0; last_line[pos] != '\0'; pos++) { >> + if (last_line[pos] != '\n' >> + && last_line[pos + 1] == '\0') >> + write_log_msg("\n"); >> + } > > pos = strlen(last_line); > if (pos > 0 && last_line[pos-1] != '\n') > write_log_msg("\n"); The for loop above was to avoid using strlen (which is not listed as signal safe), but strlen is being used in write_log_msg, so this would need further work to make it safe too. > > if (i == log_buffer.end) > break; > > i++; > } while (1); > > It's not the neatest of loops, but it should be effective. > >> + i++; >> + } while (i != log_buffer.start && i != log_buffer.end); >> + >> + write_log_msg("--- Log End\n"); > > After it has dumped the log, do you want to reset the log_buffer? > i.e. log_buffer.start = log_buffer.end; Yes, this is added in patch 4 of this series. > >> + pthread_mutex_unlock(&log_buffer_mutex); > > I was worried by taking locks inside a signal handler, but this looks > like it could be made safe, and with a bit more work, you can make the > other half robust as well: Yes, this is problematic. It will probably be worth adding some library test cases to try and ensure the default signal handlers are as safe as possible. > > char *new, *old; > > asprintf(&new, > "(%s:%d) %s%s%s: %s", > program_name, getpid(), > (domain) ? domain : "", > (domain) ? "-" : "", > igt_log_level_str[level], > line); > > pthread_mutex_lock(&log_buffer_mutex); > old = log_buffer.entries[log_buffer.end]; > log_bufffer.entries[log_buffer.end] = new; > if (++log_buffer.end == log_buffer.start) > log_buffer.start++; > pthread_mutex_unlock(&log_buffer_mutex); > > free(old); > > i.e. only do the pointer head/tail assignment inside the lock to > minimise exposure. > -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
On Wed, Dec 17, 2014 at 06:10:46PM +0000, Thomas Wood wrote: > On 17 December 2014 at 17:19, Chris Wilson <chris@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@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
On Wed, Dec 17, 2014 at 06:10:46PM +0000, Thomas Wood wrote: > On 17 December 2014 at 17:19, Chris Wilson <chris@chris-wilson.co.uk> wrote: > > After it has dumped the log, do you want to reset the log_buffer? > > i.e. log_buffer.start = log_buffer.end; > > Yes, this is added in patch 4 of this series. Does that actually cover the case of a multithreaded/forked test case with multiple failures? iirc, that can still generate multiple sets of failure reports. I thought patch 4 only cleared the log between tests. -Chris
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); + + /* ensure each line ends in a newline */ + for (int pos = 0; last_line[pos] != '\0'; pos++) { + if (last_line[pos] != '\n' + && last_line[pos + 1] == '\0') + write_log_msg("\n"); + } + + i++; + } while (i != log_buffer.start && i != log_buffer.end); + + write_log_msg("--- Log End\n"); + + pthread_mutex_unlock(&log_buffer_mutex); +} + bool igt_exit_called; static void common_exit_handler(int sig) { @@ -361,6 +419,14 @@ static void common_exit_handler(int sig) /* When not killed by a signal check that igt_exit() has been properly * called. */ assert(sig != 0 || igt_exit_called); + + /* write the log out to a file if a signal was received or a simple + * test failed (tests with subtests write the log after the subtest + * failure) */ + if (sig || (!test_with_subtests + && igt_exitcode != IGT_EXIT_SUCCESS + && igt_exitcode != IGT_EXIT_SKIP)) + write_log(); } static void print_test_description(void) @@ -383,8 +449,6 @@ static void print_version(void) uts.sysname, uts.release, uts.machine); } -static const char *command_str; - static void print_usage(const char *help_str, bool output_on_stderr) { FILE *f = output_on_stderr ? stderr : stdout; @@ -728,7 +792,6 @@ bool igt_only_list_subtests(void) static bool skipped_one = false; static bool succeeded_one = false; static bool failed_one = false; -static int igt_exitcode = IGT_EXIT_SUCCESS; static void exit_subtest(const char *) __attribute__((noreturn)); static void exit_subtest(const char *result) @@ -862,6 +925,7 @@ void igt_fail(int exitcode) exit(exitcode); if (in_subtest) { + write_log(); if (exitcode == IGT_EXIT_TIMEOUT) exit_subtest("TIMEOUT"); else @@ -1460,6 +1524,7 @@ void igt_log(const char *domain, enum igt_log_level level, const char *format, . void igt_vlog(const char *domain, enum igt_log_level level, const char *format, va_list args) { FILE *file; + char *line; const char *program_name; const char *igt_log_level_str[] = { "DEBUG", @@ -1479,16 +1544,37 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format, if (list_subtests) return; + vasprintf(&line, format, args); + + /* save log output when log level is info */ + if (igt_log_level == IGT_LOG_INFO) { + pthread_mutex_lock(&log_buffer_mutex); + + free(log_buffer.entries[log_buffer.end]); + asprintf(&log_buffer.entries[log_buffer.end], + "(%s:%d) %s%s%s: %s", + program_name, getpid(), + (domain) ? domain : "", + (domain) ? "-" : "", + igt_log_level_str[level], + line); + log_buffer.end++; + if (log_buffer.end == log_buffer.start) + log_buffer.start++; + + pthread_mutex_unlock(&log_buffer_mutex); + } + if (igt_log_level > level) - return; + goto out; if (igt_log_domain_filter) { /* if null domain and filter is not "application", return */ if (!domain && strcmp(igt_log_domain_filter, "application")) - return; + goto out; /* else if domain and filter do not match, return */ else if (domain && strcmp(igt_log_domain_filter, domain)) - return; + goto out; } if (level == IGT_LOG_WARN) { @@ -1503,7 +1589,10 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format, (domain) ? domain : "", (domain) ? "-" : "", igt_log_level_str[level]); } - vfprintf(file, format, args); + fwrite(line, sizeof(char), strlen(line), file); + +out: + free(line); } static void igt_alarm_handler(int signal)
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@intel.com> --- lib/igt_core.c | 103 +++++++++++++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 96 insertions(+), 7 deletions(-)