From mboxrd@z Thu Jan 1 00:00:00 1970 From: Don Slutz Subject: Re: [PATCH 2/2] [RFC] xen/console: Provide timestamps as an offset since boot. Date: Thu, 27 Feb 2014 13:57:39 -0500 Message-ID: <530F8AA3.5050906@terremark.com> References: <1393509787-13497-1-git-send-email-andrew.cooper3@citrix.com> <1393509787-13497-2-git-send-email-andrew.cooper3@citrix.com> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii"; Format="flowed" Content-Transfer-Encoding: 7bit Return-path: In-Reply-To: <1393509787-13497-2-git-send-email-andrew.cooper3@citrix.com> List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Sender: xen-devel-bounces@lists.xen.org Errors-To: xen-devel-bounces@lists.xen.org To: Andrew Cooper , Xen-devel Cc: Keir Fraser , Tim Deegan , Jan Beulich List-Id: xen-devel@lists.xenproject.org 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); > } >