Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1695673 > unrolled thread
| Started by | Prarit Bhargava <prarit@redhat.com> |
|---|---|
| First post | 2017-07-25 14:20 +0200 |
| Last post | 2017-07-31 19:20 +0200 |
| Articles | 9 — 6 participants |
Back to article view | Back to linux.kernel
[PATCH 0/2] printk: allow different timestamps for printk.time Prarit Bhargava <prarit@redhat.com> - 2017-07-25 14:20 +0200
[PATCH 2/2] printk: Add boottime and real timestamps Prarit Bhargava <prarit@redhat.com> - 2017-07-25 14:20 +0200
Re: [PATCH 2/2] printk: Add boottime and real timestamps Peter Zijlstra <peterz@infradead.org> - 2017-07-25 15:10 +0200
Re: [PATCH 2/2] printk: Add boottime and real timestamps Mark Salyzyn <salyzyn@android.com> - 2017-07-26 00:40 +0200
Re: [PATCH 2/2] printk: Add boottime and real timestamps Prarit Bhargava <prarit@redhat.com> - 2017-07-28 17:10 +0200
Re: [PATCH 2/2] printk: Add boottime and real timestamps Thomas Gleixner <tglx@linutronix.de> - 2017-07-28 18:30 +0200
Re: [PATCH 2/2] printk: Add boottime and real timestamps kbuild test robot <lkp@intel.com> - 2017-07-27 05:10 +0200
Re: [PATCH 1/2] printk: Make CONFIG_PRINTK_TIME an int "Luis R. Rodriguez" <mcgrof@kernel.org> - 2017-07-25 15:00 +0200
Re: [PATCH 1/2] printk: Make CONFIG_PRINTK_TIME an int Prarit Bhargava <prarit@redhat.com> - 2017-07-31 19:20 +0200
| From | Prarit Bhargava <prarit@redhat.com> |
|---|---|
| Date | 2017-07-25 14:20 +0200 |
| Subject | [PATCH 0/2] printk: allow different timestamps for printk.time |
| Message-ID | <u76YH-2Fx-15@gated-at.bofh.it> |
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. This also makes determining the time of a failure difficult in cases where /var/log/messages is unavailable. For example, [root@intel-wildcatpass-06 ~]# date; echo "Hello!" > /dev/kmsg ; date Thu Jul 20 11:38:22 EST 2017 Thu Jul 20 11:38:22 EST 2017 which displays [83973.768912] Hello! on the serial console. Running a script to convert this to the stamped time, [root@intel-wildcatpass-06 ~]# ./human.sh | tail -1 [Thu July 17 11:39:45 2017] Hello! which is already off by 1 minute and 23 seconds off after ~24 hours of uptime. This occurs because the printk 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 The other timestamps are and that results in situations external time sources are further and further offset from the kernel log timestamps. Implement printk.time settings to allow a user to specify the monotonic or real clocks. The default is the local clock (hardware clock). Real clock & 32-bit systems: Selecting the real clock printk timestamp may lead to unlikely situations where a timestamp is wrong because the real time offset is read without the protection of a sequence lock in the call to ktime_get_log_ts() in printk_get_ts(). Signed-off-by: Prarit Bhargava <prarit@redhat.com> Cc: Mark Salyzyn <salyzyn@android.com> Cc: Jonathan Corbet <corbet@lwn.net> Cc: Petr Mladek <pmladek@suse.com> Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: John Stultz <john.stultz@linaro.org> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Stephen Boyd <sboyd@codeaurora.org> Cc: Andrew Morton <akpm@linux-foundation.org> Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org> Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> Cc: Christoffer Dall <cdall@linaro.org> Cc: Deepa Dinamani <deepa.kernel@gmail.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Joel Fernandes <joelaf@google.com> Cc: Kees Cook <keescook@chromium.org> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Geert Uytterhoeven <geert+renesas@glider.be> Cc: "Luis R. Rodriguez" <mcgrof@kernel.org> Cc: Nicholas Piggin <npiggin@gmail.com> Cc: "Jason A. Donenfeld" <Jason@zx2c4.com> Cc: Olof Johansson <olof@lixom.net> Cc: "Theodore Ts'o" <tytso@mit.edu> Cc: Josh Poimboeuf <jpoimboe@redhat.com> Cc: linux-doc@vger.kernel.org Prarit Bhargava (2): printk: Make CONFIG_PRINTK_TIME an int printk: Add boottime and real timestamps Documentation/admin-guide/kernel-parameters.txt | 6 +- arch/arm/configs/aspeed_g4_defconfig | 2 +- arch/arm/configs/aspeed_g5_defconfig | 2 +- arch/arm/configs/axm55xx_defconfig | 2 +- arch/arm/configs/bcm2835_defconfig | 2 +- arch/arm/configs/colibri_pxa270_defconfig | 2 +- arch/arm/configs/colibri_pxa300_defconfig | 2 +- arch/arm/configs/dove_defconfig | 2 +- arch/arm/configs/efm32_defconfig | 2 +- arch/arm/configs/exynos_defconfig | 2 +- arch/arm/configs/ezx_defconfig | 2 +- arch/arm/configs/h5000_defconfig | 2 +- arch/arm/configs/hisi_defconfig | 2 +- arch/arm/configs/imote2_defconfig | 2 +- arch/arm/configs/imx_v6_v7_defconfig | 2 +- arch/arm/configs/keystone_defconfig | 2 +- arch/arm/configs/lpc18xx_defconfig | 2 +- arch/arm/configs/magician_defconfig | 2 +- arch/arm/configs/mmp2_defconfig | 2 +- arch/arm/configs/moxart_defconfig | 2 +- arch/arm/configs/mps2_defconfig | 2 +- arch/arm/configs/multi_v7_defconfig | 2 +- arch/arm/configs/mvebu_v7_defconfig | 2 +- arch/arm/configs/mxs_defconfig | 2 +- arch/arm/configs/omap2plus_defconfig | 2 +- arch/arm/configs/pxa168_defconfig | 2 +- arch/arm/configs/pxa3xx_defconfig | 2 +- arch/arm/configs/pxa910_defconfig | 2 +- arch/arm/configs/pxa_defconfig | 2 +- arch/arm/configs/qcom_defconfig | 2 +- arch/arm/configs/raumfeld_defconfig | 2 +- arch/arm/configs/shmobile_defconfig | 2 +- arch/arm/configs/socfpga_defconfig | 2 +- arch/arm/configs/stm32_defconfig | 2 +- arch/arm/configs/sunxi_defconfig | 2 +- arch/arm/configs/tango4_defconfig | 2 +- arch/arm/configs/tegra_defconfig | 2 +- arch/arm/configs/u300_defconfig | 2 +- arch/arm/configs/u8500_defconfig | 2 +- arch/arm/configs/vt8500_v6_v7_defconfig | 2 +- arch/arm/configs/xcep_defconfig | 2 +- arch/arm/configs/zx_defconfig | 2 +- arch/arm64/configs/defconfig | 2 +- arch/m68k/configs/amcore_defconfig | 2 +- arch/mips/configs/ath25_defconfig | 2 +- arch/mips/configs/bcm47xx_defconfig | 2 +- arch/mips/configs/bmips_be_defconfig | 2 +- arch/mips/configs/bmips_stb_defconfig | 2 +- arch/mips/configs/ci20_defconfig | 2 +- arch/mips/configs/generic_defconfig | 2 +- arch/mips/configs/lemote2f_defconfig | 2 +- arch/mips/configs/loongson3_defconfig | 2 +- arch/mips/configs/nlm_xlp_defconfig | 2 +- arch/mips/configs/nlm_xlr_defconfig | 2 +- arch/mips/configs/pistachio_defconfig | 2 +- arch/mips/configs/qi_lb60_defconfig | 2 +- arch/mips/configs/rt305x_defconfig | 2 +- arch/mips/configs/xway_defconfig | 2 +- arch/parisc/configs/generic-64bit_defconfig | 2 +- arch/powerpc/configs/40x/virtex_defconfig | 2 +- arch/powerpc/configs/44x/fsp2_defconfig | 2 +- arch/powerpc/configs/44x/virtex5_defconfig | 2 +- arch/powerpc/configs/44x/warp_defconfig | 2 +- arch/powerpc/configs/52xx/cm5200_defconfig | 2 +- arch/powerpc/configs/52xx/lite5200b_defconfig | 2 +- arch/powerpc/configs/52xx/motionpro_defconfig | 2 +- arch/powerpc/configs/52xx/tqm5200_defconfig | 2 +- arch/powerpc/configs/gamecube_defconfig | 2 +- arch/powerpc/configs/mpc5200_defconfig | 2 +- arch/powerpc/configs/pasemi_defconfig | 2 +- arch/powerpc/configs/wii_defconfig | 2 +- arch/s390/configs/default_defconfig | 2 +- arch/s390/configs/gcov_defconfig | 2 +- arch/s390/configs/performance_defconfig | 2 +- arch/s390/configs/zfcpdump_defconfig | 2 +- arch/sh/configs/edosk7760_defconfig | 2 +- arch/sh/configs/sdk7786_defconfig | 2 +- arch/sh/configs/se7722_defconfig | 2 +- arch/sh/configs/sh7785lcr_32bit_defconfig | 2 +- arch/sh/configs/urquell_defconfig | 2 +- arch/sparc/configs/sparc64_defconfig | 2 +- arch/x86/configs/i386_defconfig | 2 +- arch/x86/configs/x86_64_defconfig | 2 +- arch/xtensa/configs/audio_kc705_defconfig | 2 +- arch/xtensa/configs/cadence_csp_defconfig | 2 +- arch/xtensa/configs/generic_kc705_defconfig | 2 +- arch/xtensa/configs/nommu_kc705_defconfig | 2 +- arch/xtensa/configs/smp_lx200_defconfig | 2 +- include/linux/timekeeping.h | 1 + kernel/printk/printk.c | 95 +++++++++++++++++++++- kernel/time/timekeeping.c | 14 ++++ lib/Kconfig.debug | 8 +- .../selftests/rcutorture/configs/lock/CFcommon | 2 +- .../selftests/rcutorture/configs/rcu/CFcommon | 2 +- .../selftests/rcutorture/configs/rcuperf/CFcommon | 2 +- 95 files changed, 206 insertions(+), 98 deletions(-) -- 1.8.5.5
[toc] | [next] | [standalone]
| From | Prarit Bhargava <prarit@redhat.com> |
|---|---|
| Date | 2017-07-25 14:20 +0200 |
| Subject | [PATCH 2/2] printk: Add boottime and real timestamps |
| Message-ID | <u76YI-2Fx-35@gated-at.bofh.it> |
| In reply to | #1695673 |
printk.time=1/CONFIG_PRINTK_TIME=Y timestamps printks with an unmodified
hardware clock timestamp. This clock loses time each day making it
difficult to determine when an issue has occurred in the kernel log.
Modify printk.time to output local, monotonic, or a real timestamp.
Modify the output of /sys/module/printk/parameters/time to output the type
of clock so userspace programs can interpret the timestamp.
Real clock & 32-bit systems: Selecting the real clock printk timestamp
may lead to unlikely situations where a timestamp is wrong because the
real time offset is read without the protection of a sequence lock in the
call to ktime_get_log_ts() in printk_get_ts().
Signed-off-by: Prarit Bhargava <prarit@redhat.com>
Cc: Mark Salyzyn <salyzyn@android.com>
Cc: Jonathan Corbet <corbet@lwn.net>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Stephen Boyd <sboyd@codeaurora.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Cc: Christoffer Dall <cdall@linaro.org>
Cc: Deepa Dinamani <deepa.kernel@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Joel Fernandes <joelaf@google.com>
Cc: Kees Cook <keescook@chromium.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Geert Uytterhoeven <geert+renesas@glider.be>
Cc: "Luis R. Rodriguez" <mcgrof@kernel.org>
Cc: Nicholas Piggin <npiggin@gmail.com>
Cc: "Jason A. Donenfeld" <Jason@zx2c4.com>
Cc: Olof Johansson <olof@lixom.net>
Cc: "Theodore Ts'o" <tytso@mit.edu>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: linux-doc@vger.kernel.org
---
Documentation/admin-guide/kernel-parameters.txt | 6 +-
include/linux/timekeeping.h | 1 +
kernel/printk/printk.c | 77 +++++++++++++++++++++----
kernel/time/timekeeping.c | 14 +++++
lib/Kconfig.debug | 7 ++-
5 files changed, 89 insertions(+), 16 deletions(-)
diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index c3b14abf9da4..c03240d057b1 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3188,8 +3188,10 @@
ratelimit - ratelimit the logging
Default: ratelimit
- printk.time= Show timing data prefixed to each printk message line
- Format: <string> (1/Y/y=enable, 0/N/n=disable)
+ printk.time= Show timestamp prefixed to each printk message line
+ Format: <string>
+ (0/N/n = disable, 1/Y/y = local/unadjusted HW,
+ 2 = monotonic, 3 = real)
processor.max_cstate= [HW,ACPI]
Limit processor to maximum C-state
diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h
index ddc229ff6d1e..adb84af42deb 100644
--- a/include/linux/timekeeping.h
+++ b/include/linux/timekeeping.h
@@ -239,6 +239,7 @@ static inline u64 ktime_get_raw_ns(void)
extern u64 ktime_get_mono_fast_ns(void);
extern u64 ktime_get_raw_fast_ns(void);
extern u64 ktime_get_boot_fast_ns(void);
+extern u64 ktime_get_log_ts(u64 *offset_real);
/*
* Timespec interfaces utilizing the ktime based ones
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 26cf6cadd267..35536369a56d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -576,6 +576,8 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
}
+static u64 printk_get_ts(void);
+
/* insert record into the buffer, discard old ones, update heads */
static int log_store(int facility, int level,
enum log_flags flags, u64 ts_nsec,
@@ -624,7 +626,7 @@ static int log_store(int facility, int level,
if (ts_nsec > 0)
msg->ts_nsec = ts_nsec;
else
- msg->ts_nsec = local_clock();
+ msg->ts_nsec = printk_get_ts();
memset(log_dict(msg) + dict_len, 0, pad_len);
msg->len = size;
@@ -1203,26 +1205,60 @@ static inline void boot_delay_msec(int level)
#endif
static int printk_time = CONFIG_PRINTK_TIME;
+static int printk_time_setting; /* initial setting */
+/*
+ * Real clock & 32-bit systems: Selecting the real clock printk timestamp may
+ * lead to unlikely situations where a timestamp is wrong because the real time
+ * offset is read without the protection of a sequence lock in the call to
+ * ktime_get_log_ts() in printk_get_ts() below.
+ */
static int printk_time_set(const char *val, const struct kernel_param *kp)
{
char *param = strstrip((char *)val);
+ int _printk_time;
if (strlen(param) != 1)
return -EINVAL;
- if (!strncmp("0", param, 1) || !strncmp("n", param, 1) ||
- !strncmp("N", param, 1)) {
- printk_time = 0;
- } else if (!strncmp("1", param, 1) || !strncmp("y", param, 1) ||
- !strncmp("Y", param, 1)) {
- printk_time = 1;
- } else {
- pr_warn("printk: invalid timestamp value %s.\n", param);
+ switch (param[0]) {
+ case '0':
+ case 'n':
+ case 'N':
+ _printk_time = 0; /* none/disabled */
+ break;
+ case '1':
+ case 'y':
+ case 'Y':
+ _printk_time = 1; /* local unadjusted HW clock */
+ break;
+ case '2':
+ _printk_time = 2; /* boot time */
+ break;
+ case '3':
+ _printk_time = 3; /* real time */
+ break;
+ default:
+ pr_warn("printk: invalid timestamp value\n");
+ return -EINVAL;
+ }
+
+ /*
+ * Only allow enabling and disabling of the current printk_time
+ * setting. Changing it from one setting to another confuses
+ * userspace.
+ */
+ if (printk_time_setting == 0) {
+ printk_time_setting = _printk_time;
+ } else if ((printk_time_setting != _printk_time) &&
+ (_printk_time != 0)) {
+ pr_warn("printk: timestamp can only be set to 0 or %d ",
+ printk_time_setting);
return -EINVAL;
}
- pr_info("printk: timestamp set to %d.\n", printk_time);
+ printk_time = _printk_time;
+ pr_info("printk: timestamp set to %d.", printk_time);
return 0;
}
@@ -1237,6 +1273,21 @@ static int printk_time_get(char *buffer, const struct kernel_param *kp)
};
module_param_cb(time, &printk_time_ops, NULL, S_IRUGO | S_IWUSR);
+static u64 printk_get_ts(void)
+{
+ u64 mono, offset_real;
+
+ if (printk_time <= 1)
+ return local_clock();
+
+ mono = ktime_get_log_ts(&offset_real);
+
+ if (printk_time == 2)
+ return mono;
+
+ return mono + offset_real;
+}
+
static size_t print_time(u64 ts, char *buf)
{
unsigned long rem_nsec;
@@ -1675,7 +1726,7 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char *
cont.facility = facility;
cont.level = level;
cont.owner = current;
- cont.ts_nsec = local_clock();
+ cont.ts_nsec = printk_get_ts();
cont.flags = flags;
}
@@ -2691,6 +2742,10 @@ static int __init printk_late_init(void)
struct console *con;
int ret;
+ /* initialize printk_time settings */
+ if (printk_time_setting == 0)
+ printk_time_setting = printk_time;
+
for_each_console(con) {
if (!keep_bootcon && con->flags & CON_BOOT) {
/*
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index cedafa008de5..96f06a16c51f 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -25,6 +25,7 @@
#include <linux/stop_machine.h>
#include <linux/pvclock_gtod.h>
#include <linux/compiler.h>
+#include <linux/sched/clock.h>
#include "tick-internal.h"
#include "ntp_internal.h"
@@ -45,6 +46,7 @@
static DEFINE_RAW_SPINLOCK(timekeeper_lock);
static struct timekeeper shadow_timekeeper;
+static int timekeeping_active;
/**
* struct tk_fast - NMI safe timekeeper
@@ -477,6 +479,16 @@ u64 notrace ktime_get_boot_fast_ns(void)
}
EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
+u64 ktime_get_log_ts(u64 *offset_real)
+{
+ *offset_real = ktime_to_ns(tk_core.timekeeper.offs_real);
+
+ if (timekeeping_active)
+ return ktime_get_mono_fast_ns();
+ else
+ return local_clock();
+}
+
/* Suspend-time cycles value for halted fast timekeeper. */
static u64 cycles_at_suspend;
@@ -1530,6 +1542,8 @@ void __init timekeeping_init(void)
write_seqcount_end(&tk_core.seq);
raw_spin_unlock_irqrestore(&timekeeper_lock, flags);
+
+ timekeeping_active = 1;
}
/* time in seconds when suspend began for persistent clock */
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 5b1662ec546f..6cd38a25f8ea 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -1,8 +1,8 @@
menu "printk and dmesg options"
config PRINTK_TIME
- int "Show timing information on printks (0-1)"
- range 0 1
+ int "Show timing information on printks (0-3)"
+ range 0 3
default "0"
depends on PRINTK
help
@@ -13,7 +13,8 @@ config PRINTK_TIME
The timestamp is always recorded internally, and exported
to /dev/kmsg. This flag just specifies if the timestamp should
be included, not that the timestamp is recorded. 0 disables the
- timestamp and 1 uses the local clock.
+ timestamp and 1 uses the local clock, 2 uses the monotonic clock, and
+ 3 uses real clock.
The behavior is also controlled by the kernel command line
parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst
--
1.8.5.5
[toc] | [prev] | [next] | [standalone]
| From | Peter Zijlstra <peterz@infradead.org> |
|---|---|
| Date | 2017-07-25 15:10 +0200 |
| Subject | Re: [PATCH 2/2] printk: Add boottime and real timestamps |
| Message-ID | <u77L4-3dw-7@gated-at.bofh.it> |
| In reply to | #1695678 |
On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote: > diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug > index 5b1662ec546f..6cd38a25f8ea 100644 > --- a/lib/Kconfig.debug > +++ b/lib/Kconfig.debug > @@ -1,8 +1,8 @@ > menu "printk and dmesg options" > > config PRINTK_TIME > - int "Show timing information on printks (0-1)" > - range 0 1 > + int "Show timing information on printks (0-3)" > + range 0 3 > default "0" > depends on PRINTK > help > @@ -13,7 +13,8 @@ config PRINTK_TIME > The timestamp is always recorded internally, and exported > to /dev/kmsg. This flag just specifies if the timestamp should > be included, not that the timestamp is recorded. 0 disables the > - timestamp and 1 uses the local clock. > + timestamp and 1 uses the local clock, 2 uses the monotonic clock, and > + 3 uses real clock. > > The behavior is also controlled by the kernel command line > parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst choice prompt "printk default clock" default PRIMTK_TIME_DISABLE help goes here config PRINTK_TIME_DISABLE bool "Disabled" help goes here config PRINTK_TIME_LOCAL bool "local clock" help goes here config PRINTK_TIME_MONO bool "CLOCK_MONOTONIC" help goes here config PRINTK_TIME_REAL bool "CLOCK_REALTIME" help goes here endchoice config PRINTK_TIME int default 0 if PRINTK_TIME_DISABLE default 1 if PRINTK_TIME_LOCAL default 2 if PRINTK_TIME_MONO default 3 if PRINTK_TIME_REAL Although I must strongly discourage using REALTIME, DST will make untangling your logs an absolute nightmare. I would simply not provide it.
[toc] | [prev] | [next] | [standalone]
| From | Mark Salyzyn <salyzyn@android.com> |
|---|---|
| Date | 2017-07-26 00:40 +0200 |
| Subject | Re: [PATCH 2/2] printk: Add boottime and real timestamps |
| Message-ID | <u7gEG-op-27@gated-at.bofh.it> |
| In reply to | #1695715 |
On 07/25/2017 06:00 AM, Peter Zijlstra wrote: > On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote: >> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug >> index 5b1662ec546f..6cd38a25f8ea 100644 >> --- a/lib/Kconfig.debug >> +++ b/lib/Kconfig.debug >> @@ -1,8 +1,8 @@ >> menu "printk and dmesg options" >> >> config PRINTK_TIME >> - int "Show timing information on printks (0-1)" >> - range 0 1 >> + int "Show timing information on printks (0-3)" >> + range 0 3 >> default "0" >> depends on PRINTK >> help >> @@ -13,7 +13,8 @@ config PRINTK_TIME >> The timestamp is always recorded internally, and exported >> to /dev/kmsg. This flag just specifies if the timestamp should >> be included, not that the timestamp is recorded. 0 disables the >> - timestamp and 1 uses the local clock. >> + timestamp and 1 uses the local clock, 2 uses the monotonic clock, and >> + 3 uses real clock. >> >> The behavior is also controlled by the kernel command line >> parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst > > choice > prompt "printk default clock" > default PRIMTK_TIME_DISABLE > help > goes here > > config PRINTK_TIME_DISABLE > bool "Disabled" > help > goes here > > config PRINTK_TIME_LOCAL > bool "local clock" > help > goes here > > config PRINTK_TIME_MONO > bool "CLOCK_MONOTONIC" > help > goes here > > config PRINTK_TIME_REAL > bool "CLOCK_REALTIME" > help > goes here > > endchoice > > config PRINTK_TIME > int > default 0 if PRINTK_TIME_DISABLE > default 1 if PRINTK_TIME_LOCAL > default 2 if PRINTK_TIME_MONO > default 3 if PRINTK_TIME_REAL > > > Although I must strongly discourage using REALTIME, DST will make > untangling your logs an absolute nightmare. I would simply not provide > it. I agree with using select, ensures only valid values are landed. It does mean that CONFIG_PRINTK_TIME in-effect gets deprecated. REALTIME is always UTC in the kernel. What about BOOTTIME? -- Mark
[toc] | [prev] | [next] | [standalone]
| From | Prarit Bhargava <prarit@redhat.com> |
|---|---|
| Date | 2017-07-28 17:10 +0200 |
| Subject | Re: [PATCH 2/2] printk: Add boottime and real timestamps |
| Message-ID | <u8f3P-5oC-1@gated-at.bofh.it> |
| In reply to | #1695715 |
On 07/25/2017 09:00 AM, Peter Zijlstra wrote: > On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote: >> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug >> index 5b1662ec546f..6cd38a25f8ea 100644 >> --- a/lib/Kconfig.debug >> +++ b/lib/Kconfig.debug >> @@ -1,8 +1,8 @@ >> menu "printk and dmesg options" >> >> config PRINTK_TIME >> - int "Show timing information on printks (0-1)" >> - range 0 1 >> + int "Show timing information on printks (0-3)" >> + range 0 3 >> default "0" >> depends on PRINTK >> help >> @@ -13,7 +13,8 @@ config PRINTK_TIME >> The timestamp is always recorded internally, and exported >> to /dev/kmsg. This flag just specifies if the timestamp should >> be included, not that the timestamp is recorded. 0 disables the >> - timestamp and 1 uses the local clock. >> + timestamp and 1 uses the local clock, 2 uses the monotonic clock, and >> + 3 uses real clock. >> >> The behavior is also controlled by the kernel command line >> parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst > > > choice > prompt "printk default clock" > default PRIMTK_TIME_DISABLE > help > goes here > > config PRINTK_TIME_DISABLE > bool "Disabled" > help > goes here > > config PRINTK_TIME_LOCAL > bool "local clock" > help > goes here > > config PRINTK_TIME_MONO > bool "CLOCK_MONOTONIC" > help > goes here > > config PRINTK_TIME_REAL > bool "CLOCK_REALTIME" > help > goes here > > endchoice > > config PRINTK_TIME > int > default 0 if PRINTK_TIME_DISABLE > default 1 if PRINTK_TIME_LOCAL > default 2 if PRINTK_TIME_MONO > default 3 if PRINTK_TIME_REAL > > Thanks for the above change. I can see that makes the code simpler. > Although I must strongly discourage using REALTIME, DST will make > untangling your logs an absolute nightmare. I would simply not provide > it. I understand your concern, however, I've been in situations where REALTIME stamping has pointed me in the direction of where a bug was. Even with the complicated logs I think it is worthwhile. P.
[toc] | [prev] | [next] | [standalone]
| From | Thomas Gleixner <tglx@linutronix.de> |
|---|---|
| Date | 2017-07-28 18:30 +0200 |
| Subject | Re: [PATCH 2/2] printk: Add boottime and real timestamps |
| Message-ID | <u8gjf-65z-5@gated-at.bofh.it> |
| In reply to | #1698871 |
On Fri, 28 Jul 2017, Prarit Bhargava wrote: > On 07/25/2017 09:00 AM, Peter Zijlstra wrote: > Thanks for the above change. I can see that makes the code simpler. > > > Although I must strongly discourage using REALTIME, DST will make > > untangling your logs an absolute nightmare. I would simply not provide > > it. > > I understand your concern, however, I've been in situations where REALTIME > stamping has pointed me in the direction of where a bug was. Even with the > complicated logs I think it is worthwhile. As Mark pointed out. ktime_get_real() and the fast variant return UTC. The timezone mess plus the DST nonsense are done in user space. Thanks, tglx
[toc] | [prev] | [next] | [standalone]
| From | kbuild test robot <lkp@intel.com> |
|---|---|
| Date | 2017-07-27 05:10 +0200 |
| Subject | Re: [PATCH 2/2] printk: Add boottime and real timestamps |
| Message-ID | <u7Hlv-GZ-7@gated-at.bofh.it> |
| In reply to | #1695678 |
[Multipart message — attachments visible in raw view] — view raw
Hi Prarit,
[auto build test ERROR on linus/master]
[also build test ERROR on v4.13-rc2]
[cannot apply to next-20170726]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]
url: https://github.com/0day-ci/linux/commits/Prarit-Bhargava/printk-allow-different-timestamps-for-printk-time/20170727-104148
config: i386-tinyconfig (attached as .config)
compiler: gcc-6 (Debian 6.2.0-3) 6.2.0 20160901
reproduce:
# save the attached .config to linux build tree
make ARCH=i386
All errors (new ones prefixed by >>):
kernel/printk/printk.c: In function 'printk_late_init':
>> kernel/printk/printk.c:2746:6: error: 'printk_time_setting' undeclared (first use in this function)
if (printk_time_setting == 0)
^~~~~~~~~~~~~~~~~~~
kernel/printk/printk.c:2746:6: note: each undeclared identifier is reported only once for each function it appears in
>> kernel/printk/printk.c:2747:25: error: 'printk_time' undeclared (first use in this function)
printk_time_setting = printk_time;
^~~~~~~~~~~
vim +/printk_time_setting +2746 kernel/printk/printk.c
2724
2725 /*
2726 * Some boot consoles access data that is in the init section and which will
2727 * be discarded after the initcalls have been run. To make sure that no code
2728 * will access this data, unregister the boot consoles in a late initcall.
2729 *
2730 * If for some reason, such as deferred probe or the driver being a loadable
2731 * module, the real console hasn't registered yet at this point, there will
2732 * be a brief interval in which no messages are logged to the console, which
2733 * makes it difficult to diagnose problems that occur during this time.
2734 *
2735 * To mitigate this problem somewhat, only unregister consoles whose memory
2736 * intersects with the init section. Note that code exists elsewhere to get
2737 * rid of the boot console as soon as the proper console shows up, so there
2738 * won't be side-effects from postponing the removal.
2739 */
2740 static int __init printk_late_init(void)
2741 {
2742 struct console *con;
2743 int ret;
2744
2745 /* initialize printk_time settings */
> 2746 if (printk_time_setting == 0)
> 2747 printk_time_setting = printk_time;
2748
2749 for_each_console(con) {
2750 if (!keep_bootcon && con->flags & CON_BOOT) {
2751 /*
2752 * Make sure to unregister boot consoles whose data
2753 * resides in the init section before the init section
2754 * is discarded. Boot consoles whose data will stick
2755 * around will automatically be unregistered when the
2756 * proper console replaces them.
2757 */
2758 if (init_section_intersects(con, sizeof(*con)))
2759 unregister_console(con);
2760 }
2761 }
2762 ret = cpuhp_setup_state_nocalls(CPUHP_PRINTK_DEAD, "printk:dead", NULL,
2763 console_cpu_notify);
2764 WARN_ON(ret < 0);
2765 ret = cpuhp_setup_state_nocalls(CPUHP_AP_ONLINE_DYN, "printk:online",
2766 console_cpu_notify, NULL);
2767 WARN_ON(ret < 0);
2768 return 0;
2769 }
2770 late_initcall(printk_late_init);
2771
---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all Intel Corporation
[toc] | [prev] | [next] | [standalone]
| From | "Luis R. Rodriguez" <mcgrof@kernel.org> |
|---|---|
| Date | 2017-07-25 15:00 +0200 |
| Subject | Re: [PATCH 1/2] printk: Make CONFIG_PRINTK_TIME an int |
| Message-ID | <u77Bn-2Vd-11@gated-at.bofh.it> |
| In reply to | #1695673 |
On Tue, Jul 25, 2017 at 08:17:26AM -0400, Prarit Bhargava wrote: > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index fc47863f629c..26cf6cadd267 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -1202,8 +1202,40 @@ static inline void boot_delay_msec(int level) > } > #endif > > -static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME); > -module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR); > +static int printk_time = CONFIG_PRINTK_TIME; You could just use unsigned int but is the reason you went with int to enable backward compatibility with the old bool =y or =n? Luis
[toc] | [prev] | [next] | [standalone]
| From | Prarit Bhargava <prarit@redhat.com> |
|---|---|
| Date | 2017-07-31 19:20 +0200 |
| Subject | Re: [PATCH 1/2] printk: Make CONFIG_PRINTK_TIME an int |
| Message-ID | <u9mwi-Ac-7@gated-at.bofh.it> |
| In reply to | #1695707 |
On 07/25/2017 08:55 AM, Luis R. Rodriguez wrote: > On Tue, Jul 25, 2017 at 08:17:26AM -0400, Prarit Bhargava wrote: >> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c >> index fc47863f629c..26cf6cadd267 100644 >> --- a/kernel/printk/printk.c >> +++ b/kernel/printk/printk.c >> @@ -1202,8 +1202,40 @@ static inline void boot_delay_msec(int level) >> } >> #endif >> >> -static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME); >> -module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR); >> +static int printk_time = CONFIG_PRINTK_TIME; > > You could just use unsigned int but is the reason you went with int to > enable backward compatibility with the old bool =y or =n? Yes, I wanted to preserve backwards compatibility. P.
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web