[CRIU] Re: [PATCH] log: Add relative timestamp before each log line

[Andrey Wagin]

2012/10/3 Pavel Emelyanov <xemul at parallels.com>:
> I find this handy. Do you have any objections?
>
> Andrey, you didn't want to call getpid() on each log message, is

getpid() doesn't do syscall each time, so you can remove all this logic.

> gettimeofday() OK from your POV?

My POV has not any objection against that;).

Acked-by: Andrew Vagin <avagin at openvz.org>

A few minor comments are inline
>
> Signed-off-by: Pavel Emelyanov <xemul at parallels.com>
>
> ---
>
> diff --git a/log.c b/log.c
> index d9a36f1..8fe3429 100644
> --- a/log.c
> +++ b/log.c
> @@ -27,6 +27,37 @@ static int logdir = -1;
>  static char buffer[PAGE_SIZE];
>  static char buf_off = 0;
>
> +static struct timeval start;
> +/*
> + * Manual buf len as sprintf will _always_ put '\0' at the
> + * and, but we want a "constant" pid to be there on restore
> + */
> +#define TS_BUF_OFF     12
> +
> +static 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 void print_ts(void)
> +{
> +       struct timeval t;
> +
> +       gettimeofday(&t, NULL);
> +       timediff(&start, &t);
> +       snprintf(buffer, 12,
> +                       "(%02u.%06u)", (unsigned)t.tv_sec, (unsigned)t.tv_usec);

Could we use TS_BUF_OFF instead of 12?
I think we should check that snprintf returns  TS_BUF_OFF, otherwise
the next line will be useless.

> +       buffer[TS_BUF_OFF - 1] = ' '; /* kill the '\0' produced by snprintf */
> +}
> +
> +
> +
>  int log_get_fd(void)
>  {
>         return current_logfd;
> @@ -36,6 +67,9 @@ int log_init(const char *output)
>  {
>         int new_logfd, sfd, dfd;
>
> +       gettimeofday(&start, NULL);
> +       buf_off = TS_BUF_OFF;
> +
>         dfd = get_service_fd(LOG_DIR_FD_OFF);
>         if (dfd < 0) {
>                 pr_msg("Can't obtain logfd");
> @@ -96,8 +130,15 @@ int log_init_by_pid(void)
>  {
>         char path[PATH_MAX];
>
> +       /*
> +        * reset buf_off as this fn is called on each fork while
> +        * restoring process tree
> +        */
> +
> +       buf_off = TS_BUF_OFF;
> +
>         if (!opts.log_file_per_pid) {
> -               buf_off = snprintf(buffer, PAGE_SIZE, "%6d: ", getpid());
> +               buf_off += snprintf(buffer + buf_off, PAGE_SIZE - buf_off, "%6d: ", getpid());
>                 return 0;
>         }
>
> @@ -148,6 +189,8 @@ void print_on_level(unsigned int loglevel, const char *format, ...)
>                 fd = current_logfd;
>         }
>
> +       print_ts();
> +
>         va_start(params, format);
>         size = vsnprintf(buffer + buf_off, PAGE_SIZE - buf_off, format, params);
>         va_end(params);