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

[Andrew Cooper <andrew.cooper3@xxxxxxxxxx>]

** 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.

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

~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);
 }
 
-- 
1.7.10.4


_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel