[PATCH V2] printk: add sleep time into timestamp

[PATCH V2] printk: add sleep time into timestamp

[Neil Zhang]

Add sleep time into timestamp to reflect the actual time since
sched_clock will be stopped during suspend.

Thanks John Stultz for suggestion to use monotonic_to_bootbased.

Signed-off-by: Neil Zhang <zhangwm@marvell.com>
---
 kernel/printk/printk.c |   16 ++++++++++++++--
 1 file changed, 14 insertions(+), 2 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 4dae9cb..121f792 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -250,6 +250,18 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
+static u64 print_clock(void)
+{
+	struct timespec	ts;
+	u64 ts_nsec = local_clock();
+
+	ts = ns_to_timespec(ts_nsec);
+	monotonic_to_bootbased(&ts);
+	ts_nsec = timespec_to_ns(&ts);
+
+	return ts_nsec;
+}
+
 /* cpu currently holding logbuf_lock */
 static volatile unsigned int logbuf_cpu = UINT_MAX;
 
@@ -349,7 +361,7 @@ static void log_store(int facility, int level,
 	if (ts_nsec > 0)
 		msg->ts_nsec = ts_nsec;
 	else
-		msg->ts_nsec = local_clock();
+		msg->ts_nsec = print_clock();
 	memset(log_dict(msg) + dict_len, 0, pad_len);
 	msg->len = sizeof(struct printk_log) + text_len + dict_len + pad_len;
 
@@ -1440,7 +1452,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
-		cont.ts_nsec = local_clock();
+		cont.ts_nsec = print_clock();
 		cont.flags = 0;
 		cont.cons = 0;
 		cont.flushed = false;
-- 
1.7.9.5

Re: [PATCH V2] printk: add sleep time into timestamp

[John Stultz]

On 03/31/2014 08:20 PM, Neil Zhang wrote:
> Add sleep time into timestamp to reflect the actual time since
> sched_clock will be stopped during suspend.
>
> Thanks John Stultz for suggestion to use monotonic_to_bootbased.
>
> Signed-off-by: Neil Zhang <zhangwm@marvell.com>
> ---
>  kernel/printk/printk.c |   16 ++++++++++++++--
>  1 file changed, 14 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 4dae9cb..121f792 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -250,6 +250,18 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
>  static char *log_buf = __log_buf;
>  static u32 log_buf_len = __LOG_BUF_LEN;
>  
> +static u64 print_clock(void)
> +{
> +	struct timespec	ts;
> +	u64 ts_nsec = local_clock();
> +
> +	ts = ns_to_timespec(ts_nsec);
> +	monotonic_to_bootbased(&ts);
> +	ts_nsec = timespec_to_ns(&ts);
> +

Note that this is still problematic as monotonic_to_bootbased currently
doesn't take the required locks to ensure it reads the data atomically.

If it were fixed to take the proper locks, this would risk a deadlock
since there are places where the timekeeping code takes a write on the
seqlock and then may call printk (or WARN_ON).

I suspect if this is going to be done, we need to have the timekeeping
provide the print_clock subsystem the boottime offset when it is changed
so the print_clock logic can manage this w/o grabbing timekeeping locks.
But as I mentioned in reply to Lei's similar patches, I'm not a huge fan
of the added complexity that will be required here when userspace like
syslog can timestamps kernel messages already (so additional rational
will be needed to move this forward).

thanks
-john