On 08/23/2017 04:45 AM, Petr Mladek wrote:
> On Thu 2017-08-17 09:15:39, 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..3c46217629fd 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -1202,14 +1205,144 @@ 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_TYPE;
>> +static int printk_time_source;
>> +
>> +/**
>> + * enum timestamp_sources - Timestamp sources for printk() messages.
>> + * @PRINTK_TIME_UNDEFINED: Timestamp undefined. This option is not selectable
>> + * from the configs, and is used as a reference in the code.
>> + * @PRINTK_TIME_DISABLE: 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 when printk_get_ts() is set to
>> + * printk_get_real_ns().
>> + */
>> +enum timestamp_sources {
>
> I guess that this might be static. Also it is related to the
> PRINTK_TIME_TYPE Kconfig option. So the name should be
> enum printk_time_type or so.
>
>
>> + PRINTK_TIME_UNDEFINED = 0,
>
> I would use -1 for PRINTK_TIME_UNDEFINED or I would remove it
> completely, see below. Then we could use 0 for PRINTK_TIME_DISABLED
> which is more expected.
FIXED along with adjustment of configs (see below).
>
>
>> + PRINTK_TIME_DISABLE = 1,
>
> This should be PRINTK_TIME_DISABLED to be in sync with
> the string and style of the other flags.
>
FIXED.
>
>> + PRINTK_TIME_LOCAL = 2,
>> + PRINTK_TIME_BOOT = 3,
>> + PRINTK_TIME_MONO = 4,
>> + PRINTK_TIME_REAL = 5,
>> +};
>> +
>> +static const char * const timestamp_sources_str[6] = {
>> + "undefined",
>
> Do we really need the string "undefined"?
It is only included to keep timestamp_sources_str & the enum in sync.
FIXED & removed with adjustment of configs & enum.
<snip>
>> +/**
>> + * printk_get_real_ns: - Return a realtime timestamp for printk messages
>> + * 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.
>> + */
>> +static u64 printk_get_real_ns(void)
>> +{
>> + return ktime_get_mono_fast_ns() + ktime_get_real_offset();
>> +}
>> +
>> +static u64 printk_set_timestamp(void)
>
> I would rename this function to printk_set_ts_func() or so.
> It will be more clear the it sets the function pointer.
>
FIXED.
>
>> +{
>> + switch (printk_time) {
>> + case PRINTK_TIME_LOCAL:
>> + case PRINTK_TIME_DISABLE:
>> + default:
>> + printk_get_ts = local_clock;
>
> The PRINTK_TIME_DISABLE case is more complicated. We should set
> printk_get_ts only when it has not been set yet. Otherwise,
> we should keep storing the same type of time stamps into
> to the log buffer and keep it consistent.
>
I think you've figured this out below.... but for other readers,
printk_time_set() does not call printk_set_timestamp with
printk_time = PRINTK_TIME_DISABLE.
>
>> + 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 = printk_get_real_ns;
>> + break;
>> + }
>> + return printk_get_ts();
>
> On one hand, this side effect helps to reuse the same code but it
> looks too hacky to me. Another possibility would be to create:
>
> static u64 printk_get_first_ts()
> {
> printk_set_ts_function();
>
> return printk_get_ts();
> }
>
> and initialize:
>
> static u64 (*printk_get_ts)(void) = printk_get_first_ts();
>
FIXED.
> Another side effect is that we might not need PRINTK_TIME_UNDEFINED.
>
I tried to do this, however, I still need PRINTK_TIME_UNDEFINED to indicate
that printk_time_source is not set. PRINTK_TIME_UNDEFINED "reads" better IMO.
>From your comment it looks like you're okay with me leaving it defined, just
not as 0. I have changed it to -1. FIXED.
>
>> +}
>> +
>> +static int printk_time_set(const char *val, const struct kernel_param *kp)
>> +{
>> + char *param = strstrip((char *)val);
>> + int _printk_time = PRINTK_TIME_UNDEFINED;
>> + int ts;
>> +
>> + if (strlen(param) == 1) {
>> + /* Preserve legacy boolean settings */
>> + if ((param[0] == '0') || (param[0] == 'n') ||
>> + (param[0] == 'N'))
>> + _printk_time = PRINTK_TIME_DISABLE;
>> + if ((param[0] == '1') || (param[0] == 'y') ||
>> + (param[0] == 'Y'))
>> + _printk_time = PRINTK_TIME_LOCAL;
>> + }
>> + if (_printk_time == PRINTK_TIME_UNDEFINED) {
>> + 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 == PRINTK_TIME_UNDEFINED) {
>> + pr_warn("printk: invalid timestamp option %s\n", param);
>> + return -EINVAL;
>> + }
>> +
>> + if (printk_time_source == PRINTK_TIME_UNDEFINED)
>> + printk_time_source = _printk_time;
>> +#ifndef PRINTK_TIME_DEBUG
>> + else if ((printk_time_source != _printk_time) &&
>> + (_printk_time != PRINTK_TIME_DISABLE)) {
>> + /*
>> + * Only allow enabling and disabling of the current printk_time
>> + * setting. Changing it from one setting to another confuses
>> + * userspace.
>> + */
>> + pr_warn("printk: timestamp can only be set to 0, disabled, or %s\n",
>> + timestamp_sources_str[printk_time_source]);
>> + return -EINVAL;
>> + }
>> +#endif
>
> Do we really need this complication? I guess that people will
This has been requested multiple times by Mark Salyzyn <salyzyn@xxxxxxxxxxx>.
It does not add any additional complexity beyond a (recently requested)
config option. I like the option FWIW and I just forgot to include it (sorry
Mark) in earlier versions. I like Mark's idea of adding 'b', r', etc.,
to the timestamps but have put it off for future effort... but your suggestion
below is a better approach [1]. After some discussion with Mark,
I'll see what I can do after this initial patchset is completed.
<snip>
>
>
> And this brings an important question. Do you have any plans
> to update userspace for this change (dmesg, crash, syslogd,
> other loggers)?
I mentioned this in an earlier version of these patches -- I have code for
dmesg. crash, as I said before, doesn't need to be modified according to
Dave Anderson. dmesg, from util-linux, requires *this* patchset to be in
Linus' tree before they will even look at a patch.
>
> If I compile the kernel with CONFIG_PRINTK_TIME_LOCAL=y
> and boot with printk.time=realtime. Then I get
> the following output from dmesg --time-format=iso:
>
> 2017-08-23T09:38:10,000000+0200 RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
> 2017-08-23T09:38:10,000000+0200 NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16
> 2017-08-23T09:38:10,000000+0200 Offload RCU callbacks from CPUs: .
> 2065-04-14T17:16:20,287498+0200 Console: colour dummy device 80x25
> 2065-04-14T17:16:20,287498+0200 console [tty0] enabled
> 2065-04-14T17:16:20,287498+0200 console [ttyS0] enabled
>
Yes, you've pointed this out before and I have a solution for dmesg.
> I would like to see patches for at least one tool (dmesg)
> that would make it working properly. It will prove that
> the kernel side allows userspace to handle this
> a reasonable way.
>
>
>> +
>> + printk_time = _printk_time;
>> + if (printk_time_source > PRINTK_TIME_DISABLE)
>
> Ah, this actually prevents replacing the printk_get_ts
> with local_clock. IMHO, it will be more clear and safe
> if we handle this in printk_set_timestamp() as suggested above.
>
FIXED.
>
>> + printk_set_timestamp();
>>
>> +
>> + pr_info("printk: timestamp set to %s\n",
>> + timestamp_sources_str[printk_time]);
>> + return 0;
>> +}
>> +
>> +static int printk_time_get(char *buffer, const struct kernel_param *kp)
>> +{
>> + return scnprintf(buffer, PAGE_SIZE, "%s",
>> + timestamp_sources_str[printk_time]);
>> +}
>
> I know that it would make the code more complicated. But
> I really like the approach used by /sys/power/disk or
> /sys/power/pm_test. They list all possible values
> and put the selected one into [] brackets.
>
I like the idea too, however, I think that complicates things with userspace
(which as you point out is something that we really need to be concerned
with). I am using /sys/modules/printk/parameters/time to indicate the
timestamp to userspace.
With my code, userspace would see "realtime" or "disabled". With your
suggested change they would see "disabled [realtime]". I think that
file needs to be a simple as possible and be a single entry for userspace
to consume. IMHO.
> Well, this might be done in a separate patch.
> I am not 100% sure that this actually does not break some
> rules for sysfs.
>
I don't see anything that says I must list every available option
but I only did a quick overview of the docs.
>
>> +
>> +static struct kernel_param_ops printk_time_ops = {
>> + .set = printk_time_set,
>> + .get = printk_time_get,
>
> It seems that an often used naming scheme is:
>
> .set = param_set_<param_name>
> .get = param_get_<param_name>
>
> Please, use it. It think that they make the meaning more obvious.
FIXED.
>
>> +};
>> +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_DISABLE)
>> return 0;
>>
>> rem_nsec = do_div(ts, 1000000000);
>> @@ -1643,7 +1776,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;
>> }
>>
>> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
>> index 98fe715522e8..0262770d6bc5 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"
>> + 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"
>> + 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"
>> + help
>> + Selecting this option causes the time stamps of printk() to be
>> + stamped with the adjusted realtime clock.
>
> It might make sense to point out that this is in UTC. I would mention
> this also in kernel-parameters. The discussion about an older version
> of this patchset suggests that this is not widely known.
>
FIXED in Kconfig & kernel-parameters.txt.
>
>> +endchoice
>> +
>> +config PRINTK_TIME_TYPE
>> + int
>> + depends on PRINTK
>> + range 1 5
>> + default 1 if !PRINTK_TIME
>> + default 2 if PRINTK_TIME_LOCAL
>> + default 3 if PRINTK_TIME_BOOT
>> + default 4 if PRINTK_TIME_MONO
>> + default 5 if PRINTK_TIME_REAL
>
> I am surprised that this even force PRINTK_TIME_TYPE to be
> in sync with the above choice. I would expect that "default"
> would still allow to set another value here and make
> it inconsistent. For example I tried to define:
>
Aside: I have changed to 0-4 range to remove "undefined" from
timestamp_sources_str[], and modified additional code to reflect the change.
> CONFIG_PRINTK_TIME=y
> CONFIG_PRINTK_TIME_LOCAL=y
> CONFIG_PRINTK_TIME_TYPE=4
>
> But "make" automatically fixed this to
>
> CONFIG_PRINTK_TIME=y
> CONFIG_PRINTK_TIME_LOCAL=y
> CONFIG_PRINTK_TIME_TYPE=2
>
> which is great. I hope that we could rely on this.
>
Yes, I think this among the reasons why peterz & John recommended this method.
>
> Best Regards,
> Petr
>
> PS: I agree that this functionality would be useful. My main
> concern is how to "always" display the time correctly, especially
> by userpace tools. It does not make sense to solve the other
> rather cosmetic probles until we have a good answer for
> the main one.
>
[1]: Mark ... this is an interesting idea we should pursue in the future,
as I think it would nicely solve your request for the timestamp info.
> Note that we could store the information about the time
> type for each line in struct printk_log for each line.
> There are two unused bits in log_flags (one is LOG_NOCONS).
> The question is how to pass it to userspace.
>
P.
--
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
