From 35e3fbc4512c880fccb35b8e3abd132d4be18480 Mon Sep 17 00:00:00 2001 From: Florian Weimer Date: Mon, 19 Nov 2018 15:35:03 +0100 Subject: support: Print timestamps in timeout handler This is sometimes useful to determine if a test truly got stuck, or if it was making progress (logging information to standard output) and was merely slow to finish. --- ChangeLog | 7 +++++++ support/support_test_main.c | 28 ++++++++++++++++++++++++++++ 2 files changed, 35 insertions(+) diff --git a/ChangeLog b/ChangeLog index c71209b039..195368aaae 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,3 +1,10 @@ +2018-11-19 Florian Weimer + + support: Print timestamps in timeout handler. + * support/support_test_main.c (print_timestamp): New function. + (signal_handler): Use it to print the termination time and the + time of the last write to standard output. + 2018-11-16 Zack Weinberg Gabriel F. T. Gomes diff --git a/support/support_test_main.c b/support/support_test_main.c index 23429779ac..fa3c2e06de 100644 --- a/support/support_test_main.c +++ b/support/support_test_main.c @@ -30,6 +30,7 @@ #include #include #include +#include #include #include #include @@ -86,6 +87,19 @@ static pid_t test_pid; /* The cleanup handler passed to test_main. */ static void (*cleanup_function) (void); +static void +print_timestamp (const char *what, struct timeval tv) +{ + struct tm tm; + if (gmtime_r (&tv.tv_sec, &tm) == NULL) + printf ("%s: %lld.%06d\n", + what, (long long int) tv.tv_sec, (int) tv.tv_usec); + else + printf ("%s: %04d-%02d-%02dT%02d:%02d:%02d.%06d\n", + what, 1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday, + tm.tm_hour, tm.tm_min, tm.tm_sec, (int) tv.tv_usec); +} + /* Timeout handler. We kill the child and exit with an error. */ static void __attribute__ ((noreturn)) @@ -94,6 +108,13 @@ signal_handler (int sig) int killed; int status; + /* Do this first to avoid further interference from the + subprocess. */ + struct timeval now; + bool now_available = gettimeofday (&now, NULL) == 0; + struct stat64 st; + bool st_available = fstat64 (STDOUT_FILENO, &st) == 0 && st.st_mtime != 0; + assert (test_pid > 1); /* Kill the whole process group. */ kill (-test_pid, SIGKILL); @@ -144,6 +165,13 @@ signal_handler (int sig) printf ("Timed out: killed the child process but it exited %d\n", WEXITSTATUS (status)); + if (now_available) + print_timestamp ("Termination time", now); + if (st_available) + print_timestamp ("Last write to standard output", + (struct timeval) { st.st_mtim.tv_sec, + st.st_mtim.tv_nsec / 1000 }); + /* Exit with an error. */ exit (1); } -- cgit 1.4.1