support: Print timestamps in timeout handler

Message ID 875zx0hgio.fsf@oldenburg.str.redhat.com
State New
Headers show
Series
  • support: Print timestamps in timeout handler
Related show

Commit Message

Florian Weimer Nov. 13, 2018, 8:25 p.m.
This is sometimes useful to determine if a test truly hang, or if it
was making progress (logging information to standard output) and was
just slow to complete.

2018-11-13  Florian Weimer  <fweimer@redhat.com>

	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.

Comments

Gabriel F. T. Gomes Nov. 16, 2018, 1:12 p.m. | #1
On Tue, 13 Nov 2018, Florian Weimer wrote:

>This is sometimes useful to determine if a test truly hang, or if it

>was making progress (logging information to standard output) and was

>just slow to complete.

>

>2018-11-13  Florian Weimer  <fweimer@redhat.com>

>

>	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.


Looks good to me.

>+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);

                    ~~~~~~~~~~~~~~~            ~~~~~
OK.

>+  /* 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;


OK.

>+  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 });


OK.

The st_mtim member of stat64 is only available in XOPEN2K8 mode, which is
fine for the test cases.

PS: I was reading about these types in the manual, but there's no mention
to st_mtim, only to st_mtime, which is provided when *not* in XOPEN2K8.
Does this deserve mention in the manual?  (not a problem for this patch).

Patch

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 <string.h>
 #include <sys/param.h>
 #include <sys/resource.h>
+#include <sys/time.h>
 #include <sys/types.h>
 #include <sys/wait.h>
 #include <time.h>
@@ -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);
 }