Add a cnputs() function to write a string to the console with

a lock to prevent interspersed strings written from different CPUs
at the same time.

To avoid putting a buffer on the stack or having to malloc one,
space is incorporated in the per-cpu structure. The buffer
size if 128 bytes; chosen because it's the next power of 2 size
up from 80 characters.

String writes to the console are buffered up the end of the line
or until the buffer fills. Then the buffer is flushed to all
console devices.

Existing low level console output via cnputc() is unaffected by
this change. ithread calls to log() are also unaffected to avoid
blocking those threads.

A minor change to the behaviour in a panic situation is that
console output will still be buffered, but won't be written to
a tty as before. This should prevent interspersed panic output
as a number of CPUs panic before we end up single threaded
running ddb.

Reviewed by:	scottl, jhb
MFC after:	2 weeks

10 files changed, 109 insertions, 17 deletions

diff --git a/sys/amd64/amd64/genassym.c b/sys/amd64/amd64/genassym.c
index e4fd196..705e3fd 100644
--- a/sys/amd64/amd64/genassym.c
+++ b/sys/amd64/amd64/genassym.c
@@ -185,6 +185,7 @@ ASSYM(PC_CURTHREAD, offsetof(struct pcpu, pc_curthread));
 ASSYM(PC_FPCURTHREAD, offsetof(struct pcpu, pc_fpcurthread));
 ASSYM(PC_IDLETHREAD, offsetof(struct pcpu, pc_idlethread));
 ASSYM(PC_CURPCB, offsetof(struct pcpu, pc_curpcb));
+ASSYM(PC_CONS_BUFR, offsetof(struct pcpu, pc_cons_bufr));
 ASSYM(PC_CPUID, offsetof(struct pcpu, pc_cpuid));
 ASSYM(PC_SCRATCH_RSP, offsetof(struct pcpu, pc_scratch_rsp));
 ASSYM(PC_CURPMAP, offsetof(struct pcpu, pc_curpmap));
diff --git a/sys/arm/arm/genassym.c b/sys/arm/arm/genassym.c
index b179e74..f61e1f7 100644
--- a/sys/arm/arm/genassym.c
+++ b/sys/arm/arm/genassym.c
@@ -69,6 +69,7 @@ ASSYM(PCB_R12, offsetof(struct pcb, un_32.pcb32_r12));
 ASSYM(PCB_PC, offsetof(struct pcb, un_32.pcb32_pc));
 ASSYM(PCB_SP, offsetof(struct pcb, un_32.pcb32_sp));
 
+ASSYM(PC_CONS_BUFR, offsetof(struct pcpu, pc_cons_bufr));
 ASSYM(PC_CURPCB, offsetof(struct pcpu, pc_curpcb));
 ASSYM(PC_CURTHREAD, offsetof(struct pcpu, pc_curthread));
 ASSYM(M_LEN, offsetof(struct mbuf, m_len));
diff --git a/sys/i386/i386/genassym.c b/sys/i386/i386/genassym.c
index ca24402..01fb5fa 100644
--- a/sys/i386/i386/genassym.c
+++ b/sys/i386/i386/genassym.c
@@ -195,6 +195,7 @@ ASSYM(PC_COMMON_TSSD, offsetof(struct pcpu, pc_common_tssd));
 ASSYM(PC_TSS_GDT, offsetof(struct pcpu, pc_tss_gdt));
 ASSYM(PC_FSGS_GDT, offsetof(struct pcpu, pc_fsgs_gdt));
 ASSYM(PC_CURRENTLDT, offsetof(struct pcpu, pc_currentldt));
+ASSYM(PC_CONS_BUFR, offsetof(struct pcpu, pc_cons_bufr));
 ASSYM(PC_CPUID, offsetof(struct pcpu, pc_cpuid));
 ASSYM(PC_CURPMAP, offsetof(struct pcpu, pc_curpmap));
 ASSYM(PC_PRIVATE_TSS, offsetof(struct pcpu, pc_private_tss));
diff --git a/sys/ia64/ia64/genassym.c b/sys/ia64/ia64/genassym.c
index 8e988b6..cee754c 100644
--- a/sys/ia64/ia64/genassym.c
+++ b/sys/ia64/ia64/genassym.c
@@ -91,6 +91,7 @@ ASSYM(MC_SPECIAL_RNAT,	offsetof(mcontext_t, mc_special.rnat));
 ASSYM(PAGE_SHIFT,	PAGE_SHIFT);
 ASSYM(PAGE_SIZE,	PAGE_SIZE);
 
+ASSYM(PC_CONS_BUFR,	offsetof(struct pcpu, pc_cons_bufr));
 ASSYM(PC_CPUID,		offsetof(struct pcpu, pc_cpuid));
 ASSYM(PC_CURRENT_PMAP,	offsetof(struct pcpu, pc_current_pmap));
 ASSYM(PC_CURTHREAD,	offsetof(struct pcpu, pc_curthread));
diff --git a/sys/kern/subr_prf.c b/sys/kern/subr_prf.c
index bef5566..b6ffc91 100644
--- a/sys/kern/subr_prf.c
+++ b/sys/kern/subr_prf.c
@@ -78,6 +78,10 @@ struct putchar_arg {
 	int	flags;
 	int	pri;
 	struct	tty *tty;
+	char	*p_bufr;
+	size_t	n_bufr;
+	char	*p_next;
+	size_t	remain;
 };
 
 struct snprintf_arg {
@@ -92,7 +96,6 @@ static void  putchar(int ch, void *arg);
 static char *ksprintn(char *nbuf, uintmax_t num, int base, int *len, int upper);
 static void  snprintf_func(int ch, void *arg);
 
-static int consintr = 1;		/* Ok to handle console interrupts? */
 static int msgbufmapped;		/* Set when safe to use msgbuf */
 int msgbuftrigger;
 
@@ -234,6 +237,7 @@ log(int level, const char *fmt, ...)
 	pca.tty = NULL;
 	pca.pri = level;
 	pca.flags = log_open ? TOLOG : TOCONS;
+	pca.p_bufr = NULL;
 
 	va_start(ap, fmt);
 	kvprintf(fmt, putchar, &pca, 10, ap);
@@ -284,43 +288,96 @@ int
 printf(const char *fmt, ...)
 {
 	va_list ap;
-	int savintr;
 	struct putchar_arg pca;
 	int retval;
 
-	savintr = consintr;		/* disable interrupts */
-	consintr = 0;
+	critical_enter();
+
 	va_start(ap, fmt);
 	pca.tty = NULL;
 	pca.flags = TOCONS | TOLOG;
 	pca.pri = -1;
+	pca.p_bufr = (char *) PCPU_PTR(cons_bufr);
+	pca.p_next = pca.p_bufr;
+	pca.n_bufr = PCPU_CONS_BUFR;
+	pca.remain = PCPU_CONS_BUFR;
+	*pca.p_next = '\0';
+
 	retval = kvprintf(fmt, putchar, &pca, 10, ap);
 	va_end(ap);
+
+	/* Write any buffered console output: */
+	if (*pca.p_bufr != '\0')
+		cnputs(pca.p_bufr);
+
 	if (!panicstr)
 		msgbuftrigger = 1;
-	consintr = savintr;		/* reenable interrupts */
+
+	critical_exit();
+
 	return (retval);
 }
 
 int
 vprintf(const char *fmt, va_list ap)
 {
-	int savintr;
 	struct putchar_arg pca;
 	int retval;
 
-	savintr = consintr;		/* disable interrupts */
-	consintr = 0;
+	critical_enter();
+
 	pca.tty = NULL;
 	pca.flags = TOCONS | TOLOG;
 	pca.pri = -1;
+	pca.p_bufr = (char *) PCPU_PTR(cons_bufr);
+	pca.p_next = pca.p_bufr;
+	pca.n_bufr = PCPU_CONS_BUFR;
+	pca.remain = PCPU_CONS_BUFR;
+	*pca.p_next = '\0';
+
 	retval = kvprintf(fmt, putchar, &pca, 10, ap);
+
+	/* Write any buffered console output: */
+	if (*pca.p_bufr != '\0')
+		cnputs(pca.p_bufr);
+
 	if (!panicstr)
 		msgbuftrigger = 1;
-	consintr = savintr;		/* reenable interrupts */
+
+	critical_exit();
+
 	return (retval);
 }
 
+static void
+putcons(int c, struct putchar_arg *ap)
+{
+	/* Check if no console output buffer was provided. */
+	if (ap->p_bufr == NULL)
+		/* Output direct to the console. */
+		cnputc(c);
+	else {
+		/* Buffer the character: */
+		if (c == '\n') {
+			*ap->p_next++ = '\r';
+			ap->remain--;
+		}
+		*ap->p_next++ = c;
+		ap->remain--;
+
+		/* Always leave the buffer zero terminated. */
+		*ap->p_next = '\0';
+
+		/* Check if the buffer needs to be flushed. */
+		if (ap->remain < 3 || c == '\n') {
+			cnputs(ap->p_bufr);
+			ap->p_next = ap->p_bufr;
+			ap->remain = ap->n_bufr;
+			*ap->p_next = '\0';
+		}
+	}
+}
+
 /*
  * Print a character on console or users terminal.  If destination is
  * the console then the last bunch of characters are saved in msgbuf for
@@ -331,17 +388,15 @@ putchar(int c, void *arg)
 {
 	struct putchar_arg *ap = (struct putchar_arg*) arg;
 	struct tty *tp = ap->tty;
-	int consdirect, flags = ap->flags;
+	int flags = ap->flags;
 
-	consdirect = ((flags & TOCONS) && constty == NULL);
 	/* Don't use the tty code after a panic or while in ddb. */
-	if (panicstr)
-		consdirect = 1;
-	if (kdb_active)
-		consdirect = 1;
-	if (consdirect) {
+	if (kdb_active) {
 		if (c != '\0')
 			cnputc(c);
+	} else if (panicstr || ((flags & TOCONS) && constty == NULL)) {
+		if (c != '\0')
+			putcons(c, ap);
 	} else {
 		if ((flags & TOTTY) && tp != NULL)
 			tputchar(c, tp);
@@ -349,7 +404,7 @@ putchar(int c, void *arg)
 			if (constty != NULL)
 				msgbuf_addchar(&consmsgbuf, c);
 			if (always_console_output && c != '\0')
-				cnputc(c);
+				putcons(c, ap);
 		}
 	}
 	if ((flags & TOLOG))
diff --git a/sys/kern/tty_cons.c b/sys/kern/tty_cons.c
index f65f7ad..c0f8692 100644
--- a/sys/kern/tty_cons.c
+++ b/sys/kern/tty_cons.c
@@ -41,6 +41,8 @@ __FBSDID("$FreeBSD$");
 
 #include <sys/param.h>
 #include <sys/systm.h>
+#include <sys/lock.h>
+#include <sys/mutex.h>
 #include <sys/conf.h>
 #include <sys/cons.h>
 #include <sys/fcntl.h>
@@ -117,6 +119,8 @@ static u_char console_pausing;		/* pause after each line during probe */
 static char *console_pausestr=
 "<pause; press any key to proceed to next line or '.' to end pause mode>";
 struct tty *constty;			/* pointer to console "window" tty */
+static struct mtx cnputs_mtx;		/* Mutex for cnputs(). */
+static int use_cnputs_mtx = 0;		/* != 0 if cnputs_mtx locking reqd. */
 
 static void constty_timeout(void *arg);
 
@@ -639,6 +643,24 @@ cnputc(int c)
 	}
 }
 
+void
+cnputs(char *p)
+{
+	int c;
+	int unlock_reqd = 0;
+
+	if (use_cnputs_mtx) {
+		mtx_lock_spin(&cnputs_mtx);
+		unlock_reqd = 1;
+	}
+
+	while ((c = *p++) != '\0')
+		cnputc(c);
+
+	if (unlock_reqd)
+		mtx_unlock_spin(&cnputs_mtx);
+}
+
 static int consmsgbuf_size = 8192;
 SYSCTL_INT(_kern, OID_AUTO, consmsgbuf_size, CTLFLAG_RW, &consmsgbuf_size, 0,
     "");
@@ -708,6 +730,9 @@ cn_drvinit(void *unused)
 {
 
 	make_dev(&cn_cdevsw, 0, UID_ROOT, GID_WHEEL, 0600, "console");
+
+	mtx_init(&cnputs_mtx, "cnputs_mtx", NULL, MTX_SPIN | MTX_NOWITNESS);
+	use_cnputs_mtx = 1;
 }
 
 SYSINIT(cndev, SI_SUB_DRIVERS, SI_ORDER_MIDDLE, cn_drvinit, NULL)
diff --git a/sys/powerpc/powerpc/genassym.c b/sys/powerpc/powerpc/genassym.c
index 63719cc..80deb8e 100644
--- a/sys/powerpc/powerpc/genassym.c
+++ b/sys/powerpc/powerpc/genassym.c
@@ -55,6 +55,7 @@
 #include <machine/pmap.h>
 #include <machine/sigframe.h>
 
+ASSYM(PC_CONS_BUFR, offsetof(struct pcpu, pc_cons_bufr));
 ASSYM(PC_CURTHREAD, offsetof(struct pcpu, pc_curthread));
 ASSYM(PC_CURPCB, offsetof(struct pcpu, pc_curpcb));
 ASSYM(PC_CURPMAP, offsetof(struct pcpu, pc_curpmap));
diff --git a/sys/sparc64/sparc64/genassym.c b/sys/sparc64/sparc64/genassym.c
index fc79c6b..5639e3e 100644
--- a/sys/sparc64/sparc64/genassym.c
+++ b/sys/sparc64/sparc64/genassym.c
@@ -198,6 +198,7 @@ ASSYM(HASH_ENTRY_SHIFT, HASH_ENTRY_SHIFT);
 
 ASSYM(V_INTR, offsetof(struct vmmeter, v_intr));
 
+ASSYM(PC_CONS_BUFR, offsetof(struct pcpu, pc_cons_bufr));
 ASSYM(PC_CURTHREAD, offsetof(struct pcpu, pc_curthread));
 ASSYM(PC_CURPCB, offsetof(struct pcpu, pc_curpcb));
 ASSYM(PC_CPUID, offsetof(struct pcpu, pc_cpuid));
diff --git a/sys/sys/cons.h b/sys/sys/cons.h
index 116aa15..a3229c3 100644
--- a/sys/sys/cons.h
+++ b/sys/sys/cons.h
@@ -106,6 +106,7 @@ void	cnselect(struct consdev *);
 int	cncheckc(void);
 int	cngetc(void);
 void	cnputc(int);
+void	cnputs(char *);
 int	cnunavailable(void);
 
 #endif /* _KERNEL */
diff --git a/sys/sys/pcpu.h b/sys/sys/pcpu.h
index 00a3cac..fa54bc4 100644
--- a/sys/sys/pcpu.h
+++ b/sys/sys/pcpu.h
@@ -48,6 +48,9 @@
 struct pcb;
 struct thread;
 
+/* Size of the per-cpu console buffer for printf(). */
+#define	PCPU_CONS_BUFR	128
+
 /*
  * This structure maps out the global data that needs to be kept on a
  * per-cpu basis.  The members are accessed via the PCPU_GET/SET/PTR
@@ -71,6 +74,8 @@ struct pcpu {
 	int		pc_ktr_idx;		/* Index into trace table */
 	char		*pc_ktr_buf;
 #endif
+	char		pc_cons_bufr[PCPU_CONS_BUFR];
+						/* Console buffer */
 	PCPU_MD_FIELDS;
 	struct vmmeter	pc_cnt;			/* VM stats counters */
 	struct device	*pc_device;