[RFC] printk: add relative printk timing support

[RFC] printk: add relative printk timing support

[Sasha Levin]

This patch adds support for relative timestamps in printk output.

First, this is how it looks now:

[  120.001386] foo
[  181.036862] bar
[  186.070696] zoot
[  196.288022] foo
[  257.415895] bar
[  257.416580] zoot

Next, with Linus' suggestion (Month and date, no seconds):

[May 17 14:13] foo
[May 17 14:14] bar
[+05.00026906] zoot
[+10.00054898] foo
[May 17 14:15] bar
[+00.00000668] zoot

And Peter's suggestion (MS accurate absolute time):

[14:16:57.970] foo
[14:17:59.063] bar
[+05.00032139] zoot
[+10.00336079] foo
[14:19:15.677] bar
[+00.00001905] zoot

Todo:
 - Can we get rid of the spinlock somehow? I tried using atomic64_t, but got
hit with races causing odd prints.
 - Do we want to make the 60 second "timeout" for printing abs time
configurable?
- Are there any other formats we would want to add?

Suggested-by: Linus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: Sasha Levin <levinsasha928@gmail.com>
---
 kernel/printk.c |   50 ++++++++++++++++++++++++++++++++++++++++++++------
 1 files changed, 44 insertions(+), 6 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 32462d2..9d008e5 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -779,11 +779,12 @@ static int check_syslog_permissions(int type, bool from_file)
 }
 
 #if defined(CONFIG_PRINTK_TIME)
-static bool printk_time = 1;
+static int printk_time = 1;
 #else
-static bool printk_time;
+static int printk_time;
 #endif
-module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
+module_param_named(time, printk_time, int, S_IRUGO | S_IWUSR);
+static DEFINE_SPINLOCK(printk_time_rel);
 
 static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
 {
@@ -801,16 +802,53 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
 		}
 	}
 
-	if (printk_time) {
+	if (printk_time == 1) {
 		if (buf) {
 			unsigned long long ts = msg->ts_nsec;
-			unsigned long rem_nsec = do_div(ts, 1000000000);
+			unsigned long rem_nsec = do_div(ts, NSEC_PER_SEC);
 
 			len += sprintf(buf + len, "[%5lu.%06lu] ",
-					 (unsigned long) ts, rem_nsec / 1000);
+					 (unsigned long) ts, rem_nsec / NSEC_PER_USEC);
 		} else {
 			len += 15;
 		}
+	} else if (printk_time == 2 || printk_time == 3) {
+		static unsigned long long last_print;
+		unsigned long long ts = msg->ts_nsec;
+		unsigned long rem_nsec;
+		bool rel = 0;
+		static const char *months[12] = {"Jan", "Feb", "Mar", "Apr",
+						"May", "Jun", "Jul", "Aug",
+						"Sep", "Oct", "Nov", "Dec",};
+
+		if (!buf)
+			return len + 15;
+
+		spin_lock(&printk_time_rel);
+		if ((ts - last_print) / NSEC_PER_SEC < 60) {
+			rel = 1;
+			ts -= last_print;
+		}
+		last_print = msg->ts_nsec;
+		spin_unlock(&printk_time_rel);
+
+		rem_nsec = do_div(ts, NSEC_PER_SEC);
+		if (rel) {
+			len += sprintf(buf + len, "[%+03d.%08lu] ",
+					(int)ts, rem_nsec / NSEC_PER_USEC);
+		} else {
+			struct tm tm;
+
+			time_to_tm(get_seconds(), 0, &tm);
+			if (printk_time == 2)
+				len += sprintf(buf + len, "[%s %02d %02d:%02d] ",
+						months[tm.tm_mon], tm.tm_mday,
+						tm.tm_hour, tm.tm_min);
+			if (printk_time == 3)
+				len += sprintf(buf + len, "[%02d:%02d:%02d.%03lu] ",
+						tm.tm_hour, tm.tm_min, tm.tm_sec,
+						rem_nsec / NSEC_PER_MSEC);
+		}
 	}
 
 	return len;
-- 
1.7.8.6

Re: [RFC] printk: add relative printk timing support

[Kay Sievers]

On Thu, May 17, 2012 at 5:02 PM, Sasha Levin <levinsasha928@gmail.com> wrote:
> This patch adds support for relative timestamps in printk output.


> Next, with Linus' suggestion (Month and date, no seconds):
>
> [May 17 14:13] foo

Any idea how to handle suspend cycles right? The wall clock time
translation might not be correct anymore, or is that covered?

Also, we currently record local CPU times, they are only guaranteed to
be monotonic for the same CPU, not across them. So we could see
negative offsets?

Kay

Re: [RFC] printk: add relative printk timing support

[Kay Sievers]

On Thu, May 17, 2012 at 5:02 PM, Sasha Levin <levinsasha928@gmail.com> wrote:
> This patch adds support for relative timestamps in printk output.

>  static size_t print_prefix(const struct log *msg, bool syslog, char *buf)

> +       } else if (printk_time == 2 || printk_time == 3) {
> +               static unsigned long long last_print;

We can have multiple concurrent users of the relative time calculation, right?

I guess the last_print needs to be localized to every possible user
and concurrent instance: syslog(dmesg),  syslog(/proc/kmsg), console
output, to not race against each other?

Kay