On Tue 2017-09-05 08:06:41, Prarit Bhargava wrote:
> 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.
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fc47863f629c..5aaeb1ebd26c 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1202,14 +1205,113 @@ 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 void printk_set_ts_func(void)
> +{
> + switch (printk_time) {
> + case PRINTK_TIME_LOCAL:
> + case PRINTK_TIME_DISABLED:
> + default:
> + printk_get_ts = local_clock;
> + break;
This is slightly confusing. One would expect that local_clock()
will be used when "disabled" is written into
/sys/module/printk/parameters/time. But it is not true
because this function is not called in that case.
I know that you do this to avoid recursion in
printk_get_first_ts(), I know because I read the discussion
about an older version of the patch. But this is less
obvious from the code.
> + 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;
> + }
> +}
I think that it would be cleaner the following way:
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;
}
Then we could avoid the recursion directly in printk_get_first_ts().
> +
> +static u64 printk_get_first_ts(void)
> +{
> + printk_set_ts_func();
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 _printk_time = -1;
> + int ts;
int err;
> +
> + if (strlen(param) == 1) {
> + /* Preserve legacy boolean settings */
> + if ((param[0] == '0') || (param[0] == 'n') ||
> + (param[0] == 'N'))
> + _printk_time = PRINTK_TIME_DISABLED;
> + if ((param[0] == '1') || (param[0] == 'y') ||
> + (param[0] == 'Y'))
> + _printk_time = PRINTK_TIME_LOCAL;
> + }
> + if (_printk_time == -1) {
> + for (ts = 0; ts < ARRAY_SIZE(timestamp_sources_str); ts++) {
> + if (!strncmp(timestamp_sources_str[ts], param,
> + strlen(param))) {
> + _printk_time = ts;
> + break;
> + }
> + }
> + }
> + if (_printk_time == -1) {
> + pr_warn("printk: invalid timestamp option %s\n", param);
> + return -EINVAL;
> + }
> +
> + printk_time = _printk_time;
> + if (printk_time > PRINTK_TIME_DISABLED)
> + printk_set_ts_func();
Finally, we could replace the above two sections by:
err = printk_set_ts_source(_printk_time);
if (err) {
pr_warn("printk: invalid timestamp option %s\n", param);
return err;
}
Also I would rename the variable "_pritnk_time" to "time_source"
in this function.
> + 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_time(u64 ts, char *buf)
> {
> unsigned long rem_nsec;
>
> - if (!printk_time)
> + if (printk_time == PRINTK_TIME_DISABLED)
> return 0;
>
> rem_nsec = do_div(ts, 1000000000);
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index c617b9d1d6cb..e9e1798415fa 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -8,12 +8,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 "CLOCK_BOOTTIME"
s/CLOCK_BOOTTIME/Boot time clock/
It will make it easier to read and consistent with the local
clock option.
> + help
> + Selecting this option causes the time stamps of printk() to be
> + stamped with the adjusted boottime clock.
> +
> +config PRINTK_TIME_MONO
> + bool "CLOCK_MONOTONIC"
same here
> + help
> + Selecting this option causes the time stamps of printk() to be
> + stamped with the adjusted monotonic clock.
> +
> +config PRINTK_TIME_REAL
> + bool "CLOCK_REALTIME"
and here
> + 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
> +
I am still slightly nervous that external tools would need updating.
Also they might have troubles to interpret the time stamps especially
when the source is changed at runtime via
/sys/module/printk/parameters/time.
On the other hand, we do not change the default behavior. You sent
me a patch against dmesg. It was trivial and worked well. Also we
got positive (constructive) feedback from several people. Therefore
I am getting open for this change.
Best Regards,
Petr
PS: Please, do not forget to handle the complains from
Thomas Gleixner in the first patch.
--
To unsubscribe from this list: send the line "unsubscribe linux-doc" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
