pie: Print timestamps in restorer

Submitted by Pavel Emelianov on Jan. 11, 2017, 8:25 a.m.

Details

Message ID 5875EC0A.201@virtuozzo.com
State Accepted
Series "pie: Print timestamps in restorer"
Commit 74bd859c4cc6335708e04aa920010b6d16c235ad
Headers show

Commit Message

Pavel Emelianov Jan. 11, 2017, 8:25 a.m.
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.

Signed-off-by: Pavel Emelyanov <xemul@virtuozzo.com>
---
 compel/arch/arm/plugins/std/syscalls/syscall.def   |  1 +
 .../ppc64/plugins/std/syscalls/syscall-ppc64.tbl   |  1 +
 .../arch/x86/plugins/std/syscalls/syscall_32.tbl   |  1 +
 .../arch/x86/plugins/std/syscalls/syscall_64.tbl   |  1 +
 compel/plugins/include/uapi/std/log.h              |  3 +-
 compel/plugins/std/log.c                           | 78 +++++++++++++++++-----
 criu/cr-restore.c                                  |  1 +
 criu/include/criu-log.h                            |  1 +
 criu/include/restorer.h                            |  1 +
 criu/log.c                                         | 10 +++
 criu/pie/restorer.c                                |  1 +
 11 files changed, 83 insertions(+), 16 deletions(-)

Patch hide | download patch | download mbox

diff --git a/compel/arch/arm/plugins/std/syscalls/syscall.def b/compel/arch/arm/plugins/std/syscalls/syscall.def
index c4e390a..ffdb2eb 100644
--- a/compel/arch/arm/plugins/std/syscalls/syscall.def
+++ b/compel/arch/arm/plugins/std/syscalls/syscall.def
@@ -107,3 +107,4 @@  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)
 userfaultfd			282	388	(int flags)
+gettimeofday			169	78	(struct timeval *tv, struct timezone *tz)
diff --git a/compel/arch/ppc64/plugins/std/syscalls/syscall-ppc64.tbl b/compel/arch/ppc64/plugins/std/syscalls/syscall-ppc64.tbl
index e94277c..93e04d3 100644
--- a/compel/arch/ppc64/plugins/std/syscalls/syscall-ppc64.tbl
+++ b/compel/arch/ppc64/plugins/std/syscalls/syscall-ppc64.tbl
@@ -104,3 +104,4 @@  __NR_io_getevents	229		sys_io_getevents	(aio_context_t ctx_id, long min_nr, long
 __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_userfaultfd	364		sys_userfaultfd		(int flags)
+__NR_gettimeofday	78		sys_gettimeofday	(struct timeval *tv, struct timezone *tz)
diff --git a/compel/arch/x86/plugins/std/syscalls/syscall_32.tbl b/compel/arch/x86/plugins/std/syscalls/syscall_32.tbl
index 355de71..5d6cebd 100644
--- a/compel/arch/x86/plugins/std/syscalls/syscall_32.tbl
+++ b/compel/arch/x86/plugins/std/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)
diff --git a/compel/arch/x86/plugins/std/syscalls/syscall_64.tbl b/compel/arch/x86/plugins/std/syscalls/syscall_64.tbl
index dade3a0..35262c0 100644
--- a/compel/arch/x86/plugins/std/syscalls/syscall_64.tbl
+++ b/compel/arch/x86/plugins/std/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)
diff --git a/compel/plugins/include/uapi/std/log.h b/compel/plugins/include/uapi/std/log.h
index 9189d9f..3a3d889 100644
--- a/compel/plugins/include/uapi/std/log.h
+++ b/compel/plugins/include/uapi/std/log.h
@@ -1,10 +1,11 @@ 
 #ifndef COMPEL_PLUGIN_STD_LOG_H__
 #define COMPEL_PLUGIN_STD_LOG_H__
 
-#define STD_LOG_SIMPLE_CHUNK	72
+#define STD_LOG_SIMPLE_CHUNK	79
 
 extern void std_log_set_fd(int fd);
 extern void std_log_set_loglevel(unsigned int level);
+extern void std_log_set_start(struct timeval *tv);
 extern int std_vprint_num(char *buf, int blen, int num, char **ps);
 extern void std_sprintf(char output[STD_LOG_SIMPLE_CHUNK], const char *format, ...)
 	__attribute__ ((__format__ (__printf__, 2, 3)));
diff --git a/compel/plugins/std/log.c b/compel/plugins/std/log.c
index b60a82e..dbdbf58 100644
--- a/compel/plugins/std/log.c
+++ b/compel/plugins/std/log.c
@@ -2,6 +2,7 @@ 
 
 #include "common/bitsperlong.h"
 #include <compel/plugins/std/syscall.h>
+#include "uapi/std/string.h"
 #include <compel/plugins/std/log.h>
 #include <compel/loglevels.h>
 
@@ -14,33 +15,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 = std_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 = std_vprint_num(pbuf, sizeof(pbuf), (unsigned)now.tv_sec, &s);
+		pad_num(&s, &n, 2);
+		b->bp[0] = '(';
+		std_memcpy(b->bp + 1, s, n);
+		b->bp[n + 1] = '.';
+		b->bp += n + 2;
+
+		/* Mu-seconds */
+		n = std_vprint_num(pbuf, sizeof(pbuf), (unsigned)now.tv_usec, &s);
+		pad_num(&s, &n, 6);
+		std_memcpy(b->bp, s, n);
+		b->bp[n] = ')';
+		b->bp += n + 1;
+	}
 
-	b->bp = b->buf + b->prefix_len;
+	n = std_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] = ' ';
+	std_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;
 }
 
@@ -81,6 +124,11 @@  void std_log_set_loglevel(unsigned int level)
 	cur_loglevel = level;
 }
 
+void std_log_set_start(struct timeval *s)
+{
+	start = *s;
+}
+
 static void print_string(const char *msg, struct simple_buf *b)
 {
 	while (*msg) {
diff --git a/criu/cr-restore.c b/criu/cr-restore.c
index 1c87c6e..fb5fa74 100644
--- a/criu/cr-restore.c
+++ b/criu/cr-restore.c
@@ -3078,6 +3078,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));
diff --git a/criu/include/criu-log.h b/criu/include/criu-log.h
index d20e50d..ce60188 100644
--- a/criu/include/criu-log.h
+++ b/criu/include/criu-log.h
@@ -34,6 +34,7 @@  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 int write_pidfile(int pid);
 
diff --git a/criu/include/restorer.h b/criu/include/restorer.h
index a569fa3..23c7e24 100644
--- a/criu/include/restorer.h
+++ b/criu/include/restorer.h
@@ -107,6 +107,7 @@  struct task_restore_args {
 	int				fd_exe_link;		/* opened self->exe file */
 	int				logfd;
 	unsigned int			loglevel;
+	struct timeval			logstart;
 
 	int				uffd;
 
diff --git a/criu/log.c b/criu/log.c
index 93d9890..7997c2e 100644
--- a/criu/log.c
+++ b/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)
diff --git a/criu/pie/restorer.c b/criu/pie/restorer.c
index ccd0fbd..e50dac8 100644
--- a/criu/pie/restorer.c
+++ b/criu/pie/restorer.c
@@ -1163,6 +1163,7 @@  long __export_restore_task(struct task_restore_args *args)
 
 	std_log_set_fd(args->logfd);
 	std_log_set_loglevel(args->loglevel);
+	std_log_set_start(&args->logstart);
 
 	pr_info("Switched to the restorer %d\n", my_pid);