[PATCH v3 0/5] Improvements to console timestamps

[PATCH v3 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 just movement of wallclock_time()s declaration to common code.

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.


Finally, 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.  I am on the fence with this regard, but
comments/thoughts are very welcome.

~Andrew

[PATCH v3 1/5] xen/time: Move wallclock_time() declaration into common code

[Andrew Cooper]

It is called from common code, but has architecture specific implementations.
Have one declaration instead of two.

No functional change.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Ian Campbell <ian.campbell@citrix.com>
CC: Stefano Stabellini <stefano.stabellini@citrix.com>
CC: Tim Deegan <tim@xen.org>
---
 xen/include/asm-arm/time.h |    3 ---
 xen/include/asm-x86/time.h |    3 ---
 xen/include/xen/time.h     |    1 +
 3 files changed, 1 insertion(+), 6 deletions(-)

diff --git a/xen/include/asm-arm/time.h b/xen/include/asm-arm/time.h
index 9d302d3..d10c737 100644
--- a/xen/include/asm-arm/time.h
+++ b/xen/include/asm-arm/time.h
@@ -12,9 +12,6 @@ static inline cycles_t get_cycles (void)
         return 0;
 }
 
-struct tm;
-struct tm wallclock_time(void);
-
 /* List of timer's IRQ */
 enum timer_ppi
 {
diff --git a/xen/include/asm-x86/time.h b/xen/include/asm-x86/time.h
index 147b39e..c01b0a2 100644
--- a/xen/include/asm-x86/time.h
+++ b/xen/include/asm-x86/time.h
@@ -48,9 +48,6 @@ int dom0_pit_access(struct ioreq *ioreq);
 
 int cpu_frequency_change(u64 freq);
 
-struct tm;
-struct tm wallclock_time(void);
-
 void pit_broadcast_enter(void);
 void pit_broadcast_exit(void);
 int pit_broadcast_is_available(void);
diff --git a/xen/include/xen/time.h b/xen/include/xen/time.h
index 95b4b91..3eb5b63 100644
--- a/xen/include/xen/time.h
+++ b/xen/include/xen/time.h
@@ -48,6 +48,7 @@ struct tm {
     int     tm_isdst;       /* daylight saving time */
 };
 struct tm gmtime(unsigned long t);
+struct tm wallclock_time(void);
 
 #define SYSTEM_TIME_HZ  1000000000ULL
 #define NOW()           ((s_time_t)get_s_time())
-- 
1.7.10.4

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

[Andrew Cooper]

From: Tim Deegan <tim@xen.org>

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().
v4: shuffle boot_tsc_stamp definition and use of 'this_cpu()'.
---
 xen/arch/x86/boot/head.S |    6 ++++++
 xen/arch/x86/time.c      |   10 ++++++----
 2 files changed, 12 insertions(+), 4 deletions(-)

diff --git a/xen/arch/x86/boot/head.S b/xen/arch/x86/boot/head.S
index b12eefb..1777c17 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
diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index 000191b..4f4de22 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 */
+u64 __initdata 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());
 
@@ -1453,9 +1453,11 @@ int __init init_xen_time(void)
 /* Early init function. */
 void __init early_time_init(void)
 {
+    struct cpu_time *t = &this_cpu(cpu_time);
     u64 tmp = init_pit_and_calibrate_tsc();
 
-    set_time_scale(&this_cpu(cpu_time).tsc_scale, tmp);
+    set_time_scale(&t->tsc_scale, tmp);
+    t->local_tsc_stamp = boot_tsc_stamp;
 
     do_div(tmp, 1000);
     cpu_khz = (unsigned long)tmp;
-- 
1.7.10.4

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

[Andrew Cooper]

It is safe to do so, and useful for "[second.microseconds]" 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 v3 4/5] 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>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Tim Deegan <tim@xen.org>
---
 docs/misc/xen-command-line.markdown |   15 +++++++--
 xen/drivers/char/console.c          |   58 +++++++++++++++++++++++++++++------
 2 files changed, 61 insertions(+), 12 deletions(-)

diff --git a/docs/misc/xen-command-line.markdown b/docs/misc/xen-command-line.markdown
index 15aa404..98c9e5e 100644
--- a/docs/misc/xen-command-line.markdown
+++ b/docs/misc/xen-command-line.markdown
@@ -275,11 +275,20 @@ cleared.  This allows a single port to be shared by two subsystems
 makes sense on its own.
 
 ### console\_timestamps
-> `= <boolean>`
+> `= none | date | boot`
 
-> Default: `false`
+> Default: `boot`
+
+Specify which timestamp format Xen should use for each console line.
+
+* `none`: No timestamps
+* `date`: Date and time information
+    * `[YYYY-MM-DD HH:MM:SS]`
+* `boot`: Seconds and microseconds since boot
+    * `[SSSSSS.uuuuuu]`
 
-Flag to indicate whether include a timestamp with each console line.
+For compatibility with the older boolean parameter, specifying
+`console_timestamps` alone will enable the `date` option.
 
 ### console\_to\_ring
 > `= <boolean>`
diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c
index 7d4383c..60461b9 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_BOOT           /* [SSSSSS.uuuuuu] */
+};
+
+static enum con_timestamp_mode __read_mostly opt_con_timestamp_mode = TSM_BOOT;
+
+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_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_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

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

[Jan Beulich]

>>> On 06.03.14 at 20:28, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
> --- a/docs/misc/xen-command-line.markdown
> +++ b/docs/misc/xen-command-line.markdown
> @@ -275,11 +275,20 @@ cleared.  This allows a single port to be shared by two 
> subsystems
>  makes sense on its own.
>  
>  ### console\_timestamps
> -> `= <boolean>`
> +> `= none | date | boot`
>  
> -> Default: `false`
> +> Default: `boot`

I'd prefer the default to remain "no time stamps". They're useful
occasionally but not generally, and they consume serial console
bandwidth.

> +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_BOOT;
> +    else if ( !strcmp(s, "none") )
> +        opt_con_timestamp_mode = TSM_NONE;
> +    else
> +        printk(XENLOG_ERR "Unrecognised timestamp mode '%s'\n", s);

Printing from command line parsing routines is IIRC rather pointless
(i.e. ISTR it goes no-where), and in the majority of other cases I
think we don't warn about improper arguments of options. With
the command line being logged as a whole, there's also not much
point since the incorrect value can be easily determined by looking
there.

Jan

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

[Andrew Cooper]

On 07/03/14 09:47, Jan Beulich wrote:
>>>> On 06.03.14 at 20:28, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>> --- a/docs/misc/xen-command-line.markdown
>> +++ b/docs/misc/xen-command-line.markdown
>> @@ -275,11 +275,20 @@ cleared.  This allows a single port to be shared by two 
>> subsystems
>>  makes sense on its own.
>>  
>>  ### console\_timestamps
>> -> `= <boolean>`
>> +> `= none | date | boot`
>>  
>> -> Default: `false`
>> +> Default: `boot`
> I'd prefer the default to remain "no time stamps". They're useful
> occasionally but not generally, and they consume serial console
> bandwidth.

I would disgree with usefulness, but can see your point - I shall revert
the default back to none.

>
>> +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_BOOT;
>> +    else if ( !strcmp(s, "none") )
>> +        opt_con_timestamp_mode = TSM_NONE;
>> +    else
>> +        printk(XENLOG_ERR "Unrecognised timestamp mode '%s'\n", s);
> Printing from command line parsing routines is IIRC rather pointless
> (i.e. ISTR it goes no-where), and in the majority of other cases I
> think we don't warn about improper arguments of options. With
> the command line being logged as a whole, there's also not much
> point since the incorrect value can be easily determined by looking
> there.
>
> Jan
>

It appears at the top of xl dmesg, but not on the serial console.  I
shall drop it.

~Andrew

[PATCH v3 5/5] xen/console: Traditional console timestamps including milliseconds

[Andrew Cooper]

Suggested-by: Don Slutz <dslutz@verizon.com>
Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Ian Campbell <ian.campbell@citrix.com>
CC: Stefano Stabellini <stefano.stabellini@citrix.com>
CC: Tim Deegan <tim@xen.org>

---

The change in arm is only for the sake of compilation - the function is a
no-op.
---
 docs/misc/xen-command-line.markdown |    4 +++-
 xen/arch/arm/time.c                 |    2 +-
 xen/arch/x86/time.c                 |   10 +++++++---
 xen/drivers/char/console.c          |   11 ++++++++++-
 xen/include/xen/time.h              |    2 +-
 5 files changed, 22 insertions(+), 7 deletions(-)

diff --git a/docs/misc/xen-command-line.markdown b/docs/misc/xen-command-line.markdown
index 98c9e5e..89dc484 100644
--- a/docs/misc/xen-command-line.markdown
+++ b/docs/misc/xen-command-line.markdown
@@ -275,7 +275,7 @@ cleared.  This allows a single port to be shared by two subsystems
 makes sense on its own.
 
 ### console\_timestamps
-> `= none | date | boot`
+> `= none | date | datems | boot`
 
 > Default: `boot`
 
@@ -284,6 +284,8 @@ Specify which timestamp format Xen should use for each console line.
 * `none`: No timestamps
 * `date`: Date and time information
     * `[YYYY-MM-DD HH:MM:SS]`
+* `datems`: Date and time, with milliseconds
+    * `[YYYY-MM-DD HH:MM:SS.mmm]`
 * `boot`: Seconds and microseconds since boot
     * `[SSSSSS.uuuuuu]`
 
diff --git a/xen/arch/arm/time.c b/xen/arch/arm/time.c
index 81e3e28..22e94bb 100644
--- a/xen/arch/arm/time.c
+++ b/xen/arch/arm/time.c
@@ -282,7 +282,7 @@ void domain_set_time_offset(struct domain *d, int32_t time_offset_seconds)
     /* XXX update guest visible wallclock time */
 }
 
-struct tm wallclock_time(void)
+struct tm wallclock_time(uint64_t *ns)
 {
     return (struct tm) { 0 };
 }
diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index 4f4de22..1156ccc 100644
--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -1646,15 +1646,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() + SECONDS(wc_sec) + 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 60461b9..837e8a8 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.mmm] */
     TSM_BOOT           /* [SSSSSS.uuuuuu] */
 };
 
@@ -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_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.%03"PRIu64"] ",
+                     1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
+                     tm.tm_hour, tm.tm_min, tm.tm_sec, nsec / 1000000);
         break;
 
     case TSM_BOOT:
diff --git a/xen/include/xen/time.h b/xen/include/xen/time.h
index 3eb5b63..2703454 100644
--- a/xen/include/xen/time.h
+++ b/xen/include/xen/time.h
@@ -48,7 +48,7 @@ struct tm {
     int     tm_isdst;       /* daylight saving time */
 };
 struct tm gmtime(unsigned long t);
-struct tm wallclock_time(void);
+struct tm wallclock_time(uint64_t *ns);
 
 #define SYSTEM_TIME_HZ  1000000000ULL
 #define NOW()           ((s_time_t)get_s_time())
-- 
1.7.10.4

Re: [PATCH v3 5/5] xen/console: Traditional console timestamps including milliseconds

[Don Slutz]

On 03/06/14 14:28, Andrew Cooper wrote:
> Suggested-by: Don Slutz <dslutz@verizon.com>
> Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
> CC: Keir Fraser <keir@xen.org>
> CC: Jan Beulich <JBeulich@suse.com>
> CC: Ian Campbell <ian.campbell@citrix.com>
> CC: Stefano Stabellini <stefano.stabellini@citrix.com>
> CC: Tim Deegan <tim@xen.org>
>
> ---
>
> The change in arm is only for the sake of compilation - the function is a
> no-op.
> ---
>   docs/misc/xen-command-line.markdown |    4 +++-
>   xen/arch/arm/time.c                 |    2 +-
>   xen/arch/x86/time.c                 |   10 +++++++---
>   xen/drivers/char/console.c          |   11 ++++++++++-
>   xen/include/xen/time.h              |    2 +-
>   5 files changed, 22 insertions(+), 7 deletions(-)
>
> diff --git a/docs/misc/xen-command-line.markdown b/docs/misc/xen-command-line.markdown
> index 98c9e5e..89dc484 100644
> --- a/docs/misc/xen-command-line.markdown
> +++ b/docs/misc/xen-command-line.markdown
> @@ -275,7 +275,7 @@ cleared.  This allows a single port to be shared by two subsystems
>   makes sense on its own.
>   
>   ### console\_timestamps
> -> `= none | date | boot`
> +> `= none | date | datems | boot`
>   
>   > Default: `boot`
>   
> @@ -284,6 +284,8 @@ Specify which timestamp format Xen should use for each console line.
>   * `none`: No timestamps
>   * `date`: Date and time information
>       * `[YYYY-MM-DD HH:MM:SS]`
> +* `datems`: Date and time, with milliseconds
> +    * `[YYYY-MM-DD HH:MM:SS.mmm]`
>   * `boot`: Seconds and microseconds since boot
>       * `[SSSSSS.uuuuuu]`
>   
> diff --git a/xen/arch/arm/time.c b/xen/arch/arm/time.c
> index 81e3e28..22e94bb 100644
> --- a/xen/arch/arm/time.c
> +++ b/xen/arch/arm/time.c
> @@ -282,7 +282,7 @@ void domain_set_time_offset(struct domain *d, int32_t time_offset_seconds)
>       /* XXX update guest visible wallclock time */
>   }
>   
> -struct tm wallclock_time(void)
> +struct tm wallclock_time(uint64_t *ns)
>   {

Adding:

    if ( ns )
       *ns = 0;

Makes sense here.

>       return (struct tm) { 0 };
>   }
> diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
> index 4f4de22..1156ccc 100644
> --- a/xen/arch/x86/time.c
> +++ b/xen/arch/x86/time.c
> @@ -1646,15 +1646,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 )

And here.

>           return (struct tm) { 0 };
>   
>       seconds = NOW() + SECONDS(wc_sec) + wc_nsec;
> -    do_div(seconds, 1000000000);
> +    nsec = do_div(seconds, 1000000000);
> +
> +    if ( *ns )

This should be just

    if ( ns )


     -Don Slutz

> +        *ns = nsec;
> +
>       return gmtime(seconds);
>   }
>   
> diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c
> index 60461b9..837e8a8 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.mmm] */
>       TSM_BOOT           /* [SSSSSS.uuuuuu] */
>   };
>   
> @@ -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_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.%03"PRIu64"] ",
> +                     1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
> +                     tm.tm_hour, tm.tm_min, tm.tm_sec, nsec / 1000000);
>           break;
>   
>       case TSM_BOOT:
> diff --git a/xen/include/xen/time.h b/xen/include/xen/time.h
> index 3eb5b63..2703454 100644
> --- a/xen/include/xen/time.h
> +++ b/xen/include/xen/time.h
> @@ -48,7 +48,7 @@ struct tm {
>       int     tm_isdst;       /* daylight saving time */
>   };
>   struct tm gmtime(unsigned long t);
> -struct tm wallclock_time(void);
> +struct tm wallclock_time(uint64_t *ns);
>   
>   #define SYSTEM_TIME_HZ  1000000000ULL
>   #define NOW()           ((s_time_t)get_s_time())

Re: [PATCH v3 5/5] xen/console: Traditional console timestamps including milliseconds

[Andrew Cooper]

On 06/03/2014 23:54, Don Slutz wrote:
> On 03/06/14 14:28, Andrew Cooper wrote:
>>
>>   }
>>   -struct tm wallclock_time(void)
>> +struct tm wallclock_time(uint64_t *ns)
>>   {
>
> Adding:
>
>    if ( ns )
>       *ns = 0;
>
> Makes sense here.
>
>>       return (struct tm) { 0 };
>>   }
>> diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
>> index 4f4de22..1156ccc 100644
>> --- a/xen/arch/x86/time.c
>> +++ b/xen/arch/x86/time.c
>> @@ -1646,15 +1646,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 )
>
> And here.
>
>>           return (struct tm) { 0 };
>>         seconds = NOW() + SECONDS(wc_sec) + wc_nsec;
>> -    do_div(seconds, 1000000000);
>> +    nsec = do_div(seconds, 1000000000);
>> +
>> +    if ( *ns )
>
> This should be just
>
>    if ( ns )

Oops - so it should.

As for the other changes, I am a bit ambivalent.  printk_start_of_line()
is the sole caller of wallclock_time(), which means that tm.tm_day being
0 means *ns will never get looked at.

While it is not exactly a hot codepath, unconditionally clearing it
seems silly, especially as it is not exactly the most likely candidate
to get a new caller in the near future.

~Andrew

Re: [PATCH v3 5/5] xen/console: Traditional console timestamps including milliseconds

[Don Slutz]

On 03/06/14 19:41, Andrew Cooper wrote:
> On 06/03/2014 23:54, Don Slutz wrote:
>> On 03/06/14 14:28, Andrew Cooper wrote:
>>>    }
>>>    -struct tm wallclock_time(void)
>>> +struct tm wallclock_time(uint64_t *ns)
>>>    {
>> Adding:
>>
>>     if ( ns )
>>        *ns = 0;
>>
>> Makes sense here.
>>
>>>        return (struct tm) { 0 };
>>>    }
>>> diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
>>> index 4f4de22..1156ccc 100644
>>> --- a/xen/arch/x86/time.c
>>> +++ b/xen/arch/x86/time.c
>>> @@ -1646,15 +1646,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 )
>> And here.
>>
>>>            return (struct tm) { 0 };
>>>          seconds = NOW() + SECONDS(wc_sec) + wc_nsec;
>>> -    do_div(seconds, 1000000000);
>>> +    nsec = do_div(seconds, 1000000000);
>>> +
>>> +    if ( *ns )
>> This should be just
>>
>>     if ( ns )
> Oops - so it should.
>
> As for the other changes, I am a bit ambivalent.  printk_start_of_line()
> is the sole caller of wallclock_time(), which means that tm.tm_day being
> 0 means *ns will never get looked at.

This is not 100% true.  Last I knew (struct tm) { 0 } is

struct tm {
     int     tm_sec;         /* seconds */ = 0
     int     tm_min;         /* minutes */ <undef>
     int     tm_hour;        /* hours */ <undef>
     int     tm_mday;        /* day of the month */ <undef>
     int     tm_mon;         /* month */ <undef>
     int     tm_year;        /* year */ <undef>
     int     tm_wday;        /* day of the week */ <undef>
     int     tm_yday;        /* day in the year */ <undef>
     int     tm_isdst;       /* daylight saving time */ <undef>
};

But not having looked at the code, and the compilers could have changed 
what this means (i.e. if not provided they are zero in which case this 
should be {}.  { 0, 0, 0, 0 } or { .tm_mday = 0 } is the way I know of 
to say "tm_mday" is zero).

So the test for tm.tm_mday == 0 may just be working because the 
undefined value is zero...

> While it is not exactly a hot codepath, unconditionally clearing it
> seems silly, especially as it is not exactly the most likely candidate
> to get a new caller in the near future.

There is no clear right answer here.  So I have no issue with not doing 
the "extra" work.

    -Don Slutz

> ~Andrew
>

Re: [PATCH v3 5/5] xen/console: Traditional console timestamps including milliseconds

[Ian Campbell]

On Fri, 2014-03-07 at 18:33 -0500, Don Slutz wrote:

> Last I knew (struct tm) { 0 } is
> 
> struct tm {
>      int     tm_sec;         /* seconds */ = 0
>      int     tm_min;         /* minutes */ <undef>
>      int     tm_hour;        /* hours */ <undef>
>      int     tm_mday;        /* day of the month */ <undef>
>      int     tm_mon;         /* month */ <undef>
>      int     tm_year;        /* year */ <undef>
>      int     tm_wday;        /* day of the week */ <undef>
>      int     tm_yday;        /* day in the year */ <undef>
>      int     tm_isdst;       /* daylight saving time */ <undef>
> };
> 

Actually I believe the affect of "struct foo = { 0 }" is to zero
everything (possibly implicitly by causing it to be placed in .bss), but
I don't have my copy of the spec to hand to quote chapter and verse on
that.

Ian.

Re: [PATCH v3 5/5] xen/console: Traditional console timestamps including milliseconds

[Andrew Cooper]

On 11/03/14 10:43, Ian Campbell wrote:
> On Fri, 2014-03-07 at 18:33 -0500, Don Slutz wrote:
>
>> Last I knew (struct tm) { 0 } is
>>
>> struct tm {
>>      int     tm_sec;         /* seconds */ = 0
>>      int     tm_min;         /* minutes */ <undef>
>>      int     tm_hour;        /* hours */ <undef>
>>      int     tm_mday;        /* day of the month */ <undef>
>>      int     tm_mon;         /* month */ <undef>
>>      int     tm_year;        /* year */ <undef>
>>      int     tm_wday;        /* day of the week */ <undef>
>>      int     tm_yday;        /* day in the year */ <undef>
>>      int     tm_isdst;       /* daylight saving time */ <undef>
>> };
>>
> Actually I believe the affect of "struct foo = { 0 }" is to zero
> everything (possibly implicitly by causing it to be placed in .bss), but
> I don't have my copy of the spec to hand to quote chapter and verse on
> that.
>
> Ian.
>

This is a stack entry, so no .bss involved.  Sadly, all the time
functions pass `struct tm`s around by value rather than pointer, and
there is probably easy room for optimisation there.

As for { 0 }, it is indeed special, but even with a copy of the C spec
to hand, I cant see where it is exactly specified.  The disassembly of
wallclock_time() does indeed confirm that the entire structure is zeroed.

~Andrew

Re: [PATCH v3 5/5] xen/console: Traditional console timestamps including milliseconds

[Tim Deegan]

At 11:32 +0000 on 11 Mar (1394533949), Andrew Cooper wrote:
> On 11/03/14 10:43, Ian Campbell wrote:
> > On Fri, 2014-03-07 at 18:33 -0500, Don Slutz wrote:
> >
> >> Last I knew (struct tm) { 0 } is
> >>
> >> struct tm {
> >>      int     tm_sec;         /* seconds */ = 0
> >>      int     tm_min;         /* minutes */ <undef>
> >>      int     tm_hour;        /* hours */ <undef>
> >>      int     tm_mday;        /* day of the month */ <undef>
> >>      int     tm_mon;         /* month */ <undef>
> >>      int     tm_year;        /* year */ <undef>
> >>      int     tm_wday;        /* day of the week */ <undef>
> >>      int     tm_yday;        /* day in the year */ <undef>
> >>      int     tm_isdst;       /* daylight saving time */ <undef>
> >> };
> >>
> > Actually I believe the affect of "struct foo = { 0 }" is to zero
> > everything (possibly implicitly by causing it to be placed in .bss), but
> > I don't have my copy of the spec to hand to quote chapter and verse on
> > that.
> >
> > Ian.
> >
> 
> This is a stack entry, so no .bss involved.  Sadly, all the time
> functions pass `struct tm`s around by value rather than pointer, and
> there is probably easy room for optimisation there.
> 
> As for { 0 }, it is indeed special, but even with a copy of the C spec
> to hand, I cant see where it is exactly specified.  The disassembly of
> wallclock_time() does indeed confirm that the entire structure is zeroed.

Yes, all unspecified fields in a struct initialiser are set to 0.

Tim.

Re: [PATCH v3 5/5] xen/console: Traditional console timestamps including milliseconds

[Jan Beulich]

>>> On 11.03.14 at 12:32, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
> As for { 0 }, it is indeed special, but even with a copy of the C spec
> to hand, I cant see where it is exactly specified.  The disassembly of
> wallclock_time() does indeed confirm that the entire structure is zeroed.

In "Initialization", one of the subclauses says "If there are fewer
initializers in a brace-enclosed list than there are elements or
members of an aggregate, or fewer characters in a string literal
used to initialize an array of known size than there are elements
in the array, the remainder of the aggregate shall be initialized
implicitly the same as objects that have static storage duration."

Jan