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

[Pavel Emelyanov]

On 10/03/2012 11:07 AM, Andrey Wagin wrote:
> 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?

Yup.

> I think we should check that snprintf returns  TS_BUF_OFF, otherwise
> the next line will be useless.

It's not. The snprintf puts triling zero anyway and this is not good.

>> +       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);
> .
>