trace(1): add basic support for timestamps

This patch adds strace-like support for a -t command line option,
which causes a timestamp to be printed at the beginning of each line.
If the option is given more than once, the output will also include
microseconds.

Change-Id: I8cda581651859448c154b01815cc49d915b7b354

minix/usr.bin/trace/output.c

@@ -165,15 +165,18 @@ output_flush(void)
 }
 
 /*
- * Print a PID prefix for the given process, or an info prefix if no process
- * (NULL) is given.  Prefixes are only relevant when multiple processes are
- * traced.  As long as there are multiple processes, each line is prefixed with
- * the PID of the process.  As soon as the number of processes has been reduced
- * back to one, one more line is prefixed with the PID of the remaining process
- * (with a "'" instead of a "|") to help the user identify which process is
- * left.  In addition, whenever a preempted call is about to be resumed, a "*"
- * is printed instead of a space, so as to show that it is a continuation of a
- * previous line.  An example of all these cases:
+ * Print a prefix for a line of output.  Possibly print a timestamp first.
+ * Then, if applicable, print a PID prefix for the given process, or an info
+ * prefix if no process (NULL) is given.
+ *
+ * PIDs are relevant only when multiple processes are traced.  As long as there
+ * are multiple processes, each line is prefixed with the PID of the process.
+ * As soon as the number of processes has been reduced back to one, one more
+ * line is prefixed with the PID of the remaining process (with a "'" instead
+ * of a "|") to help the user identify which process remains.  In addition,
+ * whenever a preempted call is about to be resumed, a "*" is printed instead
+ * of a space, so as to show that it is a continuation of a previous line.  An
+ * example of all these cases:
  *
  *   fork() = 3
  *       3| Tracing test (pid 3)
@@ -191,11 +194,33 @@ output_flush(void)
 static void
 put_prefix(struct trace_proc * proc, int resuming)
 {
+	struct timeval tv;
+	struct tm *tm;
 	char prefix[32];
-	unsigned int count;
+	unsigned int off, count;
 
 	assert(line_off == 0);
 
+	off = 0;
+
+	if (timestamps > 0) {
+		gettimeofday(&tv, NULL);
+
+		tm = gmtime(&tv.tv_sec);
+
+		off = strftime(prefix, sizeof(prefix), "%T", tm);
+
+		if (timestamps > 1)
+			off += snprintf(&prefix[off], sizeof(prefix) - off,
+			    ".%06u", tv.tv_usec);
+
+		assert(off < sizeof(prefix) - 2);
+		prefix[off++] = ' ';
+		prefix[off] = '\0';
+
+		off = output_write(prefix);
+	}
+
 	count = proc_count();
 
 	/* TODO: add a command line option for always printing the pid. */
@@ -212,14 +237,14 @@ put_prefix(struct trace_proc * proc, int resuming)
 			    proc->pid, (count > 1) ? '|' : '\'',
 			    resuming ? '*' : ' ');
 
-		prefix_off = line_off = output_write(prefix);
+		off += output_write(prefix);
 
 		last_pid = (proc != NULL ? proc->pid : 0);
-	} else {
+	} else
 		assert(!resuming);
 
-		prefix_off = 0;
-	}
+	prefix_off = off;
+	line_off += off;
 
 	/* Remember whether the next line should get prefixed regardless. */
 	print_pid = (count > 1 || proc == NULL);

minix/usr.bin/trace/proto.h

@@ -96,6 +96,7 @@ unsigned int proc_count(void);
 const char *get_signal_name(int sig);
 
 /* trace.c */
+extern int timestamps;
 extern int allnames;
 extern unsigned int verbose;
 extern unsigned int valuesonly;

minix/usr.bin/trace/trace.1

@@ -6,7 +6,7 @@
 .Nd print process system calls and signals
 .Sh SYNOPSIS
 .Nm
-.Op Fl fgNsVv
+.Op Fl fgNstVv
 .Op Fl o Ar file
 .Op Fl p Ar pid
 .Op Ar command
@@ -58,6 +58,14 @@ preceded by a line showing the process's current stack trace.
 For signals blocked by the target process, the stack trace may not be
 meaningful.
 Stack traces may not be supported on all platforms.
+.It Fl t
+Print timestamps.
+By default, no timestamps are printed.
+If this flag is given once, each line will be prefixed by the current time.
+If this flag is given twice, the time will also include microseconds.
+The printed timestamp corresponds to the time at which printing of the rest of
+the line was initiated, which in the case of call resumption may not be the
+same as the time that the system call was initiated.
 .It Fl V
 Print values only.
 If this flag is given once, numerical values will be printed instead of

minix/usr.bin/trace/trace.c

@@ -8,6 +8,7 @@
 #include <err.h>
 
 /* Global variables, used only for a subset of the command line options. */
+int timestamps;		 /* 0 = none, 1 = time w/o usecs, 2 = time w/usecs */
 int allnames;		 /* FALSE = structure field names, TRUE = all names */
 unsigned int valuesonly; /* 0 = normal, 1 = no symbols, 2 = no structures */
 unsigned int verbose;	 /* 0 = essentials, 1 = elaborate, 2 = everything */
@@ -444,7 +445,7 @@ static void __dead
 usage(void)
 {
 
-	(void)fprintf(stderr, "usage: %s [-fgNsVv] [-o file] [-p pid] "
+	(void)fprintf(stderr, "usage: %s [-fgNstVv] [-o file] [-p pid] "
 	    "[command]\n", getprogname());
 
 	exit(EXIT_FAILURE);
@@ -471,11 +472,12 @@ main(int argc, char * argv[])
 	grouping = FALSE;
 	output_file = NULL;
 
+	timestamps = 0;
 	allnames = FALSE;
 	verbose = 0;
 	valuesonly = 0;
 
-	while ((c = getopt(argc, argv, "fgNsVvo:p:")) != -1) {
+	while ((c = getopt(argc, argv, "fgNstVvo:p:")) != -1) {
 		switch (c) {
 		case 'f':
 			follow_fork = TRUE;
@@ -489,6 +491,9 @@ main(int argc, char * argv[])
 		case 's':
 			show_stack = TRUE;
 			break;
+		case 't':
+			timestamps++;
+			break;
 		case 'V':
 			valuesonly++;
 			break;