[CRIU] [PATCH] pie: Print timestamps in restorer
Pavel Emelyanov
xemul at virtuozzo.com
Wed Jan 11 00:25:46 PST 2017
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 at 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(-)
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);
--
2.5.0
More information about the CRIU
mailing list