From: Prarit Bhargava <[email protected]>
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 in real time.
Make printk output different timestamps by adding options for no
timestamp, the local hardware clock, the monotonic clock, the boottime
clock, and the real clock. Allow a user to pick one of the clocks by
using the printk.time kernel parameter. Output the type of clock in
/sys/module/printk/parameters/time so userspace programs can interpret the
timestamp.
v2: Use peterz's suggested Kconfig options. Merge patchset together.
Fix i386 !CONFIG_PRINTK builds.
v3: Fixed x86_64_defconfig. Added printk_time_type enum and
printk_time_str for better output. Added BOOTTIME clock functionality.
v4: Fix messages, add additional printk.time options, and fix configs.
v5: Renaming of structures, and allow printk_time_set() to
evaluate substrings of entries (eg: allow 'r', 'real', 'realtime'). From
peterz, make fast functions return 0 until timekeeping is initialized
(removes timekeeping_active & ktime_get_boot|real_log_ts() suggested by
tglx and adds ktime_get_real_offset()). Switch to a function pointer
for printk_get_ts() and reference fast functions. Make timestamp_sources enum
match choice options for CONFIG_PRINTK_TIME (adds PRINTK_TIME_UNDEFINED).
v6: Define PRINTK_TIME_UNDEFINED for !CONFIG_PRINTK builds. Separate
timekeeping changes into separate patch. Minor include file cleanup.
v7: Add default case to printk_set_timestamp() and add PRINTK_TIME_DEBUG
for users that want to set timestamp to different values during runtime.
Add jstultz' Kconfig to avoid defconfig churn.
v8: Add CONFIG_PRINTK_TIME_DEBUG to allow timestamp runtime switching.
Rename PRINTK_TIME_DISABLE to PRINTK_TIME_DISABLED. Rename
printk_set_timestamp() to printk_set_ts_func(). Separate
printk_set_ts_func() and printk_get_first_ts() portions. Rename param
functions. Adjust configs, enum, and timestamp_sources_str to be 0-4.
Add mention realtime clock is UTC in Documentation.
v9: Fix typo. Add __ktime_get_real_fast_ns_unsafe().
v10: Remove time parameter restrictions.
v11: Rework using tglx's real time patch
v12: Reword Kconfig names. Simplify timestamp logic and remove
recursive code.
v13: This patch seems have being forgotten for 3 years. Rebase it on
the latest kernel v5.8, reolve conflicts and fix compiling errors.
Change code to adapt new printk_time usage.
Petr's concern on printk_time is addressed by current version of kernel, too.
Signed-off-by: Prarit Bhargava <[email protected]>
Cc: Mark Salyzyn <[email protected]>
Cc: Jonathan Corbet <[email protected]>
Cc: Petr Mladek <[email protected]>
Cc: Sergey Senozhatsky <[email protected]>
Cc: Steven Rostedt <[email protected]>
Cc: John Stultz <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Cc: Stephen Boyd <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: "Paul E. McKenney" <[email protected]>
Cc: Christoffer Dall <[email protected]>
Cc: Deepa Dinamani <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Joel Fernandes <[email protected]>
Cc: Prarit Bhargava <[email protected]>
Cc: Kees Cook <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Geert Uytterhoeven <[email protected]>
Cc: "Luis R. Rodriguez" <[email protected]>
Cc: Nicholas Piggin <[email protected]>
Cc: "Jason A. Donenfeld" <[email protected]>
Cc: Olof Johansson <[email protected]>
Cc: Josh Poimboeuf <[email protected]>
Cc: [email protected]
[jstultz: reworked Kconfig settings to avoid defconfig noise]
Signed-off-by: John Stultz <[email protected]>
Reviewed-by: Petr Mladek <[email protected]>
[orson: rebase on v5.8 and make necessary changes]
Signed-off-by: Orson Zhai <[email protected]>
---
Documentation/admin-guide/kernel-parameters.txt | 6 +-
kernel/printk/printk.c | 127 +++++++++++++++++++++++-
lib/Kconfig.debug | 48 ++++++++-
3 files changed, 174 insertions(+), 7 deletions(-)
diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index fb95fad..0bf5f69 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3874,8 +3874,10 @@
ratelimit - ratelimit the logging
Default: ratelimit
- printk.time= Show timing data prefixed to each printk message line
- Format: <bool> (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,
+ 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 b71eaf5..ba35f89 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -612,6 +612,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(u32 caller_id, int facility, int level,
enum log_flags flags, u64 ts_nsec,
@@ -660,7 +663,7 @@ static int log_store(u32 caller_id, 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();
#ifdef CONFIG_PRINTK_CALLER
msg->caller_id = caller_id;
#endif
@@ -1284,8 +1287,124 @@ 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_TIME_TYPE;
+
+static int printk_set_ts_source(enum timestamp_sources ts_source)
+{
+ int err = 0;
+
+ switch (ts_source) {
+ case PRINTK_TIME_LOCAL:
+ printk_get_ts = local_clock;
+ break;
+ case PRINTK_TIME_BOOT:
+ printk_get_ts = ktime_get_boot_fast_ns;
+ break;
+ case PRINTK_TIME_MONO:
+ printk_get_ts = ktime_get_mono_fast_ns;
+ break;
+ case PRINTK_TIME_REAL:
+ printk_get_ts = ktime_get_real_fast_ns;
+ break;
+ case PRINTK_TIME_DISABLED:
+ /*
+ * The timestamp is always stored into the log buffer.
+ * Keep the current one.
+ */
+ break;
+ default:
+ err = -EINVAL;
+ break;
+ }
+
+ if (!err)
+ printk_time = ts_source;
+ return err;
+}
+
+static u64 printk_get_first_ts(void)
+{
+ printk_set_ts_source(printk_time);
+
+ /* Fallback for invalid or disabled timestamp source */
+ if (printk_get_ts == printk_get_first_ts)
+ printk_get_ts = local_clock;
+
+ return printk_get_ts();
+}
+
+static int param_set_time(const char *val, const struct kernel_param *kp)
+{
+ char *param = strstrip((char *)val);
+ int time_source = -1;
+ int ts;
+ int err;
+
+ if (strlen(param) == 1) {
+ /* Preserve legacy boolean settings */
+ if ((param[0] == '0') || (param[0] == 'n') ||
+ (param[0] == 'N'))
+ time_source = PRINTK_TIME_DISABLED;
+ if ((param[0] == '1') || (param[0] == 'y') ||
+ (param[0] == 'Y'))
+ time_source = PRINTK_TIME_LOCAL;
+ }
+ if (time_source == -1) {
+ for (ts = 0; ts < ARRAY_SIZE(timestamp_sources_str); ts++) {
+ if (!strncmp(timestamp_sources_str[ts], param,
+ strlen(param))) {
+ time_source = ts;
+ break;
+ }
+ }
+ }
+
+ err = printk_set_ts_source(time_source);
+ if (err) {
+ pr_warn("printk: invalid timestamp option %s\n", param);
+ return err;
+ }
+
+ pr_info("printk: timestamp set to %s\n",
+ timestamp_sources_str[printk_time]);
+ return 0;
+}
+
+static int param_get_time(char *buffer, const struct kernel_param *kp)
+{
+ return scnprintf(buffer, PAGE_SIZE, "%s",
+ timestamp_sources_str[printk_time]);
+}
+
+static struct kernel_param_ops printk_time_ops = {
+ .set = param_set_time,
+ .get = param_get_time,
+};
+module_param_cb(time, &printk_time_ops, NULL, 0644);
static size_t print_syslog(unsigned int level, char *buf)
{
@@ -1876,7 +1995,7 @@ static bool cont_add(u32 caller_id, int facility, int level,
cont.facility = facility;
cont.level = level;
cont.caller_id = caller_id;
- cont.ts_nsec = local_clock();
+ cont.ts_nsec = printk_get_ts();
cont.flags = flags;
}
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 9ad9210..e34b905 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -11,12 +11,58 @@ config PRINTK_TIME
messages to be added to the output of the syslog() system
call and at the console.
+choice
+ prompt "printk default clock timestamp" if PRINTK_TIME
+ default PRINTK_TIME_LOCAL if PRINTK_TIME
+ help
+ This option is selected by setting one of
+ PRINTK_TIME_[DISABLE|LOCAL|BOOT|MONO|REAL] and causes time stamps of
+ the printk() messages to be added to the output of the syslog()
+ system call and at the console.
+
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.
The behavior is also controlled by the kernel command line
- parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst
+ parameter printk.time. See
+ Documentation/admin-guide/kernel-parameters.rst
+
+config PRINTK_TIME_LOCAL
+ bool "Local Clock"
+ help
+ Selecting this option causes the time stamps of printk() to be
+ stamped with the unadjusted hardware clock.
+
+config PRINTK_TIME_BOOT
+ bool "Boot Time Clock"
+ help
+ Selecting this option causes the time stamps of printk() to be
+ stamped with the adjusted boottime clock.
+
+config PRINTK_TIME_MONO
+ bool "Monotonic Clock"
+ help
+ Selecting this option causes the time stamps of printk() to be
+ stamped with the adjusted monotonic clock.
+
+config PRINTK_TIME_REAL
+ bool "Real Time Clock"
+ help
+ Selecting this option causes the time stamps of printk() to be
+ stamped with the adjusted realtime clock (UTC).
+endchoice
+
+config PRINTK_TIME_TYPE
+ int
+ depends on PRINTK
+ range 0 4
+ default 0 if !PRINTK_TIME
+ default 1 if PRINTK_TIME_LOCAL
+ default 2 if PRINTK_TIME_BOOT
+ default 3 if PRINTK_TIME_MONO
+ default 4 if PRINTK_TIME_REAL
+
config PRINTK_CALLER
bool "Show caller information on printks"
--
2.7.4
Chunyan Zhang <[email protected]> wrote:
> From: Prarit Bhargava <[email protected]>
>
> 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 in real time.
>
> Make printk output different timestamps by adding options for no
> timestamp, the local hardware clock, the monotonic clock, the boottime
> clock, and the real clock. Allow a user to pick one of the clocks by
> using the printk.time kernel parameter. Output the type of clock in
> /sys/module/printk/parameters/time so userspace programs can interpret the
> timestamp.
>
> v13: This patch seems have being forgotten for 3 years. Rebase it on
> the latest kernel v5.8, reolve conflicts and fix compiling errors.
> Change code to adapt new printk_time usage.
> Petr's concern on printk_time is addressed by current version of kernel, too.
Lyra,
Copying a reply I sent to Orson who sent me this patch privately this
morning with some additional information.
ISTR the reason that this was dropped was because of the a problem with
the way systemd read the kernel's timestamps. It got the attention of
Linus, and it was then pulled from the tree.
I need to go back and review the entire thread as it's been several years
since we had the discussion although ISTR someone mentioning that doing two
timestamps would not be a problem for systemd.
For example,
[48551.015086]
would be
[48551.015086] m[xxxx.xxxx]
for the monotonic clock timestamp, and
[48551.015086] b[xxxx.xxxx]
for the boottime clock, etc.
P.
On Wed 2020-07-29 08:22:36, Prarit Bhargava wrote:
> Chunyan Zhang <[email protected]> wrote:
> > From: Prarit Bhargava <[email protected]>
> >
> > 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 in real time.
> >
> > Make printk output different timestamps by adding options for no
> > timestamp, the local hardware clock, the monotonic clock, the boottime
> > clock, and the real clock. Allow a user to pick one of the clocks by
> > using the printk.time kernel parameter. Output the type of clock in
> > /sys/module/printk/parameters/time so userspace programs can interpret the
> > timestamp.
> >
> ISTR the reason that this was dropped was because of the a problem with
> the way systemd read the kernel's timestamps. It got the attention of
> Linus, and it was then pulled from the tree.
>
> I need to go back and review the entire thread as it's been several years
> since we had the discussion although ISTR someone mentioning that doing two
> timestamps would not be a problem for systemd.
I guess that you talk about this thread
https://lore.kernel.org/lkml/CA+55aFwUfA__6MgMgjENnx+_RYY2ZOOLiSx2ea1AvYhSZN+78A@mail.gmail.com/
> For example,
>
> [48551.015086]
>
> would be
>
> [48551.015086] m[xxxx.xxxx]
>
> for the monotonic clock timestamp, and
>
> [48551.015086] b[xxxx.xxxx]
>
> for the boottime clock, etc.
This approach has several drawbacks:
+ Too long prefix might make it hard to see the real messages
because of shrunken/wrapped lines.
+ Too long lines are problem with slow consoles.
+ More space will be necessary to store all the time stamps.
+ Userspace tools would need/want to parse the format. We would
need to maintain it forever.
Linus had an interesting idea to print all timestamps regularly.
The frequency might be configurable. It might print, for example,
the following line every 10 minutes or once a day:
[48551.015086] System alive: b[xxxx.xxxx] m[xxxx.xxxx]
It might be useful in general to see when the system was still alive
before it froze.
Would it be enough to sort messages printed with different clock
sources?
Best Regards,
Petr
On 8/5/20 10:04 AM, Petr Mladek wrote:
> On Wed 2020-07-29 08:22:36, Prarit Bhargava wrote:
>> Chunyan Zhang <[email protected]> wrote:
>>> From: Prarit Bhargava <[email protected]>
>>>
>>> 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 in real time.
>>>
>>> Make printk output different timestamps by adding options for no
>>> timestamp, the local hardware clock, the monotonic clock, the boottime
>>> clock, and the real clock. Allow a user to pick one of the clocks by
>>> using the printk.time kernel parameter. Output the type of clock in
>>> /sys/module/printk/parameters/time so userspace programs can interpret the
>>> timestamp.
>>>
>> ISTR the reason that this was dropped was because of the a problem with
>> the way systemd read the kernel's timestamps. It got the attention of
>> Linus, and it was then pulled from the tree.
>>
>> I need to go back and review the entire thread as it's been several years
>> since we had the discussion although ISTR someone mentioning that doing two
>> timestamps would not be a problem for systemd.
>
> I guess that you talk about this thread
> https://lore.kernel.org/lkml/CA+55aFwUfA__6MgMgjENnx+_RYY2ZOOLiSx2ea1AvYhSZN+78A@mail.gmail.com/
>
>> For example,
>>
>> [48551.015086]
>>
>> would be
>>
>> [48551.015086] m[xxxx.xxxx]
>>
>> for the monotonic clock timestamp, and
>>
>> [48551.015086] b[xxxx.xxxx]
>>
>> for the boottime clock, etc.
>
> This approach has several drawbacks:
>
> + Too long prefix might make it hard to see the real messages
> because of shrunken/wrapped lines.
>
> + Too long lines are problem with slow consoles.
>
> + More space will be necessary to store all the time stamps.
>
> + Userspace tools would need/want to parse the format. We would
> need to maintain it forever.
>
>
> Linus had an interesting idea to print all timestamps regularly.
> The frequency might be configurable. It might print, for example,
> the following line every 10 minutes or once a day:
>
> [48551.015086] System alive: b[xxxx.xxxx] m[xxxx.xxxx]
>
> It might be useful in general to see when the system was still alive
> before it froze.
>
> Would it be enough to sort messages printed with different clock
> sources?
Hey Petr,
After reviewing the thread (it has been three years after all), I have asked
Orson and Lyra to look at the suggested changes by tglx and Linus and submit
those instead of "this" patch.
I should have updated this thread with that info. Sorry 'bout that.
P.