[tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps
Commit-ID: a4c1a0002f4518363da9d9ecd7b805af152dcdf1
Gitweb: http://git.kernel.org/tip/a4c1a0002f4518363da9d9ecd7b805af152dcdf1
Author: Prarit Bhargava
AuthorDate: Mon, 28 Aug 2017 08:21:54 -0400
Committer: Thomas Gleixner
CommitDate: Mon, 25 Sep 2017 21:12:06 +0200
printk: Add monotonic, boottime, and realtime timestamps
printk.time=1/CONFIG_PRINTK_TIME=1 adds a unmodified local hardware clock
timestamp to printk messages. The local hardware clock loses time each
day making it difficult to determine exactly when an issue has occurred in
the kernel log, and making it difficult to determine how kernel and
hardware issues relate to each other.
Make printk output different timestamps by adding options for no timestamp,
the local hardware clock, the monotonic clock, the boottime clock, and the
clock realtime. The default clock can be selected via:
- Kconfig
- Kernel command line parameter
- Sysfs file
Note, that existing user space tools might be confused by selecting clock
realtime, so handle with care.
[ jstultz: Reworked Kconfig settings to avoid defconfig noise ]
Signed-off-by: Prarit Bhargava
Signed-off-by: Thomas Gleixner
Cc: John Stultz
Cc: Joel Fernandes
Cc: Geert Uytterhoeven
Cc: linux-...@vger.kernel.org
Cc: Peter Zijlstra
Cc: Deepa Dinamani
Cc: Christoffer Dall
Cc: "Jason A. Donenfeld"
Cc: Jonathan Corbet
Cc: "Paul E. McKenney"
Cc: Petr Mladek
Cc: Kees Cook
Cc: Steven Rostedt
Cc: Nicholas Piggin
Cc: Josh Poimboeuf
Cc: Greg Kroah-Hartman
Cc: Stephen Boyd
Cc: Mark Salyzyn
Cc: Sergey Senozhatsky
Cc: "Luis R. Rodriguez"
Cc: Olof Johansson
Cc: Andrew Morton
Link:
http://lkml.kernel.org/r/1503922914-10660-3-git-send-email-pra...@redhat.com
---
Documentation/admin-guide/kernel-parameters.txt | 6 +-
kernel/printk/printk.c | 116 +++-
lib/Kconfig.debug | 48 +-
3 files changed, 162 insertions(+), 8 deletions(-)
diff --git a/Documentation/admin-guide/kernel-parameters.txt
b/Documentation/admin-guide/kernel-parameters.txt
index 0549662..9a84483 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3211,8 +3211,10 @@
ratelimit - ratelimit the logging
Default: ratelimit
- printk.time=Show timing data prefixed to each printk message line
- Format: (1/Y/y=enable, 0/N/n=disable)
+ printk.time=Show timestamp prefixed to each printk message line
+ Format:
+ (0/N/n/disable, 1/Y/y/local,
+b/boot, m/monotonic, r/realtime (in UTC))
processor.max_cstate= [HW,ACPI]
Limit processor to maximum C-state
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 512f7c2..4b824dd 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -576,6 +576,9 @@ 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_first_ts(void);
+static u64 (*printk_get_ts)(void) = printk_get_first_ts;
+
/* 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 +627,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;
@@ -1201,14 +1204,116 @@ 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);
+/**
+ * enum timestamp_sources - Timestamp sources for printk() messages.
+ * @PRINTK_TIME_DISABLED: No time stamp.
+ * @PRINTK_TIME_LOCAL: Local hardware clock timestamp.
+ * @PRINTK_TIME_BOOT: Boottime clock timestamp.
+ * @PRINTK_TIME_MONO: Monotonic clock timestamp.
+ * @PRINTK_TIME_REAL: Realtime clock timestamp. On 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.
+ */
+enum timestamp_sources {
+ PRINTK_TIME_DISABLED = 0,
+ PRINTK_TIME_LOCAL = 1,
+ PRINTK_TIME_BOOT = 2,
+ PRINTK_TIME_MONO = 3,
+ PRINTK_TIME_REAL = 4,
+};
+
+static const char * const timestamp_sources_str[5] = {
+ "disabled",
+ "local",
+ "boottime",
+ "monotonic",
+ "realtime",
+};
+
+static int printk_time = CONFIG_PRINTK_TIME_TYPE;
+
+static void printk_set_ts_func(void)
+{
+ switch (printk_time) {
+ case PRINTK_TIME_LOCAL:
+ case
Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps
On (09/25/17 12:19), tip-bot for Prarit Bhargava wrote: > Commit-ID: a4c1a0002f4518363da9d9ecd7b805af152dcdf1 > Gitweb: http://git.kernel.org/tip/a4c1a0002f4518363da9d9ecd7b805af152dcdf1 > Author: Prarit Bhargava > AuthorDate: Mon, 28 Aug 2017 08:21:54 -0400 > Committer: Thomas Gleixner > CommitDate: Mon, 25 Sep 2017 21:12:06 +0200 > > printk: Add monotonic, boottime, and realtime timestamps this doesn't seem to be the latest version of the patch set. v12 can be found here: lkml.kernel.org/r/1505757060-2004-1-git-send-email-pra...@redhat.com -ss
Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps
On Tue, 26 Sep 2017, Sergey Senozhatsky wrote: > On (09/25/17 12:19), tip-bot for Prarit Bhargava wrote: > > Commit-ID: a4c1a0002f4518363da9d9ecd7b805af152dcdf1 > > Gitweb: > > http://git.kernel.org/tip/a4c1a0002f4518363da9d9ecd7b805af152dcdf1 > > Author: Prarit Bhargava > > AuthorDate: Mon, 28 Aug 2017 08:21:54 -0400 > > Committer: Thomas Gleixner > > CommitDate: Mon, 25 Sep 2017 21:12:06 +0200 > > > > printk: Add monotonic, boottime, and realtime timestamps > > this doesn't seem to be the latest version of the patch set. > v12 can be found here: > lkml.kernel.org/r/1505757060-2004-1-git-send-email-pra...@redhat.com Thanks for pointing it out. I somehow got lost in the revisions zoo. Fixed now. tglx
Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps
On 09/26/2017 04:42 AM, tip-bot for Prarit Bhargava wrote:
> Commit-ID: 310b454a8653ea60d3eb21ce5ab03a282a32fbe1
> Gitweb: http://git.kernel.org/tip/310b454a8653ea60d3eb21ce5ab03a282a32fbe1
> Author: Prarit Bhargava
> AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400
> Committer: Thomas Gleixner
> CommitDate: Tue, 26 Sep 2017 10:38:07 +0200
>
> printk: Add monotonic, boottime, and realtime timestamps
>
> printk.time=1/CONFIG_PRINTK_TIME=1 adds a unmodified local hardware clock
> timestamp to printk messages. The local hardware clock loses time each
> day making it difficult to determine exactly when an issue has occurred in
> the kernel log, and making it difficult to determine how kernel and
> hardware issues relate to each other.
>
> Make printk output different timestamps by adding options for no timestamp,
> the local hardware clock, monotonic clock, boottime clock, and clock
> realtime. The default clock can be selected via:
>
> - Kconfig
> - Kernel command line parameter
> - Sysfs file
>
> Note, that existing user space tools might be confused by selecting clock
> realtime, so handle with care.
pmladek found a compile warning due to printk_time being unused. I will post a
v14 on LKML shortly.
P.
>
> [jstultz: Reworked Kconfig settings to avoid defconfig noise]
>
> Signed-off-by: Prarit Bhargava
> Signed-off-by: Thomas Gleixner
> Cc: Joel Fernandes
> Cc: Geert Uytterhoeven
> Cc: linux-...@vger.kernel.org
> Cc: Peter Zijlstra
> Cc: Deepa Dinamani
> Cc: Christoffer Dall
> Cc: "Jason A. Donenfeld"
> Cc: Jonathan Corbet
> Cc: "Paul E. McKenney"
> Cc: Petr Mladek
> Cc: Kees Cook
> Cc: Steven Rostedt
> Cc: Nicholas Piggin
> Cc: Josh Poimboeuf
> Cc: Greg Kroah-Hartman
> Cc: Stephen Boyd
> Cc: Mark Salyzyn
> Cc: Sergey Senozhatsky
> Cc: "Luis R. Rodriguez"
> Cc: Olof Johansson
> Cc: Andrew Morton
> Link:
> https://lkml.kernel.org/r/1505757060-2004-4-git-send-email-pra...@redhat.com
>
> ---
> Documentation/admin-guide/kernel-parameters.txt | 6 +-
> kernel/printk/printk.c | 130
> +++-
> lib/Kconfig.debug | 48 -
> 3 files changed, 176 insertions(+), 8 deletions(-)
>
> diff --git a/Documentation/admin-guide/kernel-parameters.txt
> b/Documentation/admin-guide/kernel-parameters.txt
> index 0549662..9a84483 100644
> --- a/Documentation/admin-guide/kernel-parameters.txt
> +++ b/Documentation/admin-guide/kernel-parameters.txt
> @@ -3211,8 +3211,10 @@
> ratelimit - ratelimit the logging
> Default: ratelimit
>
> - printk.time=Show timing data prefixed to each printk message line
> - Format: (1/Y/y=enable, 0/N/n=disable)
> + printk.time=Show timestamp prefixed to each printk message line
> + Format:
> + (0/N/n/disable, 1/Y/y/local,
> + b/boot, m/monotonic, r/realtime (in UTC))
>
> processor.max_cstate= [HW,ACPI]
> Limit processor to maximum C-state
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 512f7c2..5e0bf2e 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -576,6 +576,9 @@ 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_first_ts(void);
> +static u64 (*printk_get_ts)(void) = printk_get_first_ts;
> +
> /* 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 +627,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;
>
> @@ -1201,14 +1204,130 @@ 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);
> +/**
> + * enum timestamp_sources - Timestamp sources for printk() messages.
> + * @PRINTK_TIME_DISABLED: No time stamp.
> + * @PRINTK_TIME_LOCAL: Local hardware clock timestamp.
> + * @PRINTK_TIME_BOOT: Boottime clock timestamp.
> + * @PRINTK_TIME_MONO: Monotonic clock timestamp.
> + * @PRINTK_TIME_REAL: Realtime clock timestamp.
> + */
> +enum timestamp_sources {
> + PRINTK_TIME_DISABLED = 0,
> + PRINTK_TIME_LOCAL = 1,
> + PRINTK_TIME_BOOT = 2,
> + PRINTK_TIME_MONO = 3,
> + PRINTK_TIME_REAL = 4,
> +};
> +
> +static const char * const timestamp_sources_str[5] = {
> + "disabled",
> + "local",
> + "boottime",
> + "monotonic",
> + "realtime",
> +};
> +
> +static int printk_time = CONFIG_PRINTK
Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps
On Tue, 26 Sep 2017, Prarit Bhargava wrote: > On 09/26/2017 04:42 AM, tip-bot for Prarit Bhargava wrote: > > Commit-ID: 310b454a8653ea60d3eb21ce5ab03a282a32fbe1 > > Gitweb: > > http://git.kernel.org/tip/310b454a8653ea60d3eb21ce5ab03a282a32fbe1 > > Author: Prarit Bhargava > > AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400 > > Committer: Thomas Gleixner > > CommitDate: Tue, 26 Sep 2017 10:38:07 +0200 > > > > printk: Add monotonic, boottime, and realtime timestamps > > > > printk.time=1/CONFIG_PRINTK_TIME=1 adds a unmodified local hardware clock > > timestamp to printk messages. The local hardware clock loses time each > > day making it difficult to determine exactly when an issue has occurred in > > the kernel log, and making it difficult to determine how kernel and > > hardware issues relate to each other. > > > > Make printk output different timestamps by adding options for no timestamp, > > the local hardware clock, monotonic clock, boottime clock, and clock > > realtime. The default clock can be selected via: > > > > - Kconfig > > - Kernel command line parameter > > - Sysfs file > > > > Note, that existing user space tools might be confused by selecting clock > > realtime, so handle with care. > > pmladek found a compile warning due to printk_time being unused. I will post > a > v14 on LKML shortly. Errm. I applied v12. where the heck is v13? And in the applied patch printk_time is used. Thanks, tglx
Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps
On 09/26/2017 11:26 AM, Thomas Gleixner wrote: > On Tue, 26 Sep 2017, Prarit Bhargava wrote: > >> On 09/26/2017 04:42 AM, tip-bot for Prarit Bhargava wrote: >>> Commit-ID: 310b454a8653ea60d3eb21ce5ab03a282a32fbe1 >>> Gitweb: >>> http://git.kernel.org/tip/310b454a8653ea60d3eb21ce5ab03a282a32fbe1 >>> Author: Prarit Bhargava >>> AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400 >>> Committer: Thomas Gleixner >>> CommitDate: Tue, 26 Sep 2017 10:38:07 +0200 >>> >>> printk: Add monotonic, boottime, and realtime timestamps >>> >>> printk.time=1/CONFIG_PRINTK_TIME=1 adds a unmodified local hardware clock >>> timestamp to printk messages. The local hardware clock loses time each >>> day making it difficult to determine exactly when an issue has occurred in >>> the kernel log, and making it difficult to determine how kernel and >>> hardware issues relate to each other. >>> >>> Make printk output different timestamps by adding options for no timestamp, >>> the local hardware clock, monotonic clock, boottime clock, and clock >>> realtime. The default clock can be selected via: >>> >>> - Kconfig >>> - Kernel command line parameter >>> - Sysfs file >>> >>> Note, that existing user space tools might be confused by selecting clock >>> realtime, so handle with care. >> >> pmladek found a compile warning due to printk_time being unused. I will >> post a >> v14 on LKML shortly. > > Errm. I applied v12. where the heck is v13? > > And in the applied patch printk_time is used. Sorry, my mistake I meant v13. This morning pmladek posted about a warning when when CONFIG_PRINTK is not defined: https://marc.info/?l=linux-doc&m=150642667403344&w=2 I'm fixing it now for v13. P. > > Thanks, > > tglx > >
Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps
On Tue, 26 Sep 2017, Prarit Bhargava wrote: > On 09/26/2017 11:26 AM, Thomas Gleixner wrote: > > On Tue, 26 Sep 2017, Prarit Bhargava wrote: > > > >> On 09/26/2017 04:42 AM, tip-bot for Prarit Bhargava wrote: > >>> Commit-ID: 310b454a8653ea60d3eb21ce5ab03a282a32fbe1 > >>> Gitweb: > >>> http://git.kernel.org/tip/310b454a8653ea60d3eb21ce5ab03a282a32fbe1 > >>> Author: Prarit Bhargava > >>> AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400 > >>> Committer: Thomas Gleixner > >>> CommitDate: Tue, 26 Sep 2017 10:38:07 +0200 > >>> > >>> printk: Add monotonic, boottime, and realtime timestamps > >>> > >>> printk.time=1/CONFIG_PRINTK_TIME=1 adds a unmodified local hardware clock > >>> timestamp to printk messages. The local hardware clock loses time each > >>> day making it difficult to determine exactly when an issue has occurred in > >>> the kernel log, and making it difficult to determine how kernel and > >>> hardware issues relate to each other. > >>> > >>> Make printk output different timestamps by adding options for no > >>> timestamp, > >>> the local hardware clock, monotonic clock, boottime clock, and clock > >>> realtime. The default clock can be selected via: > >>> > >>> - Kconfig > >>> - Kernel command line parameter > >>> - Sysfs file > >>> > >>> Note, that existing user space tools might be confused by selecting clock > >>> realtime, so handle with care. > >> > >> pmladek found a compile warning due to printk_time being unused. I will > >> post a > >> v14 on LKML shortly. > > > > Errm. I applied v12. where the heck is v13? > > > > And in the applied patch printk_time is used. > > Sorry, my mistake I meant v13. > > This morning pmladek posted about a warning when when CONFIG_PRINTK is not > defined: > > https://marc.info/?l=linux-doc&m=150642667403344&w=2 > > I'm fixing it now for v13. Please send a delta patch.
Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps
On 09/26/2017 11:33 AM, Thomas Gleixner wrote: > On Tue, 26 Sep 2017, Prarit Bhargava wrote: >> On 09/26/2017 11:26 AM, Thomas Gleixner wrote: >>> On Tue, 26 Sep 2017, Prarit Bhargava wrote: >>> On 09/26/2017 04:42 AM, tip-bot for Prarit Bhargava wrote: > Commit-ID: 310b454a8653ea60d3eb21ce5ab03a282a32fbe1 > Gitweb: > http://git.kernel.org/tip/310b454a8653ea60d3eb21ce5ab03a282a32fbe1 > Author: Prarit Bhargava > AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400 > Committer: Thomas Gleixner > CommitDate: Tue, 26 Sep 2017 10:38:07 +0200 > > printk: Add monotonic, boottime, and realtime timestamps > > printk.time=1/CONFIG_PRINTK_TIME=1 adds a unmodified local hardware clock > timestamp to printk messages. The local hardware clock loses time each > day making it difficult to determine exactly when an issue has occurred in > the kernel log, and making it difficult to determine how kernel and > hardware issues relate to each other. > > Make printk output different timestamps by adding options for no > timestamp, > the local hardware clock, monotonic clock, boottime clock, and clock > realtime. The default clock can be selected via: > > - Kconfig > - Kernel command line parameter > - Sysfs file > > Note, that existing user space tools might be confused by selecting clock > realtime, so handle with care. pmladek found a compile warning due to printk_time being unused. I will post a v14 on LKML shortly. >>> >>> Errm. I applied v12. where the heck is v13? >>> >>> And in the applied patch printk_time is used. >> >> Sorry, my mistake I meant v13. >> >> This morning pmladek posted about a warning when when CONFIG_PRINTK is not >> defined: >> >> https://marc.info/?l=linux-doc&m=150642667403344&w=2 >> >> I'm fixing it now for v13. > > Please send a delta patch. > Will do. P.
