diff options
| -rw-r--r-- | include/util/log.h | 11 | ||||
| -rwxr-xr-x | misc/crucible-report | 7 | ||||
| -rw-r--r-- | src/cmd/run.c | 5 | ||||
| -rw-r--r-- | src/framework/runner/master.c | 20 | ||||
| -rw-r--r-- | src/util/log.c | 52 |
5 files changed, 68 insertions, 27 deletions
diff --git a/include/util/log.h b/include/util/log.h index b490363..fb0eb08 100644 --- a/include/util/log.h +++ b/include/util/log.h @@ -31,14 +31,14 @@ extern "C" { #endif -void log_tag(const char *tag, const char *format, ...) printflike(2, 3); +void log_tag(const char *tag, pid_t pid, const char *format, ...) printflike(3, 4); void log_abort(const char *format, ...) printflike(1, 2); void loge(const char *format, ...) printflike(1, 2); void logw(const char *format, ...) printflike(1, 2); void logi(const char *format, ...) printflike(1, 2); void logd(const char *format, ...) printflike(1, 2); -void log_tag_v(const char *tag, const char *format, va_list va); +void log_tag_v(const char *tag, pid_t pid, const char *format, va_list va); void log_abort_v(const char *format, va_list va); void loge_v(const char *format, va_list va); void logw_v(const char *format, va_list va); @@ -51,6 +51,13 @@ void logd_v(const char *format, va_list va); /// parse the output if all test names to start on the same column. void log_align_tags(bool enable); +/// \brief Print pids associated with log messages. +/// +/// Having the PID of a child process can be useful when trying to match +/// test results to other information reported by the system such as GPU +/// hangs or run-away processes. +void log_print_pids(bool enable); + #define log_finishme(format, ...) \ __log_finishme(__FILE__, __LINE__, format, ##__VA_ARGS__) diff --git a/misc/crucible-report b/misc/crucible-report index f629cdc..7720a40 100755 --- a/misc/crucible-report +++ b/misc/crucible-report @@ -11,7 +11,8 @@ import re import sys from textwrap import dedent -cru_re = re.compile(r'^crucible:\s+(\w*)\s*:\s+(\S*)\s*$') +cru_re = re.compile('^crucible(?:\s*\[(?P<pid>\w*)\s*\])?:' + + '\s+(?P<status>\w*)\s*:\s+(?P<name>\S*)\s*$') def parse_results(fname): results = {} @@ -21,8 +22,8 @@ def parse_results(fname): if not match: continue - name = match.group(2) - status = match.group(1) + name = match.group('name') + status = match.group('status') # We don't want info mesages if status not in ('start', 'pass', 'fail', 'skip'): diff --git a/src/cmd/run.c b/src/cmd/run.c index 6c83759..0d4dda6 100644 --- a/src/cmd/run.c +++ b/src/cmd/run.c @@ -33,6 +33,7 @@ static bool get_fork_mode(void); static runner_isolation_mode_t opt_isolation = RUNNER_ISOLATION_MODE_PROCESS; static int opt_jobs = 0; static int opt_fork = -1; // -1 => unset on cmdline +static int opt_log_pids = 0; static int opt_no_cleanup = 0; static int opt_dump = 0; static int opt_use_spir_v = 1; @@ -68,6 +69,7 @@ static const struct option longopts[] = { {"jobs", required_argument, NULL, OPT_NAME_JOBS}, {"isolation", required_argument, NULL, OPT_NAME_ISLOATION}, {"fork", no_argument, &opt_fork, true}, + {"log-pids", no_argument, &opt_log_pids, true}, {"no-fork", no_argument, &opt_fork, false}, {"no-cleanup", no_argument, &opt_no_cleanup, true}, {"dump", no_argument, &opt_dump, true}, @@ -247,6 +249,9 @@ cmd_start(const cru_command_t *cmd, int argc, char **argv) .junit_xml_filepath = opt_junit_xml, }); + if (opt_log_pids) + log_print_pids(true); + if (!ok) { loge("failed to initialize the test runner"); exit(EXIT_FAILURE); diff --git a/src/framework/runner/master.c b/src/framework/runner/master.c index 0ff3152..865016c 100644 --- a/src/framework/runner/master.c +++ b/src/framework/runner/master.c @@ -147,7 +147,7 @@ static void master_cleanup_dead_slave(slave_t *slave); static void master_collect_result(int timeout_ms); -static void master_report_result(const test_def_t *def, test_result_t result); +static void master_report_result(const test_def_t *def, pid_t pid, test_result_t result); static bool master_send_packet(slave_t *slave, const dispatch_packet_t *pk); static void master_kill_all_slaves(void); @@ -454,13 +454,13 @@ master_dispatch_loop_no_fork(void) continue; if (def->skip) { - master_report_result(def, TEST_RESULT_SKIP); + master_report_result(def, 0, TEST_RESULT_SKIP); continue; } - log_tag("start", "%s", def->name); + log_tag("start", 0, "%s", def->name); result = run_test_def(def); - master_report_result(def, result); + master_report_result(def, 0, result); } } @@ -475,7 +475,7 @@ master_dispatch_loop_with_fork(void) continue; if (def->skip) { - master_report_result(def, TEST_RESULT_SKIP); + master_report_result(def, 0, TEST_RESULT_SKIP); continue; } @@ -667,7 +667,7 @@ master_cleanup_dead_slave(slave_t *slave) // Any remaining tests owned by the slave are lost. for (uint32_t i = 0; i < slave->tests.len; ++i) { const test_def_t *def = slave->tests.data[i]; - master_report_result(def, TEST_RESULT_LOST); + master_report_result(def, slave->pid, TEST_RESULT_LOST); } assert(master.cur_dispatched_tests >= slave->tests.len); @@ -721,9 +721,9 @@ master_collect_result(int timeout_ms) } static void -master_report_result(const test_def_t *def, test_result_t result) +master_report_result(const test_def_t *def, pid_t pid, test_result_t result) { - log_tag(test_result_to_string(result), "%s", def->name); + log_tag(test_result_to_string(result), pid, "%s", def->name); fflush(stdout); switch (result) { @@ -1053,7 +1053,7 @@ slave_start_test(slave_t *slave, const test_def_t *def) if (!slave_insert_test(slave, def)) return false; - log_tag("start", "%s", def->name); + log_tag("start", slave->pid, "%s", def->name); if (!master_send_packet(slave, &pk)) { slave_rm_test(slave, def); @@ -1103,7 +1103,7 @@ slave_drain_result_pipe(slave_t *slave) return; slave_rm_test(slave, pk.test_def); - master_report_result(pk.test_def, pk.result); + master_report_result(pk.test_def, slave->pid, pk.result); } } diff --git a/src/util/log.c b/src/util/log.c index 795f876..f0eadc7 100644 --- a/src/util/log.c +++ b/src/util/log.c @@ -24,19 +24,21 @@ #include <stdlib.h> #include <stdio.h> +#include "framework/runner/runner.h" #include "framework/test/test.h" #include "util/log.h" static pthread_mutex_t log_mutex = PTHREAD_MUTEX_INITIALIZER; static bool log_has_aligned_tags = false; +static bool log_should_print_pids = false; void -log_tag(const char *tag, const char *format, ...) +log_tag(const char *tag, pid_t pid, const char *format, ...) { va_list va; va_start(va, format); - log_tag_v(tag, format, va); + log_tag_v(tag, pid, format, va); va_end(va); } @@ -91,15 +93,35 @@ logd(const char *format, ...) } void -log_tag_v(const char *tag, const char *format, va_list va) +log_tag_v(const char *tag, pid_t pid, const char *format, va_list va) { pthread_mutex_lock(&log_mutex); - if (log_has_aligned_tags) { - // Align to 7 because that's wide enough for "warning". - printf("crucible: %-7s: ", tag); + // Tags are aligned to 7 because that's wide enough for "warning". + // PID fields are aligned to 6 because that's enough for "master" and + // any 16-bit unsigned value. + if (log_should_print_pids) { + if (pid == 0) { + if (log_has_aligned_tags) { + printf("crucible [master]: %-7s: ", tag); + } else { + printf("crucible [master]: %s: ", tag); + } + } else { + assert(pid > 0 && pid <= UINT16_MAX); + int ipid = pid; // printf likes standard data types better + if (log_has_aligned_tags) { + printf("crucible [%-6d]: %-7s: ", ipid, tag); + } else { + printf("crucible [%-6d]: %s: ", ipid, tag); + } + } } else { - printf("crucible: %s: ", tag); + if (log_has_aligned_tags) { + printf("crucible: %-7s: ", tag); + } else { + printf("crucible: %s: ", tag); + } } if (test_is_current()) { @@ -119,32 +141,32 @@ log_tag_v(const char *tag, const char *format, va_list va) void log_abort_v(const char *format, va_list va) { - log_tag_v("abort", format, va); + log_tag_v("abort", 0, format, va); abort(); } void loge_v(const char *format, va_list va) { - log_tag_v("error", format, va); + log_tag_v("error", 0, format, va); } void logw_v(const char *format, va_list va) { - log_tag_v("warning", format, va); + log_tag_v("warning", 0, format, va); } void logi_v(const char *format, va_list va) { - log_tag_v("info", format, va); + log_tag_v("info", 0, format, va); } void logd_v(const char *format, va_list va) { - log_tag_v("debug", format, va); + log_tag_v("debug", 0, format, va); } void @@ -188,6 +210,12 @@ log_internal_error_loc_v(const char *file, int line, } void +log_print_pids(bool enable) +{ + log_should_print_pids = enable; +} + +void log_align_tags(bool enable) { log_has_aligned_tags = enable; |