[RFC PATCH v2 0/5] Improvements to console timestamps

[RFC PATCH v2 0/5] Improvements to console timestamps

[Andrew Cooper]

This series aims to improve on the current implementation of console
timestamps in Xen.

Patch 1 is a plain optimisation fix and logically independent from the rest of
the series.

Patch 2 changes Xen's idea of when time starts, from when the BSPs TSC was 0,
to when Xen boots.

Patch 3 guesses at AP time calibration earlier during boot, so printk()s using
the new console timestamp have a real stamp, rather than 0s.

Patch 4 is the meat of the series, adding a new timestamp implementation to
printk_start_of_line().

Patch 5 comes as a intermediate suggestion, to retain the old timestamp style,
but to display milliseconds as well.

There is still one bug to fix; The time step when the platform timer start:

    (XEN) [    1.069271] ENABLING IO-APIC IRQs
    (XEN) [    1.073308]  -> Using new ACK method
    (XEN) [    1.077771] ..TIMER: vector=0xF0 apic1=0 pin1=2 apic2=-1 pin2=-1
    (XEN) [    0.017017] Platform timer is 14.318MHz HPET
    (XEN) [    0.021701] Allocated console ring of 16 KiB.

Also, from discussion in the office, it has been suggested that the timestamp
mode/format would be better as build-time configuration rather than boot-time
configuration, and I would have to lean towards agreeing with this.

Furthermore, 3 different timestamp modes would seem to be overkill.

Comments welcome,

~Andrew

[PATCH v2 1/5] x86/time: Avoid redundant this_cpu()

[Andrew Cooper]

this_cpu() makes use of RELOC_HIDE() to prevent unsafe optimisations, forcing
a recalculation of the per-cpu data area.  Don't use it needlessly.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Tim Deegan <tim@xen.org>
---
 xen/arch/x86/time.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index 82492c1..883c135 100644
--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -1323,7 +1323,7 @@ void init_percpu_time(void)
     s_time_t now;
 
     /* Initial estimate for TSC rate. */
-    this_cpu(cpu_time).tsc_scale = per_cpu(cpu_time, 0).tsc_scale;
+    t->tsc_scale = per_cpu(cpu_time, 0).tsc_scale;
 
     local_irq_save(flags);
     rdtscll(t->local_tsc_stamp);
-- 
1.7.10.4

[PATCH v2 2/5] x86/time: Always count s_time from Xen boot

[Andrew Cooper]

From: Tim Deegan <tim@xen.org>

In the early-boot clock, before the calibration routines kick in,
count time from Xen boot rather than from when the BSP's TSC was 0.

Signed-off-by: Tim Deegan <tim@xen.org>

Stash the timestamp in head.S as a good approximation of when we actually
started, rather than measuing "time since we ran early_time_init()"

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>

CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
---
 xen/arch/x86/boot/head.S |   10 ++++++++++
 xen/arch/x86/time.c      |    4 ++++
 2 files changed, 14 insertions(+)

diff --git a/xen/arch/x86/boot/head.S b/xen/arch/x86/boot/head.S
index b12eefb..d62eaae 100644
--- a/xen/arch/x86/boot/head.S
+++ b/xen/arch/x86/boot/head.S
@@ -136,6 +136,12 @@ __start:
         /* Check for availability of long mode. */
         bt      $29,%edx
         jnc     bad_cpu
+
+        /* Stash TSC to calculate a good approximation of time-since-boot */
+        rdtsc
+        mov     %eax,sym_phys(boot_tsc_stamp)
+        mov     %edx,sym_phys(boot_tsc_stamp+4)
+
         /* Initialise L2 boot-map page table entries (16MB). */
         mov     $sym_phys(l2_bootmap),%edx
         mov     $PAGE_HYPERVISOR|_PAGE_PSE,%eax
@@ -203,6 +209,10 @@ GLOBAL(trampoline_end)
 __high_start:
 #include "x86_64.S"
 
+        .section .init.data, "a", @progbits
+GLOBAL(boot_tsc_stamp)
+        .quad   0
+
         .section .data.page_aligned, "aw", @progbits
         .p2align PAGE_SHIFT
 /*
diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index 883c135..3da4def 100644
--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -84,6 +84,9 @@ static u16 pit_stamp16;
 static u32 pit_stamp32;
 static bool_t __read_mostly using_pit;
 
+/* Boot timestamp, filled in head.S (initdata) */
+extern u64 boot_tsc_stamp;
+
 /*
  * 32-bit division of integer dividend and integer divisor yielding
  * 32-bit fractional quotient.
@@ -1456,6 +1459,7 @@ void __init early_time_init(void)
     u64 tmp = init_pit_and_calibrate_tsc();
 
     set_time_scale(&this_cpu(cpu_time).tsc_scale, tmp);
+    this_cpu(cpu_time).local_tsc_stamp = boot_tsc_stamp;
 
     do_div(tmp, 1000);
     cpu_khz = (unsigned long)tmp;
-- 
1.7.10.4

[PATCH v2 3/5] x86/time: Initialise time earlier during start_secondary()

[Andrew Cooper]

It is safe to do so, and useful for "[second.nanoseconds]" style timestamps on
printk()s during secondary bringup.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Tim Deegan <tim@xen.org>
---
 xen/arch/x86/smpboot.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/xen/arch/x86/smpboot.c b/xen/arch/x86/smpboot.c
index 42b8a59..5014397 100644
--- a/xen/arch/x86/smpboot.c
+++ b/xen/arch/x86/smpboot.c
@@ -347,6 +347,8 @@ void start_secondary(void *unused)
 
     percpu_traps_init();
 
+    init_percpu_time();
+
     cpu_init();
 
     smp_callin();
@@ -381,8 +383,6 @@ void start_secondary(void *unused)
     cpumask_set_cpu(cpu, &cpu_online_map);
     unlock_vector_lock();
 
-    init_percpu_time();
-
     /* We can take interrupts now: we're officially "up". */
     local_irq_enable();
     mtrr_ap_init();
-- 
1.7.10.4

[PATCH v2 4/5] [RFC] xen/console: Provide timestamps as an offset since boot

[Andrew Cooper]

This adds a new "Linux style" console timestamp method, which is shorter and
more useful than the current date/time timestamps with single-second
granularity.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
---
 xen/drivers/char/console.c |   58 +++++++++++++++++++++++++++++++++++++-------
 1 file changed, 49 insertions(+), 9 deletions(-)

diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c
index 532c426..652d02d 100644
--- a/xen/drivers/char/console.c
+++ b/xen/drivers/char/console.c
@@ -49,8 +49,17 @@ static bool_t __read_mostly opt_console_to_ring;
 boolean_param("console_to_ring", opt_console_to_ring);
 
 /* console_timestamps: include a timestamp prefix on every Xen console line. */
-static bool_t __read_mostly opt_console_timestamps;
-boolean_param("console_timestamps", opt_console_timestamps);
+enum con_timestamp_mode
+{
+    TSM_NONE,          /* No timestamps */
+    TSM_DATE,          /* [YYYY-MM-DD HH:MM:SS] */
+    TSM_SINCE_BOOT     /* [SSSSSS.mmmmmm] */
+};
+
+static enum con_timestamp_mode __read_mostly opt_con_timestamp_mode = TSM_NONE;
+
+static void parse_console_timestamps(char *s);
+custom_param("console_timestamps", parse_console_timestamps);
 
 /* conring_size: allows a large console ring than default (16kB). */
 static uint32_t __initdata opt_conring_size;
@@ -546,23 +555,54 @@ static int printk_prefix_check(char *p, char **pp)
             ((loglvl < upper_thresh) && printk_ratelimit()));
 } 
 
+static void __init parse_console_timestamps(char *s)
+{
+    if ( *s == '\0' || /* Compat for old booleanparam() */
+         !strcmp(s, "date") )
+        opt_con_timestamp_mode = TSM_DATE;
+    else if ( !strcmp(s, "boot") )
+        opt_con_timestamp_mode = TSM_SINCE_BOOT;
+    else if ( !strcmp(s, "none") )
+        opt_con_timestamp_mode = TSM_NONE;
+    else
+        printk(XENLOG_ERR "Unrecognised timestamp mode '%s'\n", s);
+}
+
 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;
+    switch ( opt_con_timestamp_mode )
+    {
+    case TSM_DATE:
+        tm = wallclock_time();
+
+        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);
+        break;
+
+    case TSM_SINCE_BOOT:
+        sec = NOW();
+        nsec = do_div(sec, 1000000000);
 
-    tm = wallclock_time();
-    if ( tm.tm_mday == 0 )
+        snprintf(tstr, sizeof(tstr), "[%5"PRIu64".%06"PRIu64"] ",
+                 sec, nsec / 1000);
+        break;
+
+    case TSM_NONE:
+    default:
         return;
+    }
 
-    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);
     __putstr(tstr);
 }
 
-- 
1.7.10.4

[PATCH v2 5/5] [RFC] Traditional console timestamps including milliseconds

[Andrew Cooper]

Suggested-by: Don Slutz <dslutz@verizon.com>
Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
---
 xen/arch/x86/time.c        |   10 +++++++---
 xen/drivers/char/console.c |   11 ++++++++++-
 xen/include/asm-x86/time.h |    2 +-
 3 files changed, 18 insertions(+), 5 deletions(-)

diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index 3da4def..884a522 100644
--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -1648,15 +1648,19 @@ int dom0_pit_access(struct ioreq *ioreq)
     return 0;
 }
 
-struct tm wallclock_time(void)
+struct tm wallclock_time(uint64_t *ns)
 {
-    uint64_t seconds;
+    uint64_t seconds, nsec;
 
     if ( !wc_sec )
         return (struct tm) { 0 };
 
     seconds = NOW() + (wc_sec * 1000000000ull) + wc_nsec;
-    do_div(seconds, 1000000000);
+    nsec = do_div(seconds, 1000000000);
+
+    if ( *ns )
+        *ns = nsec;
+
     return gmtime(seconds);
 }
 
diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c
index 652d02d..02f6599 100644
--- a/xen/drivers/char/console.c
+++ b/xen/drivers/char/console.c
@@ -53,6 +53,7 @@ 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.mmmmmm] */
     TSM_SINCE_BOOT     /* [SSSSSS.mmmmmm] */
 };
 
@@ -560,6 +561,8 @@ static void __init parse_console_timestamps(char *s)
     if ( *s == '\0' || /* Compat for old booleanparam() */
          !strcmp(s, "date") )
         opt_con_timestamp_mode = TSM_DATE;
+    else if ( !strcmp(s, "datems") )
+        opt_con_timestamp_mode = TSM_DATE_MS;
     else if ( !strcmp(s, "boot") )
         opt_con_timestamp_mode = TSM_SINCE_BOOT;
     else if ( !strcmp(s, "none") )
@@ -579,7 +582,8 @@ static void printk_start_of_line(const char *prefix)
     switch ( opt_con_timestamp_mode )
     {
     case TSM_DATE:
-        tm = wallclock_time();
+    case TSM_DATE_MS:
+        tm = wallclock_time(&nsec);
 
         if ( tm.tm_mday == 0 )
             return;
@@ -588,6 +592,11 @@ static void printk_start_of_line(const char *prefix)
             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
+            snprintf(tstr, sizeof(tstr),
+                     "[%04u-%02u-%02u %02u:%02u:%02u.%06"PRIu64"] ",
+                     1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
+                     tm.tm_hour, tm.tm_min, tm.tm_sec, nsec / 1000);
         break;
 
     case TSM_SINCE_BOOT:
diff --git a/xen/include/asm-x86/time.h b/xen/include/asm-x86/time.h
index 147b39e..2f9dbd1 100644
--- a/xen/include/asm-x86/time.h
+++ b/xen/include/asm-x86/time.h
@@ -49,7 +49,7 @@ int dom0_pit_access(struct ioreq *ioreq);
 int cpu_frequency_change(u64 freq);
 
 struct tm;
-struct tm wallclock_time(void);
+struct tm wallclock_time(uint64_t *ns);
 
 void pit_broadcast_enter(void);
 void pit_broadcast_exit(void);
-- 
1.7.10.4

Re: [PATCH v2 5/5] [RFC] Traditional console timestamps including milliseconds

[Julien Grall]

Hello Andrew,

On 01/03/14 02:57, Andrew Cooper wrote:
> diff --git a/xen/include/asm-x86/time.h b/xen/include/asm-x86/time.h
> index 147b39e..2f9dbd1 100644
> --- a/xen/include/asm-x86/time.h
> +++ b/xen/include/asm-x86/time.h
> @@ -49,7 +49,7 @@ int dom0_pit_access(struct ioreq *ioreq);
>   int cpu_frequency_change(u64 freq);
>
>   struct tm;
> -struct tm wallclock_time(void);
> +struct tm wallclock_time(uint64_t *ns);
>


You also need to modify the prototype in asm-arm/time.h. Otherwise it 
will break compilation on ARM.

BTW, as the function is used by common code, can you merge the both 
prototype in xen/time.h?

Regards,

-- 
Julien Grall

Re: [PATCH v2 5/5] [RFC] Traditional console timestamps including milliseconds

[Andrew Cooper]

On 01/03/14 04:06, Julien Grall wrote:
> Hello Andrew,
>
> On 01/03/14 02:57, Andrew Cooper wrote:
>> diff --git a/xen/include/asm-x86/time.h b/xen/include/asm-x86/time.h
>> index 147b39e..2f9dbd1 100644
>> --- a/xen/include/asm-x86/time.h
>> +++ b/xen/include/asm-x86/time.h
>> @@ -49,7 +49,7 @@ int dom0_pit_access(struct ioreq *ioreq);
>>   int cpu_frequency_change(u64 freq);
>>
>>   struct tm;
>> -struct tm wallclock_time(void);
>> +struct tm wallclock_time(uint64_t *ns);
>>
>
>
> You also need to modify the prototype in asm-arm/time.h. Otherwise it
> will break compilation on ARM.
>
> BTW, as the function is used by common code, can you merge the both
> prototype in xen/time.h?
>
> Regards,
>

Hmm yes - I had overlooked that it was a common function declared in an
x86 header.  It certainly should be moved, irrespective of whether this
change actually happens (subject to the RFCs in patch 0)

~Andrew

Re: [PATCH v2 4/5] [RFC] xen/console: Provide timestamps as an offset since boot

[David Vrabel]

On 28/02/14 18:57, Andrew Cooper wrote:
> This adds a new "Linux style" console timestamp method, which is shorter and
> more useful than the current date/time timestamps with single-second
> granularity.
> 
> Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
> ---
>  xen/drivers/char/console.c |   58 +++++++++++++++++++++++++++++++++++++-------
>  1 file changed, 49 insertions(+), 9 deletions(-)
> 
> diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c
> index 532c426..652d02d 100644
> --- a/xen/drivers/char/console.c
> +++ b/xen/drivers/char/console.c
> @@ -49,8 +49,17 @@ static bool_t __read_mostly opt_console_to_ring;
>  boolean_param("console_to_ring", opt_console_to_ring);
>  
>  /* console_timestamps: include a timestamp prefix on every Xen console line. */
> -static bool_t __read_mostly opt_console_timestamps;
> -boolean_param("console_timestamps", opt_console_timestamps);
> +enum con_timestamp_mode
> +{
> +    TSM_NONE,          /* No timestamps */
> +    TSM_DATE,          /* [YYYY-MM-DD HH:MM:SS] */
> +    TSM_SINCE_BOOT     /* [SSSSSS.mmmmmm] */
> +};

A higher precision timestamp is useful, but do we really need different
options for this?  Can we not agree on one format?

David

Re: [PATCH v2 2/5] x86/time: Always count s_time from Xen boot

[David Vrabel]

On 28/02/14 18:57, Andrew Cooper wrote:
> From: Tim Deegan <tim@xen.org>
> 
> In the early-boot clock, before the calibration routines kick in,
> count time from Xen boot rather than from when the BSP's TSC was 0.
> 
> Signed-off-by: Tim Deegan <tim@xen.org>
> 
> Stash the timestamp in head.S as a good approximation of when we actually
> started, rather than measuing "time since we ran early_time_init()"

Is this difference/accuracy interesting?  It seems more obvious to me to
just read the TSC in early_time_init().

David

Re: [PATCH v2 3/5] x86/time: Initialise time earlier during start_secondary()

[Jan Beulich]

>>> On 28.02.14 at 19:57, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
> --- a/xen/arch/x86/smpboot.c
> +++ b/xen/arch/x86/smpboot.c
> @@ -347,6 +347,8 @@ void start_secondary(void *unused)
>  
>      percpu_traps_init();
>  
> +    init_percpu_time();
> +
>      cpu_init();
>  
>      smp_callin();

I consider it rather risky to put this before the call to cpu_init().
While currently it doesn't seem like the function depends on any
of the CPU feature flags, I could easily see this to become
necessary.

Jan

Re: [PATCH v2 5/5] [RFC] Traditional console timestamps including milliseconds

[Jan Beulich]

>>> On 28.02.14 at 19:57, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
> --- a/xen/drivers/char/console.c
> +++ b/xen/drivers/char/console.c
> @@ -53,6 +53,7 @@ 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.mmmmmm] */
>      TSM_SINCE_BOOT     /* [SSSSSS.mmmmmm] */

Just ".mmm".

> @@ -588,6 +592,11 @@ static void printk_start_of_line(const char *prefix)
>              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
> +            snprintf(tstr, sizeof(tstr),
> +                     "[%04u-%02u-%02u %02u:%02u:%02u.%06"PRIu64"] ",

And on the same basis just '.%03"PRIu64"]'

> +                     1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
> +                     tm.tm_hour, tm.tm_min, tm.tm_sec, nsec / 1000);

And finally "nsec / 1000000".

Or is the patch title wrong, and you meant microseconds (in which
case the enumerator should be TSM_DATE_US)?

Jan

Re: [PATCH v2 5/5] [RFC] Traditional console timestamps including milliseconds

[Andrew Cooper]

On 04/03/14 09:14, Jan Beulich wrote:
>>>> On 28.02.14 at 19:57, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>> --- a/xen/drivers/char/console.c
>> +++ b/xen/drivers/char/console.c
>> @@ -53,6 +53,7 @@ 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.mmmmmm] */
>>      TSM_SINCE_BOOT     /* [SSSSSS.mmmmmm] */
> Just ".mmm".
>
>> @@ -588,6 +592,11 @@ static void printk_start_of_line(const char *prefix)
>>              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
>> +            snprintf(tstr, sizeof(tstr),
>> +                     "[%04u-%02u-%02u %02u:%02u:%02u.%06"PRIu64"] ",
> And on the same basis just '.%03"PRIu64"]'
>
>> +                     1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
>> +                     tm.tm_hour, tm.tm_min, tm.tm_sec, nsec / 1000);
> And finally "nsec / 1000000".
>
> Or is the patch title wrong, and you meant microseconds (in which
> case the enumerator should be TSM_DATE_US)?
>
> Jan
>

The patch title was indeed wrong in context, although either
milliseconds or microseconds could be appropriate here; the time prefix
was already quite long and is somewhat uncomfortably long given the
extra 7 characters.

~Andrew

Re: [PATCH v2 3/5] x86/time: Initialise time earlier during start_secondary()

[Andrew Cooper]

On 04/03/14 09:02, Jan Beulich wrote:
>>>> On 28.02.14 at 19:57, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>> --- a/xen/arch/x86/smpboot.c
>> +++ b/xen/arch/x86/smpboot.c
>> @@ -347,6 +347,8 @@ void start_secondary(void *unused)
>>  
>>      percpu_traps_init();
>>  
>> +    init_percpu_time();
>> +
>>      cpu_init();
>>  
>>      smp_callin();
> I consider it rather risky to put this before the call to cpu_init().
> While currently it doesn't seem like the function depends on any
> of the CPU feature flags, I could easily see this to become
> necessary.
>
> Jan
>

The thing is that cpu_init() has quite a few printk()s in, mainly on
error paths, which use a timestamp of all 0's as the TSC scale and delta
have not yet been copied from the bsp.

Any potential new functionality in the future could easily define
init_percpu_time_late() or similar.

~Andrew

Re: [PATCH v2 5/5] [RFC] Traditional console timestamps including milliseconds

[Don Slutz]

On 03/04/14 05:30, Andrew Cooper wrote:
> On 04/03/14 09:14, Jan Beulich wrote:
>>>>> On 28.02.14 at 19:57, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>>> --- a/xen/drivers/char/console.c
>>> +++ b/xen/drivers/char/console.c
>>> @@ -53,6 +53,7 @@ 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.mmmmmm] */
>>>       TSM_SINCE_BOOT     /* [SSSSSS.mmmmmm] */
>> Just ".mmm".
>>
>>> @@ -588,6 +592,11 @@ static void printk_start_of_line(const char *prefix)
>>>               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
>>> +            snprintf(tstr, sizeof(tstr),
>>> +                     "[%04u-%02u-%02u %02u:%02u:%02u.%06"PRIu64"] ",
>> And on the same basis just '.%03"PRIu64"]'
>>
>>> +                     1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
>>> +                     tm.tm_hour, tm.tm_min, tm.tm_sec, nsec / 1000);
>> And finally "nsec / 1000000".
>>
>> Or is the patch title wrong, and you meant microseconds (in which
>> case the enumerator should be TSM_DATE_US)?
>>
>> Jan
>>
> The patch title was indeed wrong in context, although either
> milliseconds or microseconds could be appropriate here; the time prefix
> was already quite long and is somewhat uncomfortably long given the
> extra 7 characters.

I think that only 3 digits is enough for this format.   This format (that I asked for) is more useful in a set of long running servers where the date/time a given server started is not handy or easy to add seconds to so as to know when something was logged.  The TSM_SINCE_BOOT mode is more for looking at issues in a shorter time frame.

    -Don Slutz

> ~Andrew
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

[PATCH v3] x86/time: Always count s_time from Xen boot

[Tim Deegan]

Timestamped printks() can call NOW() before init_xen_time().
Set a baseline TSC as soon as we've calibrated the TSC rate,
so that NOW() consistently counts from boot time.

Signed-off-by: Tim Deegan <tim@xen.org>
Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>

CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
---
v2: use TSC from __start() rather than from early_time_init().
v3: remove later reset of TSC baseline from init_xen_time().

diff --git a/xen/arch/x86/boot/head.S b/xen/arch/x86/boot/head.S
index b12eefb..d62eaae 100644
--- a/xen/arch/x86/boot/head.S
+++ b/xen/arch/x86/boot/head.S
@@ -136,6 +136,12 @@ __start:
         /* Check for availability of long mode. */
         bt      $29,%edx
         jnc     bad_cpu
+
+        /* Stash TSC to calculate a good approximation of time-since-boot */
+        rdtsc
+        mov     %eax,sym_phys(boot_tsc_stamp)
+        mov     %edx,sym_phys(boot_tsc_stamp+4)
+
         /* Initialise L2 boot-map page table entries (16MB). */
         mov     $sym_phys(l2_bootmap),%edx
         mov     $PAGE_HYPERVISOR|_PAGE_PSE,%eax
@@ -203,6 +209,10 @@ GLOBAL(trampoline_end)
 __high_start:
 #include "x86_64.S"
 
+        .section .init.data, "a", @progbits
+GLOBAL(boot_tsc_stamp)
+        .quad   0
+
         .section .data.page_aligned, "aw", @progbits
         .p2align PAGE_SHIFT
 /*
diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index 000191b..a5e7eca 100644
--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -84,6 +84,9 @@ static u16 pit_stamp16;
 static u32 pit_stamp32;
 static bool_t __read_mostly using_pit;
 
+/* Boot timestamp, filled in head.S (initdata) */
+extern u64 boot_tsc_stamp;
+
 /*
  * 32-bit division of integer dividend and integer divisor yielding
  * 32-bit fractional quotient.
@@ -1433,9 +1436,6 @@ int __init init_xen_time(void)
 
     open_softirq(TIME_CALIBRATE_SOFTIRQ, local_time_calibration);
 
-    /* System time (get_s_time()) starts ticking from now. */
-    rdtscll(this_cpu(cpu_time).local_tsc_stamp);
-
     /* NB. get_cmos_time() can take over one second to execute. */
     do_settime(get_cmos_time(), 0, NOW());
 
@@ -1456,6 +1456,7 @@ void __init early_time_init(void)
     u64 tmp = init_pit_and_calibrate_tsc();
 
     set_time_scale(&this_cpu(cpu_time).tsc_scale, tmp);
+    this_cpu(cpu_time).local_tsc_stamp = boot_tsc_stamp;
 
     do_div(tmp, 1000);
     cpu_khz = (unsigned long)tmp;

Re: [PATCH v3] x86/time: Always count s_time from Xen boot

[Jan Beulich]

>>> On 06.03.14 at 17:01, Tim Deegan <tim@xen.org> wrote:
> @@ -203,6 +209,10 @@ GLOBAL(trampoline_end)
>  __high_start:
>  #include "x86_64.S"
>  
> +        .section .init.data, "a", @progbits
> +GLOBAL(boot_tsc_stamp)
> +        .quad   0

I think it would be better to have that definition in the C file, ...

> --- a/xen/arch/x86/time.c
> +++ b/xen/arch/x86/time.c
> @@ -84,6 +84,9 @@ static u16 pit_stamp16;
>  static u32 pit_stamp32;
>  static bool_t __read_mostly using_pit;
>  
> +/* Boot timestamp, filled in head.S (initdata) */
> +extern u64 boot_tsc_stamp;

... instead of only declaring it here.

Jan

Re: [PATCH v3] x86/time: Always count s_time from Xen boot

[Andrew Cooper]

On 06/03/14 16:15, Jan Beulich wrote:
>>>> On 06.03.14 at 17:01, Tim Deegan <tim@xen.org> wrote:
>> @@ -203,6 +209,10 @@ GLOBAL(trampoline_end)
>>  __high_start:
>>  #include "x86_64.S"
>>  
>> +        .section .init.data, "a", @progbits
>> +GLOBAL(boot_tsc_stamp)
>> +        .quad   0
> I think it would be better to have that definition in the C file, ...
>
>> --- a/xen/arch/x86/time.c
>> +++ b/xen/arch/x86/time.c
>> @@ -84,6 +84,9 @@ static u16 pit_stamp16;
>>  static u32 pit_stamp32;
>>  static bool_t __read_mostly using_pit;
>>  
>> +/* Boot timestamp, filled in head.S (initdata) */
>> +extern u64 boot_tsc_stamp;
> ... instead of only declaring it here.
>
> Jan
>

Ok - I will see about cleaning this up (as it was my part of the patch)
and respin the full series.