lkml.org 
[lkml]   [2018]   [Jan]   [29]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: [GIT pull] printk updates for 4.15
From
Date
Any movement on the following proposal? tglx@ do you have an update?

-- Mark

On 11/14/2017 02:50 PM, Thomas Gleixner wrote:
> On Tue, 14 Nov 2017, Linus Torvalds wrote:
>> I'd suggest simply adding another time to the internal 'struct
>> printk_log' (and probably just set it in "log_store()").
>>
>> Doesn't that seem much simpler and more targeted?
>>
>> And exactly because it's targeted and only changes that one thing, now
>> people that don't run Android, and have systemd that actually looks at
>> that timestamp, can _also_ enable that wall clock output if they want
>> to, without it impacting timestamps at all.
>>
>> In fact, I would expect that at that point you actually would want to
>> have multiple different formats that don't necessarily have anything
>> to do with the clock source, but simply with the formatting.
>>
>> Do you want wallclock to be shown in UTC? Do you want to show it in
>> the system timezeone? Do you want to always show the full resolution,
>> or do you want to show something that takes the previous log entry
>> into account, so it only shows the date if it has actually changed,
>> and maybe shows the time as just a delta if it is small?
>>
>> Because now it's clearly about the freeflowing _text_, not about the
>> timestamp that is processed by tools.
>>
>> The text field done by print_time() really is _that_ different from
>> the timestamp field that is exposed to tools.
>>
>> Yes, somebody might still be parsing it, and maybe then you need to
>> set that text field to a legacy format anyway, but at least it's a
>> whole lot easier to explain what's going on.
> Something like the untested patch below should do the storage and converts
> the primary timestamp from local_clock() to clock monotonic.
>
> The print out and /dev/kmsg is unchanged. That's a separate story.
>
> Thanks,
>
> tglx
>
> 8<-------------------
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -352,7 +352,11 @@ enum log_flags {
> };
>
> struct printk_log {
> - u64 ts_nsec; /* timestamp in nanoseconds */
> + /* Timestamps in nanoseconds */
> + union {
> + u64 ts_nsec;
> + struct timestamps ts;
> + };
> u16 len; /* length of entire record */
> u16 text_len; /* length of text buffer */
> u16 dict_len; /* length of dictionary buffer */
> @@ -578,7 +582,7 @@ static u32 truncate_msg(u16 *text_len, u
>
> /* 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,
> + enum log_flags flags, struct timestamps *ts,
> const char *dict, u16 dict_len,
> const char *text, u16 text_len)
> {
> @@ -621,10 +625,10 @@ static int log_store(int facility, int l
> msg->facility = facility;
> msg->level = level & 7;
> msg->flags = flags & 0x1f;
> - if (ts_nsec > 0)
> - msg->ts_nsec = ts_nsec;
> + if (ts && ts->mono > 0)
> + msg->ts = *ts;
> else
> - msg->ts_nsec = local_clock();
> + ktime_get_fast_timestamps(&msg->ts);
> memset(log_dict(msg) + dict_len, 0, pad_len);
> msg->len = size;
>
> @@ -687,7 +691,7 @@ static void append_char(char **pp, char
> static ssize_t msg_print_ext_header(char *buf, size_t size,
> struct printk_log *msg, u64 seq)
> {
> - u64 ts_usec = msg->ts_nsec;
> + u64 ts_usec = msg->ts.mono;
>
> do_div(ts_usec, 1000);
>
> @@ -1022,6 +1026,7 @@ void log_buf_vmcoreinfo_setup(void)
> */
> VMCOREINFO_STRUCT_SIZE(printk_log);
> VMCOREINFO_OFFSET(printk_log, ts_nsec);
> + VMCOREINFO_OFFSET(printk_log, ts);
> VMCOREINFO_OFFSET(printk_log, len);
> VMCOREINFO_OFFSET(printk_log, text_len);
> VMCOREINFO_OFFSET(printk_log, dict_len);
> @@ -1204,17 +1209,18 @@ static inline void boot_delay_msec(int l
> static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
> module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
>
> -static size_t print_time(u64 ts, char *buf)
> +static size_t print_time(const struct timestamps *ts, char *buf)
> {
> unsigned long rem_nsec;
> + u64 mono = ts->mono;
>
> if (!printk_time)
> return 0;
>
> - rem_nsec = do_div(ts, 1000000000);
> + rem_nsec = do_div(mono, 1000000000);
>
> if (!buf)
> - return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
> + return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)mono);
>
> return sprintf(buf, "[%5lu.%06lu] ",
> (unsigned long)ts, rem_nsec / 1000);
> @@ -1239,7 +1245,7 @@ static size_t print_prefix(const struct
> }
> }
>
> - len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
> + len += print_time(&msg->ts, buf ? buf + len : NULL);
> return len;
> }
>
> @@ -1599,7 +1605,7 @@ static struct cont {
> char buf[LOG_LINE_MAX];
> size_t len; /* length == 0 means unused buffer */
> struct task_struct *owner; /* task of first print*/
> - u64 ts_nsec; /* time of first print */
> + struct timestamps ts; /* time of first print */
> u8 level; /* log level of first message */
> u8 facility; /* log facility of first message */
> enum log_flags flags; /* prefix, newline flags */
> @@ -1610,7 +1616,7 @@ static void cont_flush(void)
> if (cont.len == 0)
> return;
>
> - log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
> + log_store(cont.facility, cont.level, cont.flags, &cont.ts,
> NULL, 0, cont.buf, cont.len);
> cont.len = 0;
> }
> @@ -1631,7 +1637,7 @@ static bool cont_add(int facility, int l
> cont.facility = facility;
> cont.level = level;
> cont.owner = current;
> - cont.ts_nsec = local_clock();
> + ktime_get_fast_timestamps(&cont.ts);
> cont.flags = flags;
> }
>
> @@ -1677,7 +1683,8 @@ static size_t log_output(int facility, i
> }
>
> /* Store it in the record log */
> - return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
> + return log_store(facility, level, lflags, NULL, dict, dictlen, text,
> + text_len);
> }
>
> asmlinkage int vprintk_emit(int facility, int level,
> --- a/include/linux/timekeeping.h
> +++ b/include/linux/timekeeping.h
> @@ -146,7 +146,19 @@ extern void timekeeping_inject_sleeptime
> * PPS accessor
> */
> extern void ktime_get_raw_and_real_ts64(struct timespec64 *ts_raw,
> - struct timespec64 *ts_real);
> + struct timespec64 *ts_real);
> +
> +/*
> + * struct timestanps - Simultaneous mono/boot/real timestamps
> + * @mono: Monotonic timestamp
> + * @boot: Boottime timestamp
> + * @real: Realtime timestamp
> + */
> +struct timestamps {
> + u64 mono;
> + u64 boot;
> + u64 real;
> +};
>
> /*
> * struct system_time_snapshot - simultaneous raw/real time capture with
> @@ -206,6 +218,9 @@ extern int get_device_system_crosststamp
> */
> extern void ktime_get_snapshot(struct system_time_snapshot *systime_snapshot);
>
> +/* NMI safe mono/boot/realtime timestamps */
> +extern void ktime_get_fast_timestamps(struct timestamps *snap);
> +
> /*
> * Persistent clock related interfaces
> */
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -496,29 +496,29 @@ u64 notrace ktime_get_boot_fast_ns(void)
> }
> EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
>
> -
> /*
> * See comment for __ktime_get_fast_ns() vs. timestamp ordering
> */
> -static __always_inline u64 __ktime_get_real_fast_ns(struct tk_fast *tkf)
> +static notrace u64 __ktime_get_real_fast(struct tk_fast *tkf, u64 *mono)
> {
> struct tk_read_base *tkr;
> + u64 basem, baser, delta;
> unsigned int seq;
> - u64 now;
>
> do {
> seq = raw_read_seqcount_latch(&tkf->seq);
> tkr = tkf->base + (seq & 0x01);
> - now = ktime_to_ns(tkr->base_real);
> + basem = ktime_to_ns(tkr->base);
> + baser = ktime_to_ns(tkr->base_real);
>
> - now += timekeeping_delta_to_ns(tkr,
> - clocksource_delta(
> - tk_clock_read(tkr),
> - tkr->cycle_last,
> - tkr->mask));
> + delta = timekeeping_delta_to_ns(tkr,
> + clocksource_delta(tk_clock_read(tkr),
> + tkr->cycle_last, tkr->mask));
> } while (read_seqcount_retry(&tkf->seq, seq));
>
> - return now;
> + if (mono)
> + *mono = basem + delta;
> + return baser + delta;
> }
>
> /**
> @@ -526,11 +526,25 @@ static __always_inline u64 __ktime_get_r
> */
> u64 ktime_get_real_fast_ns(void)
> {
> - return __ktime_get_real_fast_ns(&tk_fast_mono);
> + return __ktime_get_real_fast(&tk_fast_mono, NULL);
> }
> EXPORT_SYMBOL_GPL(ktime_get_real_fast_ns);
>
> /**
> + * ktime_get_fast_timestamps: - NMI safe timestamps
> + * @snap: Pointer to timestamp storage
> + *
> + * Stores clock monotonic, boottime and realtime time stamps
> + */
> +void ktime_get_fast_timestamps(struct timestamps *snap)
> +{
> + struct timekeeper *tk = &tk_core.timekeeper;
> +
> + snap->real = __ktime_get_real_fast(&tk_fast_mono, &snap->mono);
> + snap->boot = snap->mono + ktime_to_ns(tk->offs_boot);
> +}
> +
> +/**
> * halt_fast_timekeeper - Prevent fast timekeeper from accessing clocksource.
> * @tk: Timekeeper to snapshot.
> *

\
 
 \ /
  Last update: 2018-01-29 21:37    [W:0.174 / U:0.420 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site