[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@xxxxxxxxxxxxxxxxxxxx>
Signed-off-by: Sasha Levin <levinsasha928@xxxxxxxxx>
---
 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

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/