[RFC] Prepend timestamp in msgbuf

From: Arnaud Lacombe <lacombar_at_gmail.com>

Hi folks,

There is many case recently when I really wished timestamp were present in the
post-mortem msgbuf. Such situation could be when userland application segfault
potentially triggering a panic/crash, or have information about the time-wise
location of a given message (kernel or userland).

Attached patch is available in the git repository at:
  git://github.com/lacombar/freebsd.git master/topic/msgbuf-timestamp

Arnaud Lacombe (3):
      msgbuf(4): convert `msg_needsnl' to a bit flag
      msgbuf(4): add logic to prepend timestamp on new line
      msgbuf(4): add a sysctl to toggle timestamp prepend

 sys/kern/subr_msgbuf.c |   53 ++++++++++++++++++++++++++++++++++++++++-------
 sys/sys/msgbuf.h       |    4 ++-
 2 files changed, 48 insertions(+), 9 deletions(-)

diff --git a/sys/kern/subr_msgbuf.c b/sys/kern/subr_msgbuf.c
index cd9c551..b2f0e1a 100644
--- a/sys/kern/subr_msgbuf.c
+++ b/sys/kern/subr_msgbuf.c
_at__at_ -34,6 +34,7 _at__at_
 #include <sys/lock.h>
 #include <sys/mutex.h>
 #include <sys/msgbuf.h>
+#include <sys/sysctl.h>
 
 /*
  * Maximum number conversion buffer length: uintmax_t in base 2, plus <>
_at__at_ -47,6 +48,13 _at__at_
 static u_int msgbuf_cksum(struct msgbuf *mbp);
 
 /*
+ *
+ */
+static int msgbuf_show_timestamp = 1;
+SYSCTL_INT(_kern, OID_AUTO, msgbuf_show_timestamp, CTLFLAG_RW,
+    &msgbuf_show_timestamp, 0, "Show timestamp in msgbuf");
+
+/*
  * Initialize a message buffer of the specified size at the specified
  * location. This also zeros the buffer area.
  */
_at__at_ -60,7 +68,7 _at__at_ msgbuf_init(struct msgbuf *mbp, void *ptr, int size)
 	msgbuf_clear(mbp);
 	mbp->msg_magic = MSG_MAGIC;
 	mbp->msg_lastpri = -1;
-	mbp->msg_needsnl = 0;
+	mbp->msg_flags = 0;
 	bzero(&mbp->msg_lock, sizeof(mbp->msg_lock));
 	mtx_init(&mbp->msg_lock, "msgbuf", NULL, MTX_SPIN);
 }
_at__at_ -95,7 +103,7 _at__at_ msgbuf_reinit(struct msgbuf *mbp, void *ptr, int size)
 
 	mbp->msg_lastpri = -1;
 	/* Assume that the old message buffer didn't end in a newline. */
-	mbp->msg_needsnl = 1;
+	mbp->msg_flags |= MSGBUF_NEEDNL;
 	bzero(&mbp->msg_lock, sizeof(mbp->msg_lock));
 	mtx_init(&mbp->msg_lock, "msgbuf", NULL, MTX_SPIN);
 }
_at__at_ -134,7 +142,7 _at__at_ msgbuf_getcount(struct msgbuf *mbp)
  * The caller should hold the message buffer spinlock.
  */
 static inline void
-msgbuf_do_addchar(struct msgbuf *mbp, u_int *seq, int c)
+__msgbuf_do_addchar(struct msgbuf *mbp, u_int *seq, int c)
 {
 	u_int pos;
 
_at__at_ -149,6 +157,34 _at__at_ msgbuf_do_addchar(struct msgbuf *mbp, u_int *seq, int c)
 	*seq = MSGBUF_SEQNORM(mbp, *seq + 1);
 }
 
+static inline void
+msgbuf_do_addchar(struct msgbuf *mbp, u_int *seq, int c)
+{
+
+	if (msgbuf_show_timestamp && mbp->msg_flags & MSGBUF_NEXT_NEW_LINE) {
+		char buf[32], *bufp;
+		struct timespec ts;
+		int err;
+
+		buf[0] = '\0';
+		getnanouptime(&ts);
+		err = snprintf(buf, sizeof buf, "[%d.%ld] ", ts.tv_sec, ts.tv_nsec / 1000);
+
+		bufp = buf;
+		while (*bufp != '\0') {
+			__msgbuf_do_addchar(mbp, seq, *bufp);
+			bufp++;
+		}
+
+		mbp->msg_flags &= ~MSGBUF_NEXT_NEW_LINE;
+	}
+
+	__msgbuf_do_addchar(mbp, seq, c);
+
+	if (c == '\n')
+		mbp->msg_flags |= MSGBUF_NEXT_NEW_LINE;
+}
+
 /*
  * Append a character to a message buffer.
  */
_at__at_ -207,10 +243,10 _at__at_ msgbuf_addstr(struct msgbuf *mbp, int pri, char *str, int filter_cr)
 	 * did not end with a newline.  If that is the case, we need to
 	 * insert a newline before this string.
 	 */
-	if (mbp->msg_lastpri != pri && mbp->msg_needsnl != 0) {
+	if (mbp->msg_lastpri != pri && (mbp->msg_flags & MSGBUF_NEEDNL) != 0) {
 
 		msgbuf_do_addchar(mbp, &seq, '\n');
-		mbp->msg_needsnl = 0;
+		mbp->msg_flags &= ~MSGBUF_NEEDNL;
 	}
 
 	for (i = 0; i < len; i++) {
_at__at_ -219,7 +255,7 _at__at_ msgbuf_addstr(struct msgbuf *mbp, int pri, char *str, int filter_cr)
 		 * (and therefore prefix_len != 0), then we need a priority
 		 * prefix for this line.
 		 */
-		if (mbp->msg_needsnl == 0 && prefix_len != 0) {
+		if ((mbp->msg_flags & MSGBUF_NEEDNL) == 0 && prefix_len != 0) {
 			int j;
 
 			for (j = 0; j < prefix_len; j++)
_at__at_ -242,9 +278,9 _at__at_ msgbuf_addstr(struct msgbuf *mbp, int pri, char *str, int filter_cr)
 		 * we need to insert a new prefix or insert a newline later.
 		 */
 		if (str[i] == '\n')
-			mbp->msg_needsnl = 0;
+			mbp->msg_flags &= ~MSGBUF_NEEDNL;
 		else
-			mbp->msg_needsnl = 1;
+			mbp->msg_flags |= MSGBUF_NEEDNL;
 
 		msgbuf_do_addchar(mbp, &seq, str[i]);
 	}
_at__at_ -395,3 +431,4 _at__at_ msgbuf_copy(struct msgbuf *src, struct msgbuf *dst)
 	while ((c = msgbuf_getchar(src)) >= 0)
 		msgbuf_addchar(dst, c);
 }
+
diff --git a/sys/sys/msgbuf.h b/sys/sys/msgbuf.h
index 67f80a5..639ed72 100644
--- a/sys/sys/msgbuf.h
+++ b/sys/sys/msgbuf.h
_at__at_ -46,7 +46,9 _at__at_ struct msgbuf {
 	u_int	   msg_cksum;		/* checksum of contents */
 	u_int	   msg_seqmod;		/* range for sequence numbers */
 	int	   msg_lastpri;		/* saved priority value */
-	int	   msg_needsnl;		/* set when newline needed */
+	uint32_t   msg_flags;
+#define MSGBUF_NEEDNL		0x01	/* set when newline needed */
+#define MSGBUF_NEXT_NEW_LINE	0x02
 	struct mtx msg_lock;		/* mutex to protect the buffer */
 };