Re: [PATCH 2/2] [RFC] xen/console: Provide timestamps as an offset since boot.

[Don Slutz <dslutz@verizon.com>]

On 02/27/14 09:03, Andrew Cooper wrote:
> ** This is RFC, and not intended to be applied in its current state **
>
> There exists a "console_timestamps" command line option which causes full
> date/time stamps to be printed, e.g.
>
>      (XEN) ENABLING IO-APIC IRQs
>      (XEN)  -> Using old ACK method
>      (XEN) ..TIMER: vector=0xF0 apic1=0 pin1=2 apic2=-1 pin2=-1
>      (XEN) TSC deadline timer enabled
>      (XEN) [2014-02-27 12:29:27] Platform timer is 14.318MHz HPET
>      (XEN) [2014-02-27 12:29:27] Allocated console ring of 64 KiB.
>      (XEN) [2014-02-27 12:29:27] mwait-idle: MWAIT substates: 0x21120
>
> However, this only has single-second granularity.  This patch replaces the
> string printed with one which matches Linux kernel timestamps, in seconds and
> milliseconds since boot.
>
> The result looks like:
>
>      (XEN) [    0.158968] VMX: Supported advanced features:
>      (XEN) [    0.159369]  - APIC TPR shadow
>      (XEN) [    0.159771] HVM: ASIDs disabled.
>      (XEN) [    0.160203] HVM: VMX enabled
>      (XEN) [    0.160599] HVM: Hardware Assisted Paging (HAP) not detected
>
> Although it looks rather worse interleaved with kernel timestamps:
>
>      [    0.300276] pci 0000:00:1c.0: System wakeup disabled by ACPI
>      (XEN) [    3.286620] PCI add device 0000:00:1c.0
>      [    0.301169] pci 0000:00:1c.4: System wakeup disabled by ACPI
>      (XEN) [    3.287508] PCI add device 0000:00:1c.4
>      [    0.302078] pci 0000:00:1c.5: System wakeup disabled by ACPI
>      (XEN) [    3.288420] PCI add device 0000:00:1c.5
>      [    0.302899] pci 0000:00:1d.0: System wakeup disabled by ACPI
>      (XEN) [    3.289229] PCI add device 0000:00:1d.0
>
> Some latent bugs are emphasised by these changes.  There are steps in time
> when the TSC scale is calculated, and when the platform time is initialised ...
>
>      (XEN) [    0.000000] Using scheduler: SMP Credit Scheduler (credit)
>      (XEN) [   27.553075] Detected 2793.232 MHz processor.
>      (XEN) [   27.558277] Initing memory sharing.
>      (XEN) [   27.562502] Cannot set CPU feature mask on CPU#0
>      (XEN) [   27.567852] mce_intel.c:717: MCA Capability: BCAST 0 SER 0 CMCI 0 firstbank 0 extended MCE MSR 18
>      (XEN) [   27.577687] Intel machine check reporting enabled
>      (XEN) [   27.583147] PCI: MCFG configuration 0: base e0000000 segment 0000 buses 00 - 3f
>      (XEN) [   27.591407] PCI: MCFG area at e0000000 reserved in E820
>      (XEN) [   27.597369] PCI: Using MCFG for segment 0000 bus 00-3f
>      (XEN) [   27.603238] I/O virtualisation disabled
>      (XEN) [   27.608093] ENABLING IO-APIC IRQs
>      (XEN) [   27.612136]  -> Using new ACK method
>      (XEN) [   27.616601] ..TIMER: vector=0xF0 apic1=0 pin1=2 apic2=-1 pin2=-1
>      (XEN) [    0.153431] Platform timer is 14.318MHz HPET
>
> ... and the synchronisation across CPUs needs to be earlier during AP bringup.
>
>      (XEN) [    0.161004] HVM: PVH mode not supported on this platform
>      (XEN) [    0.000000] Cannot set CPU feature mask on CPU#1
>      (XEN) [    0.182299] Brought up 2 CPUs
>
> Is it likely that people would want to still have the option for the full
> date/timestamps?  If so, that code will have to be kept.

I would like to be able to select the old way.

> Comments/suggestions welcome, especially regarding the interleaving of Xen and
> dom0 timestamps.

Another option would be to just add the milliseconds to the current output.  This might help with the interleaving.

    -Don Slutz

> ~Andrew
> ---
>   xen/drivers/char/console.c |   12 +++++-------
>   1 file changed, 5 insertions(+), 7 deletions(-)
>
> diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c
> index 532c426..e2d9521 100644
> --- a/xen/drivers/char/console.c
> +++ b/xen/drivers/char/console.c
> @@ -548,21 +548,19 @@ static int printk_prefix_check(char *p, char **pp)
>   
>   static void printk_start_of_line(const char *prefix)
>   {
> -    struct tm tm;
>       char tstr[32];
> +    uint64_t sec, nsec;
>   
>       __putstr(prefix);
>   
>       if ( !opt_console_timestamps )
>           return;
>   
> -    tm = wallclock_time();
> -    if ( tm.tm_mday == 0 )
> -        return;
> +    sec = NOW();
> +    nsec = do_div(sec, 1000000000);
>   
> -    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);
> +    snprintf(tstr, sizeof(tstr), "[%5"PRIu64".%06"PRIu64"] ",
> +             sec, nsec/1000);
>       __putstr(tstr);
>   }
>