Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1308363 > unrolled thread

[PATCH 0/2] printk, Add printk.clock kernel parameter [v2]

Back to article view | Back to linux.kernel

Contents

  [PATCH 0/2] printk, Add printk.clock kernel parameter [v2] Prarit Bhargava <prarit@redhat.com> - 2016-01-13 13:40 +0100
    Re: [PATCH 0/2] printk, Add printk.clock kernel parameter [v2] Thomas Gleixner <tglx@linutronix.de> - 2016-01-13 14:50 +0100
      Re: [PATCH 0/2] printk, Add printk.clock kernel parameter [v2] Prarit Bhargava <prarit@redhat.com> - 2016-01-13 15:40 +0100
        Re: [PATCH 0/2] printk, Add printk.clock kernel parameter [v2] Thomas Gleixner <tglx@linutronix.de> - 2016-01-13 18:40 +0100
          Re: [PATCH 0/2] printk, Add printk.clock kernel parameter [v2] Petr Mladek <pmladek@suse.com> - 2016-01-14 14:00 +0100
            Re: [PATCH 0/2] printk, Add printk.clock kernel parameter [v2] Prarit Bhargava <prarit@redhat.com> - 2016-01-14 15:40 +0100
            Re: [PATCH 0/2] printk, Add printk.clock kernel parameter [v2] Thomas Gleixner <tglx@linutronix.de> - 2016-01-14 15:50 +0100

#1308363 — [PATCH 0/2] printk, Add printk.clock kernel parameter [v2]

The script used in the analysis below:

dmesg_with_human_timestamps () {
    $(type -P dmesg) "$@" | perl -w -e 'use strict;
        my ($uptime) = do { local @ARGV="/proc/uptime";<>}; ($uptime) = ($uptime =~ /^(\d+)\./);
        foreach my $line (<>) {
            printf( ($line=~/^\[\s*(\d+)\.\d+\](.+)/) ? ( "[%s]%s\n", scalar localtime(time - $uptime + $1), $2 ) : $line )
        }'
}

dmesg_with_human_timestamps

----8<----

Over the past years I've seen many reports of bugs that include
time-stamped kernel logs (enabled when CONFIG_PRINTK_TIME=y or
print.time=1 is specified as a kernel parameter) that do not align
with either external time stamped logs or /var/log/messages.

For example,

[root@intel-wildcatpass-06 ~]# date; echo "Hello!" > /dev/kmsg ; date
Thu Dec 17 13:58:31 EST 2015
Thu Dec 17 13:58:31 EST 2015

which displays

[83973.768912] Hello!

on the serial console.

Running a script to convert this to "boot time",

[root@intel-wildcatpass-06 ~]# ./human.sh  | tail -1
[Thu Dec 17 13:59:57 2015] Hello!

which is already off by 1 minute and 26 seconds off after ~24 hours of
uptime.

This occurs because the time stamp is obtained from a call to
local_clock() which (on x86) is a direct call to the hardware.  These
hardware clock reads are not modified by the standard ntp or ptp protocol,
while the other timestamps are, and that results in situations external
time sources are further and further offset from the kernel log
timestamps.

This patchset introduces additional NMI safe timekeeping functions and the
kernel parameter printk.clock=[local|boot|real|tai] allowing a
user to specify an adjusted clock to use with printk timestamps.  The
hardware clock, or the existing functionality, is preserved by default.

[v2]: use NMI safe timekeeping access functions

Cc: John Stultz <john.stultz@linaro.org>
Cc: Xunlei Pang <pang.xunlei@linaro.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Baolin Wang <baolin.wang@linaro.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: Petr Mladek <pmladek@suse.cz>
Cc: Tejun Heo <tj@kernel.org>
Cc: Peter Hurley <peter@hurleysoftware.com>
Cc: Vasily Averin <vvs@virtuozzo.com>
Cc: Joe Perches <joe@perches.com>
Signed-off-by: Prarit Bhargava <prarit@redhat.com>


Prarit Bhargava (2):
  kernel, timekeeping, add ktime_get_[boot|real|tai]_fast_ns functions
  printk, Add printk.clock kernel parameter

 include/linux/timekeeping.h |    3 +++
 kernel/printk/printk.c      |   54 +++++++++++++++++++++++++++++++++++++++++--
 kernel/time/timekeeping.c   |   52 +++++++++++++++++++++++++++++++++--------
 3 files changed, 97 insertions(+), 12 deletions(-)

-- 
1.7.9.3

[toc] | [next] | [standalone]

#1308424

On Wed, 13 Jan 2016, Prarit Bhargava wrote:
> This patchset introduces additional NMI safe timekeeping functions and the
> kernel parameter printk.clock=[local|boot|real|tai] allowing a
> user to specify an adjusted clock to use with printk timestamps.  The
> hardware clock, or the existing functionality, is preserved by default.

You still fail to explain WHY we need a gazillion of different clocks
here.

What's the problem with using the fast monotonic clock instead of local_clock
and be done with it? I really don't see the point why we would need
boot/real/tai and all the extra churn in the fast clock.

Thanks,

	tglx

[toc] | [prev] | [next] | [standalone]

#1308457

On 01/13/2016 08:45 AM, Thomas Gleixner wrote:
> On Wed, 13 Jan 2016, Prarit Bhargava wrote:
>> This patchset introduces additional NMI safe timekeeping functions and the
>> kernel parameter printk.clock=[local|boot|real|tai] allowing a
>> user to specify an adjusted clock to use with printk timestamps.  The
>> hardware clock, or the existing functionality, is preserved by default.
> 
> You still fail to explain WHY we need a gazillion of different clocks
> here.

I've had cases in the past where an earlier warning/failures have resulted in a
much later panics, across several systems.  Trying to synchronize all of these
events with wall clock time is all but impossible after the event has occurred.
 I've seen cases where earlier MCAs lead to panics, earlier I/O warnings have
lead to panics, panics/problems at a specific time, etc.  Attempting to figure
out what happened in the lab or cluster is not trivial without having a
timestamp that can actually be synchronized against a wall clock.

In the case that made me finally submit this, the disks were generating
seemingly random I/O timeout errors which meant at that point I had no logging
to disk (and this assumes the systems are logging to disk because I'm seeing
more and more systems that are not).  I did manage to get dmesg from crash
dumps, however, the problem then became trying to figure out exactly what time
the system started having problems (Was there an external event that lead to the
failures and panics?  Are the early failures across systems at the same time, or
did they occur over several hours?  Did the systems all panic at the same time?
 Was the failure at a specific time after boot and due to a weird timeout?  etc.)

Trying to figure out what actually is happening & debugging becomes much easier
with the above timestamp patch because I can actually tell what time something
happened.

Admittedly, I have not used TAI.  I started by using REAL, and then the BOOT
clock to see if this was some sort of strange 10-day timeout on the system.  I
only included TAI option for completeness.

> 
> What's the problem with using the fast monotonic clock instead of local_clock
> and be done with it? I really don't see the point why we would need
> boot/real/tai and all the extra churn in the fast clock.

AFAICT the local_clock() (on x86 at least) is accessed without accessing a lock
and is just a tsc read.  I assumed that local_clock() fast and lockless access
was the "best" method for obtaining a time stamp.  I would only suggest using
the other clocks on systems that are "known stable", or running kernels that are
considered to have stable timekeeping code.

P.

> 

[toc] | [prev] | [next] | [standalone]

#1308671

On Wed, 13 Jan 2016, Prarit Bhargava wrote:
> On 01/13/2016 08:45 AM, Thomas Gleixner wrote:
> > On Wed, 13 Jan 2016, Prarit Bhargava wrote:
> >> This patchset introduces additional NMI safe timekeeping functions and the
> >> kernel parameter printk.clock=[local|boot|real|tai] allowing a
> >> user to specify an adjusted clock to use with printk timestamps.  The
> >> hardware clock, or the existing functionality, is preserved by default.
> > 
> > You still fail to explain WHY we need a gazillion of different clocks
> > here.
> 
> I've had cases in the past where an earlier warning/failures have resulted in a
> much later panics, across several systems.  Trying to synchronize all of these
> events with wall clock time is all but impossible after the event has occurred.
>  I've seen cases where earlier MCAs lead to panics, earlier I/O warnings have
> lead to panics, panics/problems at a specific time, etc.  Attempting to figure
> out what happened in the lab or cluster is not trivial without having a
> timestamp that can actually be synchronized against a wall clock.
> 
> In the case that made me finally submit this, the disks were generating
> seemingly random I/O timeout errors which meant at that point I had no logging
> to disk (and this assumes the systems are logging to disk because I'm seeing
> more and more systems that are not).  I did manage to get dmesg from crash
> dumps, however, the problem then became trying to figure out exactly what time
> the system started having problems (Was there an external event that lead to the
> failures and panics?  Are the early failures across systems at the same time, or
> did they occur over several hours?  Did the systems all panic at the same time?
>  Was the failure at a specific time after boot and due to a weird timeout?  etc.)
> 
> Trying to figure out what actually is happening & debugging becomes much easier
> with the above timestamp patch because I can actually tell what time something
> happened.
> 
> Admittedly, I have not used TAI.  I started by using REAL, and then the BOOT
> clock to see if this was some sort of strange 10-day timeout on the system.  I
> only included TAI option for completeness.

So I really don't see a reason why we would need TAI for that. Just because we
can is not one.

BOOT is questionable as well simply because the boot offset only changes when
the system suspends/resumes. So we rather note that time delta in dmesg than
having a gazillion of command line options.

That leaves REAL as a possible useful option. Though the points where the MONO
to REAL offset changes are rather limited as well (Initial RTC readout,
do_settimeofday(), adjtimex(), leap seconds, suspend/resume).

> > What's the problem with using the fast monotonic clock instead of local_clock
> > and be done with it? I really don't see the point why we would need
> > boot/real/tai and all the extra churn in the fast clock.
> 
> AFAICT the local_clock() (on x86 at least) is accessed without accessing a lock
> and is just a tsc read.  I assumed that local_clock() fast and lockless access
> was the "best" method for obtaining a time stamp.

printk() is hardly a hotpath function and local_clock() is not much faster
than ktime_get_mono_fast_ns(). It's lockless as well otherwise it would not be
NMI safe.

So what's the point? 

> I would only suggest using the other clocks on systems that are "known
> stable", or running kernels that are considered to have stable timekeeping
> code.

I neither run production stuff on systems which are known to be unstable nor
on a kernel which does not have a stable timekeeping code.

Sorry, but your argumentation does not make any sense.

You can solve the whole business by changing the timestamp in printk_log to

   u64	    mono;
   u64	    offset_real;

and have a function which does:

u64 ktime_get_log_ts(u64 *offset_real)
{
	*offset_real = tk_core.timekeeper.offs_real;

	if (timekeeping_active)
		return ktime_get_mono_fast_ns();
	else
		return local_clock();
}

That uses extra 8 bytes of data per log buffer entry, but that's really a non
issue. That already gives you the data for crash analysis. If you want to be
able to have the clock REAL time stamps in console/dmesg/syslog then you
simply can make printk_time an integer and act depending on the value:

     printk_time=0  timestamps off
     printk_time=1  timestamps clock MONO (default and backwards compatible)
     printk_time=2  timestamps clock REAL
     
That's minimal intrusive and does the job without the need of a gazillion of
command line options and new functions which are just pointless bloat.

Note, that on 32bit systems accessing tk_core.timekeeper.offs_real is racy
vs. a concurrent update, but with your proposed solution it's not any
different.

Thanks,

	tglx

[toc] | [prev] | [next] | [standalone]

#1309252

On Wed 2016-01-13 18:28:50, Thomas Gleixner wrote:
> You can solve the whole business by changing the timestamp in printk_log to
> 
>    u64	    mono;
>    u64	    offset_real;

This is not so easy because the structure is proceed by userspace tool,
e.g. crash, see log_buf_kexec_setup(). We would need to update all
the tools as well.


> and have a function which does:
> 
> u64 ktime_get_log_ts(u64 *offset_real)
> {
> 	*offset_real = tk_core.timekeeper.offs_real;
> 
> 	if (timekeeping_active)
> 		return ktime_get_mono_fast_ns();
> 	else
> 		return local_clock();
> }

A solution would be to apply the offset_real immediately. I wonder if
any tool expects the messages to be sorted by a monotonic clock. In
fact, it might be useful to see that some messages are disordered
against the real time, e.g. because of the leaf second.

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1309333

On 01/14/2016 07:52 AM, Petr Mladek wrote:
> On Wed 2016-01-13 18:28:50, Thomas Gleixner wrote:
>> You can solve the whole business by changing the timestamp in printk_log to
>>
>>    u64	    mono;
>>    u64	    offset_real;
> 
> This is not so easy because the structure is proceed by userspace tool,
> e.g. crash, see log_buf_kexec_setup(). We would need to update all
> the tools as well.
> 
> 
>> and have a function which does:
>>
>> u64 ktime_get_log_ts(u64 *offset_real)
>> {
>> 	*offset_real = tk_core.timekeeper.offs_real;
>>
>> 	if (timekeeping_active)
>> 		return ktime_get_mono_fast_ns();
>> 	else
>> 		return local_clock();
>> }
> 
> A solution would be to apply the offset_real immediately. I wonder if
> any tool expects the messages to be sorted by a monotonic clock. In

/var/log/messages from systemd will have to be fixed, but that's something that
was brought up previously (and IMO should be trivial based on the value in
/sys/modules/printk/parameters/time).

> fact, it might be useful to see that some messages are disordered
> against the real time, e.g. because of the leaf second.

I kicked a leap seconds during my testing (I have been running tests from
/tools/tests/selftests/timers) and didn't see anything strange with both a stock
leap-a-day.c and a modified leap-a-day.c which only does leap insertions.

P.

> 
> Best Regards,
> Petr
> 

[toc] | [prev] | [next] | [standalone]

#1309346

On Thu, 14 Jan 2016, Petr Mladek wrote:
> On Wed 2016-01-13 18:28:50, Thomas Gleixner wrote:
> > You can solve the whole business by changing the timestamp in printk_log to
> > 
> >    u64	    mono;
> >    u64	    offset_real;
> 
> This is not so easy because the structure is proceed by userspace tool,
> e.g. crash, see log_buf_kexec_setup(). We would need to update all
> the tools as well.

Fair enough.
 
> > and have a function which does:
> > 
> > u64 ktime_get_log_ts(u64 *offset_real)
> > {
> > 	*offset_real = tk_core.timekeeper.offs_real;
> > 
> > 	if (timekeeping_active)
> > 		return ktime_get_mono_fast_ns();
> > 	else
> > 		return local_clock();
> > }
> 
> A solution would be to apply the offset_real immediately. I wonder if
> any tool expects the messages to be sorted by a monotonic clock. In
> fact, it might be useful to see that some messages are disordered
> against the real time, e.g. because of the leaf second.

Not only leap seconds, it's also settimeofday and NTP might make the wall time
jump under certain conditions.

Thanks,

	tglx

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web