Re: [Xen-devel] [PATCH] console: avoid printing no or null time stamps

[Julien Grall <julien.grall@xxxxxxx>]

Hi Jan,

On 26/06/18 08:24, Jan Beulich wrote:
> During early boot timestamps aren't very useful, as they're all zero
> (in "boot" mode) or absent altogether (in "date" and "datems" modes).
> Log "boot" format timestamps when the date formats aren't available yet,
> and log raw timestamps when boot ones are still all zero. Also add a
> "raw" mode.
>
> Signed-off-by: Jan Beulich <jbeulich@xxxxxxxx>
> ---
> ARM side build-tested only; I'm in particular unsure whether
> READ_SYSREG64(CNTPCT_EL0) can indeed be used right at start of day.
On most of the platforms, the timer will have been correctly enabled by 
the firmware. However, on a few platforms it may require additional 
setup that will be performed by platform_init_time().
In any case, CNTCPT_EL0 can always be read but may return garbage on 
those few platforms. I would not worry too much for those platforms 
thoughts.
> --- a/docs/misc/xen-command-line.markdown
> +++ b/docs/misc/xen-command-line.markdown
> @@ -413,7 +413,7 @@ only available when used together with `
>   makes sense on its own.
>   
>   ### console\_timestamps
> -> `= none | date | datems | boot`
> +> `= none | date | datems | boot | raw`
>   
>   > Default: `none`
>   
> @@ -428,6 +428,8 @@ Specify which timestamp format Xen shoul
>       * `[YYYY-MM-DD HH:MM:SS.mmm]`
>   * `boot`: Seconds and microseconds since boot
>       * `[SSSSSS.uuuuuu]`
> ++ `raw`: Raw platform ticks, architecture and implementation dependent
> +    * `[XXXXXXXXXXXXXXXX]`
>   
>   For compatibility with the older boolean parameter, specifying
>   `console_timestamps` alone will enable the `date` option.
> --- a/xen/drivers/char/console.c
> +++ b/xen/drivers/char/console.c
> @@ -68,7 +68,8 @@ enum con_timestamp_mode
>       TSM_NONE,          /* No timestamps */
>       TSM_DATE,          /* [YYYY-MM-DD HH:MM:SS] */
>       TSM_DATE_MS,       /* [YYYY-MM-DD HH:MM:SS.mmm] */
> -    TSM_BOOT           /* [SSSSSS.uuuuuu] */
> +    TSM_BOOT,          /* [SSSSSS.uuuuuu] */
> +    TSM_RAW,           /* [XXXXXXXXXXXXXXXX] */
>   };
>   
>   static enum con_timestamp_mode __read_mostly opt_con_timestamp_mode = TSM_NONE;
> @@ -676,6 +677,8 @@ static int parse_console_timestamps(cons
>           opt_con_timestamp_mode = TSM_DATE_MS;
>       else if ( !strcmp(s, "boot") )
>           opt_con_timestamp_mode = TSM_BOOT;
> +    else if ( !strcmp(s, "raw") )
> +        opt_con_timestamp_mode = TSM_RAW;
>       else if ( !strcmp(s, "none") )
>           opt_con_timestamp_mode = TSM_NONE;
>       else
> @@ -698,26 +701,30 @@ static void printk_start_of_line(const c
>       case TSM_DATE_MS:
>           tm = wallclock_time(&nsec);
>   
> -        if ( tm.tm_mday == 0 )
> -            return;
> -
> -        if ( opt_con_timestamp_mode == TSM_DATE )
> -            snprintf(tstr, sizeof(tstr), "[%04u-%02u-%02u %02u:%02u:%02u] ",
> -                     1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
> -                     tm.tm_hour, tm.tm_min, tm.tm_sec);
> -        else
> +        if ( tm.tm_mday )
> +        {
>               snprintf(tstr, sizeof(tstr),
> -                     "[%04u-%02u-%02u %02u:%02u:%02u.%03"PRIu64"] ",
> +                     opt_con_timestamp_mode == TSM_DATE
> +                     ? "[%04u-%02u-%02u %02u:%02u:%02u] "
> +                     : "[%04u-%02u-%02u %02u:%02u:%02u.%03"PRIu64"] ",
>                        1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
>                        tm.tm_hour, tm.tm_min, tm.tm_sec, nsec / 1000000);
I find this change rather difficult to read because the number of 
arguments for the 2 formats are different. It would be better to keep 
the two snprintf separately.
But I am fairly surprised the compiler is happy with such changes.

> -        break;
> -
> +            break;
> +        }
> +        /* fall through */
>       case TSM_BOOT:
>           sec = NOW();
>           nsec = do_div(sec, 1000000000);
>   
> -        snprintf(tstr, sizeof(tstr), "[%5"PRIu64".%06"PRIu64"] ",
> -                 sec, nsec / 1000);
> +        if ( sec | nsec )
> +        {
> +            snprintf(tstr, sizeof(tstr), "[%5"PRIu64".%06"PRIu64"] ",
> +                     sec, nsec / 1000);
> +            break;
> +        }
> +        /* fall through */
> +    case TSM_RAW:
> +        snprintf(tstr, sizeof(tstr), "[%016"PRIx64"] ", get_cycles());
>           break;
>   
>       case TSM_NONE:
> --- a/xen/include/asm-arm/time.h
> +++ b/xen/include/asm-arm/time.h
> @@ -5,11 +5,11 @@
>       DT_MATCH_COMPATIBLE("arm,armv7-timer"), \
>       DT_MATCH_COMPATIBLE("arm,armv8-timer")
>   
> -typedef unsigned long cycles_t;
> +typedef uint64_t cycles_t;
Please mention this change in the commit message.

>   
>   static inline cycles_t get_cycles (void)
>   {
> -        return 0;
> +        return READ_SYSREG64(CNTPCT_EL0);
>   }
>   
>   /* List of timer's IRQ */
> --- a/xen/include/asm-x86/time.h
> +++ b/xen/include/asm-x86/time.h
> @@ -28,7 +28,7 @@ extern bool disable_tsc_sync;
>   
>   static inline cycles_t get_cycles(void)
>   {
> -    return rdtsc();
> +    return rdtsc_ordered();
>   }
>   
>   unsigned long
Cheers,

--
Julien Grall

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxxx
https://lists.xenproject.org/mailman/listinfo/xen-devel