pie: Print timestamps in restorer

Nowadays we have parasite and restorer logs just start with pie:
prefix. Let's add timestamps in restorer too.

For parasite adding timestamps would require passing the start
timeval through the libcompel which is not (yet) clear how to do.

travis-ci: success for pie: Print timestamps in restorer
Signed-off-by: Pavel Emelyanov <xemul@virtuozzo.com>

criu/arch/arm/syscalls/syscall.def

@@ -106,3 +106,4 @@ io_setup			0	243	(unsigned nr_events, aio_context_t *ctx)
 io_submit			2	246	(aio_context_t ctx_id, long nr, struct iocb **iocbpp)
 io_getevents			4	245	(aio_context_t ctx, long min_nr, long nr, struct io_event *evs, struct timespec *tmo)
 seccomp				277	383	(unsigned int op, unsigned int flags, const char *uargs)
+gettimeofday			169	78	(struct timeval *tv, struct timezone *tz)

criu/arch/ppc64/syscalls/syscall-ppc64.tbl

@@ -103,3 +103,4 @@ __NR_io_setup		227		sys_io_setup		(unsigned nr_events, aio_context_t *ctx_idp)
 __NR_io_getevents	229		sys_io_getevents	(aio_context_t ctx_id, long min_nr, long nr, struct io_event *events, struct timespec *timeout)
 __NR_io_submit		230		sys_io_submit		(aio_context_t ctx_id, long nr, struct iocb **iocbpp)
 __NR_ipc		117		sys_ipc			(unsigned int call, int first, unsigned long second, unsigned long third, const void *ptr, long fifth)
+__NR_gettimeofday	78		sys_gettimeofday	(struct timeval *tv, struct timezone *tz)

criu/arch/x86/syscalls/syscall_32.tbl

@@ -24,6 +24,7 @@ __NR_ioctl		54		sys_ioctl		(unsigned int fd, unsigned int cmd, unsigned long arg
 __NR_fcntl		55		sys_fcntl		(unsigned int fd, unsigned int cmd, unsigned long arg)
 __NR_umask		60		sys_umask		(int mask)
 __NR_setrlimit		75		sys_setrlimit		(unsigned int resource, struct krlimit *rlim)
+__NR_gettimeofday	78		sys_gettimeofday	(struct timeval *tv, struct timezone *tz)
 __NR_munmap		91		sys_munmap		(void *addr, unsigned long len)
 __NR_setpriority	97		sys_setpriority		(int which, int who, int nice)
 __NR_socketcall		102		sys_socketcall		(int call, unsigned long *args)

criu/arch/x86/syscalls/syscall_64.tbl

@@ -47,6 +47,7 @@ __NR_mkdir			83		sys_mkdir		(const char *name, int mode)
 __NR_rmdir			84		sys_rmdir		(const char *name)
 __NR_unlink			87		sys_unlink		(char *pathname)
 __NR_umask			95		sys_umask		(int mask)
+__NR_gettimeofday		96		sys_gettimeofday	(struct timeval *tv, struct timezone *tz)
 __NR_ptrace			101		sys_ptrace		(long request, pid_t pid, void *addr, void *data)
 __NR_getgroups			115		sys_getgroups		(int gsize, unsigned int *groups)
 __NR_setgroups			116		sys_setgroups		(int gsize, unsigned int *groups)

criu/cr-restore.c

@@ -2929,6 +2929,7 @@ static int sigreturn_restore(pid_t pid, struct task_restore_args *task_args, uns
 
 	task_args->logfd	= log_get_fd();
 	task_args->loglevel	= log_get_loglevel();
+	log_get_logstart(&task_args->logstart);
 	task_args->sigchld_act	= sigchld_act;
 
 	strncpy(task_args->comm, core->tc->comm, sizeof(task_args->comm));

criu/include/criu-log.h

@@ -34,6 +34,8 @@ extern int log_get_fd(void);
 
 extern void log_set_loglevel(unsigned int loglevel);
 extern unsigned int log_get_loglevel(void);
+extern void log_get_logstart(struct timeval *);
+extern void log_set_start(struct timeval *s);
 
 extern int write_pidfile(int pid);
 

criu/include/log.h

@@ -70,7 +70,7 @@ extern void print_on_level(unsigned int loglevel, const char *format, ...)
 
 #else
 
-#define LOG_SIMPLE_CHUNK	72
+#define LOG_SIMPLE_CHUNK	79
 
 extern int vprint_num(char *buf, int blen, int num, char **ps);
 extern void simple_sprintf(char output[LOG_SIMPLE_CHUNK], const char *format, ...)

criu/include/restorer.h

@@ -108,6 +108,7 @@ struct task_restore_args {
 	int				fd_exe_link;		/* opened self->exe file */
 	int				logfd;
 	unsigned int			loglevel;
+	struct timeval			logstart;
 
 	/* threads restoration */
 	int				nr_threads;		/* number of threads */

criu/log.c

@@ -66,6 +66,16 @@ int log_get_fd(void)
 	return fd < 0 ? DEFAULT_LOGFD : fd;
 }
 
+void log_get_logstart(struct timeval *s)
+{
+	if (current_loglevel >= LOG_TIMESTAMP)
+		*s = start;
+	else {
+		s->tv_sec = 0;
+		s->tv_usec = 0;
+	}
+}
+
 static void reset_buf_off(void)
 {
 	if (current_loglevel >= LOG_TIMESTAMP)

criu/pie/log-simple.c

@@ -2,6 +2,7 @@
 
 #include "int.h"
 #include "types.h"
+#include "string.h"
 #include "common/bitsperlong.h"
 #include "syscall.h"
 #include "log.h"
@@ -15,33 +16,75 @@ struct simple_buf {
 
 static int logfd = -1;
 static int cur_loglevel = DEFAULT_LOGLEVEL;
+static struct timeval start;
 
 static void sbuf_log_flush(struct simple_buf *b);
 
+static inline void timediff(struct timeval *from, struct timeval *to)
+{
+	to->tv_sec -= from->tv_sec;
+	if (to->tv_usec >= from->tv_usec)
+		to->tv_usec -= from->tv_usec;
+	else {
+		to->tv_sec--;
+		to->tv_usec += 1000000 - from->tv_usec;
+	}
+}
+
+static inline void pad_num(char **s, int *n, int nr)
+{
+	while (*n < nr) {
+		(*s)--;
+		(*n)++;
+		**s = '0';
+	}
+}
+
 static void sbuf_log_init(struct simple_buf *b)
 {
-	char pid_buf[12], *s;
+	char pbuf[12], *s;
 	int n;
 
 	/*
 	 * Format:
 	 *
-	 * pie: pid: string-itself
+	 * (time)pie: pid: string-itself
 	 */
-	b->prefix_len = vprint_num(pid_buf, sizeof(pid_buf), sys_gettid(), &s);
-	b->buf[0] = 'p';
-	b->buf[1] = 'i';
-	b->buf[2] = 'e';
-	b->buf[3] = ':';
-	b->buf[4] = ' ';
-
-	for (n = 0; n < b->prefix_len; n++)
-		b->buf[n + 5] = s[n];
-	b->buf[n + 5] = ':';
-	b->buf[n + 6] = ' ';
-	b->prefix_len += 7;
+	b->bp = b->buf;
+
+	if (start.tv_sec != 0) {
+		struct timeval now;
+
+		sys_gettimeofday(&now, NULL);
+		timediff(&start, &now);
+
+		/* Seconds */
+		n = vprint_num(pbuf, sizeof(pbuf), (unsigned)now.tv_sec, &s);
+		pad_num(&s, &n, 2);
+		b->bp[0] = '(';
+		memcpy(b->bp + 1, s, n);
+		b->bp[n + 1] = '.';
+		b->bp += n + 2;
+
+		/* Mu-seconds */
+		n = vprint_num(pbuf, sizeof(pbuf), (unsigned)now.tv_usec, &s);
+		pad_num(&s, &n, 6);
+		memcpy(b->bp, s, n);
+		b->bp[n] = ')';
+		b->bp += n + 1;
+	}
 
-	b->bp = b->buf + b->prefix_len;
+	n = vprint_num(pbuf, sizeof(pbuf), sys_gettid(), &s);
+	b->bp[0] = 'p';
+	b->bp[1] = 'i';
+	b->bp[2] = 'e';
+	b->bp[3] = ':';
+	b->bp[4] = ' ';
+	memcpy(b->bp + 5, s, n);
+	b->bp[n + 5] = ':';
+	b->bp[n + 6] = ' ';
+	b->bp += n + 7;
+	b->prefix_len = b->bp - b->buf;
 	b->flush = sbuf_log_flush;
 }
 
@@ -82,6 +125,11 @@ void log_set_loglevel(unsigned int level)
 	cur_loglevel = level;
 }
 
+void log_set_start(struct timeval *s)
+{
+	start = *s;
+}
+
 static void print_string(const char *msg, struct simple_buf *b)
 {
 	while (*msg) {

criu/pie/restorer.c

@@ -1061,6 +1061,7 @@ long __export_restore_task(struct task_restore_args *args)
 
 	log_set_fd(args->logfd);
 	log_set_loglevel(args->loglevel);
+	log_set_start(&args->logstart);
 
 	pr_info("Switched to the restorer %d\n", my_pid);