lkml.org 
[lkml]   [2017]   [Aug]   [7]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH v3] printk: Add boottime and real timestamps
On Thu, Aug 03, 2017 at 09:18:44PM -0400, Prarit Bhargava wrote:
> index fc47863f629c..8f093dd0a733 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1202,8 +1204,119 @@ 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;
> +static int printk_time_setting;
> +
> +/**
> + * enum printk_time_type - Timestamp types for printk() messages.
> + * @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 in the call to ktime_get_log_ts()
> + * in printk_get_ts() below.

You can expand on this or the actual routines that use this in kdoc form.

> + */
> +enum printk_time_type {
> + PRINTK_TIME_DISABLE = 0,
> + PRINTK_TIME_LOCAL = 1,
> + PRINTK_TIME_BOOT = 2,
> + PRINTK_TIME_MONO = 3,
> + PRINTK_TIME_REAL = 4,
> +};
> +
> +static const char * const printk_time_str[5] = {
> + "disabled",
> + "local hardware",
> + "boottime",
> + "monotonic",
> + "realtime",
> +};
> +
> +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;
> +
> + switch (param[0]) {
> + case '0':
> + case 'n':
> + case 'N':
> + _printk_time = PRINTK_TIME_DISABLE;
> + break;
> + case '1':
> + case 'y':
> + case 'Y':
> + _printk_time = PRINTK_TIME_LOCAL;
> + break;
> + case '2':
> + _printk_time = PRINTK_TIME_BOOT;
> + break;
> + case '3':
> + _printk_time = PRINTK_TIME_MONO;
> + break;
> + case '4':
> + _printk_time = PRINTK_TIME_REAL;
> + 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 == PRINTK_TIME_DISABLE) {
> + 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(disabled) or %d(%s) ",
> + printk_time_setting,
> + printk_time_str[printk_time_setting]);
> + return -EINVAL;
> + }
> +
> + printk_time = _printk_time;
> + pr_info("printk: timestamp set to %d(%s).",
> + printk_time, printk_time_str[printk_time]);
> + return 0;
> +}
> +
> +static int printk_time_get(char *buffer, const struct kernel_param *kp)
> +{
> + return scnprintf(buffer, PAGE_SIZE, "%d", printk_time);
> +}
> +
> +static struct kernel_param_ops printk_time_ops = {
> + .set = printk_time_set,
> + .get = printk_time_get,
> +};
> +module_param_cb(time, &printk_time_ops, NULL, 0644);
> +
> +static u64 printk_get_ts(void)
> +{
> + u64 mono, offset_real;
> +
> + if (printk_time <= PRINTK_TIME_LOCAL)
> + return local_clock();
> +
> + if (printk_time == PRINTK_TIME_BOOT)
> + return ktime_get_boot_log_ts();
> +
> + mono = ktime_get_real_log_ts(&offset_real);
> +
> + if (printk_time == PRINTK_TIME_MONO)
> + return mono;
> +
> + return mono + offset_real;
> +}
>
> static size_t print_time(u64 ts, char *buf)
> {
> @@ -1643,7 +1756,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;
> }
>
> @@ -1873,6 +1986,8 @@ static size_t msg_print_text(const struct printk_log *msg,
> bool syslog, char *buf, size_t size) { return 0; }
> static bool suppress_message_printing(int level) { return false; }
>
> +static int printk_time;
> +static int printk_time_setting;
> #endif /* CONFIG_PRINTK */
>
> #ifdef CONFIG_EARLY_PRINTK
>
> @@ -2659,6 +2774,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;
> +

Note printk_late_init() is a late_initcall(). This means if the
printk_time_setting was disabled it will take a while to enable it. Enabling it
is done at the device_initcall(), so if printk setting is disabled but a user
enables it with a toggle of the module param there is a period of time during
which time resolution would be different. Perhaps for some this is not useful
information but for others I think this would be very valuable.

There is also something to say about the time in between initializing access
to ktime_get_mono_fast_ns(), how early is this reliable?

All these things could be mentioned on the documentation.

Luis

\
 
 \ /
  Last update: 2017-08-07 19:15    [W:0.117 / U:1.204 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site