kmsg - do not flush partial lines when the console is busy

Fragments of continuation lines are flushed to the console immediately. In case the console is locked, the fragment must be queued up in the cont buffer. If the the console is busy and the continuation line is complete, but no part of it was written to the console up to this point, we can just store the entire line as a regular record and free the buffer earlier. If the console is busy and earlier messages are already queued up, we should not flush the fragments of continuation lines, but store them after the queued up messages, to ensure the proper ordering. This keeps the console output better readable in case printk()s race against each other, or we receive over-long continuation lines we need to flush. Signed-off-by: Kay Sievers <kay@vrfy.org> Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

kmsg - do not flush partial lines when the console is busy
Fragments of continuation lines are flushed to the console immediately. In case the console is locked, the fragment must be queued up in the cont buffer. If the the console is busy and the continuation line is complete, but no part of it was written to the console up to this point, we can just store the entire line as a regular record and free the buffer earlier. If the console is busy and earlier messages are already queued up, we should not flush the fragments of continuation lines, but store them after the queued up messages, to ensure the proper ordering. This keeps the console output better readable in case printk()s race against each other, or we receive over-long continuation lines we need to flush. Signed-off-by: Kay Sievers <kay@vrfy.org> Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Kay Sievers · Greg Kroah-Hartman
1 parent d39f3d77c9
Showing 1 changed file with 68 additions and 25 deletions Side-by-side Diff
kernel/printk.c
@@ -231,6 +231,11 @@
 static u64 log_next_seq;
 static u32 log_next_idx;
  
+/* the next printk record to write to the console */
+static u64 console_seq;
+static u32 console_idx;
+static enum log_flags console_prev;
+
 /* the next printk record to read after the last 'clear' command */
 static u64 clear_seq;
 static u32 clear_idx;
@@ -1386,6 +1391,7 @@
 	u64 ts_nsec;			/* time of first print */
 	u8 level;			/* log level of first message */
 	u8 facility;			/* log level of first message */
+	enum log_flags flags;		/* prefix, newline flags */
 	bool flushed:1;			/* buffer sealed and committed */
 } cont;
  
@@ -1396,10 +1402,25 @@
 	if (cont.len == 0)
 		return;
  
-	log_store(cont.facility, cont.level, LOG_NOCONS | flags,
-		  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
-
-	cont.flushed = true;
+	if (cont.cons) {
+		/*
+		 * If a fragment of this line was directly flushed to the
+		 * console; wait for the console to pick up the rest of the
+		 * line. LOG_NOCONS suppresses a duplicated output.
+		 */
+		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
+			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
+		cont.flags = flags;
+		cont.flushed = true;
+	} else {
+		/*
+		 * If no fragment of this line ever reached the console,
+		 * just submit it to the store and free the buffer.
+		 */
+		log_store(cont.facility, cont.level, flags, 0,
+			  NULL, 0, cont.buf, cont.len);
+		cont.len = 0;
+	}
 }
  
 static bool cont_add(int facility, int level, const char *text, size_t len)
  
@@ -1418,12 +1439,17 @@
 		cont.level = level;
 		cont.owner = current;
 		cont.ts_nsec = local_clock();
+		cont.flags = 0;
 		cont.cons = 0;
 		cont.flushed = false;
 	}
  
 	memcpy(cont.buf + cont.len, text, len);
 	cont.len += len;
+
+	if (cont.len > (sizeof(cont.buf) * 80) / 100)
+		cont_flush(LOG_CONT);
+
 	return true;
 }
  
@@ -1432,7 +1458,7 @@
 	size_t textlen = 0;
 	size_t len;
  
-	if (cont.cons == 0) {
+	if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
 		textlen += print_time(cont.ts_nsec, text);
 		size -= textlen;
 	}
@@ -1447,7 +1473,8 @@
 	}
  
 	if (cont.flushed) {
-		text[textlen++] = '\n';
+		if (cont.flags & LOG_NEWLINE)
+			text[textlen++] = '\n';
 		/* got everything, release buffer */
 		cont.len = 0;
 	}
@@ -1545,7 +1572,7 @@
 		 * or another task also prints continuation lines.
 		 */
 		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
-			cont_flush(0);
+			cont_flush(LOG_NEWLINE);
  
 		/* buffer line if possible, otherwise store it right away */
 		if (!cont_add(facility, level, text, text_len))
@@ -1563,7 +1590,7 @@
 		if (cont.len && cont.owner == current) {
 			if (!(lflags & LOG_PREFIX))
 				stored = cont_add(facility, level, text, text_len);
-			cont_flush(0);
+			cont_flush(LOG_NEWLINE);
 		}
  
 		if (!stored)
  
@@ -1661,10 +1688,13 @@
 #define LOG_LINE_MAX 0
 static u64 syslog_seq;
 static u32 syslog_idx;
+static u64 console_seq;
+static u32 console_idx;
 static enum log_flags syslog_prev;
 static u64 log_first_seq;
 static u32 log_first_idx;
 static u64 log_next_seq;
+static enum log_flags console_prev;
 static struct cont {
 	size_t len;
 	size_t cons;
  
@@ -1948,11 +1978,35 @@
 		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
 }
  
-/* the next printk record to write to the console */
-static u64 console_seq;
-static u32 console_idx;
-static enum log_flags console_prev;
+static void console_cont_flush(char *text, size_t size)
+{
+	unsigned long flags;
+	size_t len;
  
+	raw_spin_lock_irqsave(&logbuf_lock, flags);
+
+	if (!cont.len)
+		goto out;
+
+	/*
+	 * We still queue earlier records, likely because the console was
+	 * busy. The earlier ones need to be printed before this one, we
+	 * did not flush any fragment so far, so just let it queue up.
+	 */
+	if (console_seq < log_next_seq && !cont.cons)
+		goto out;
+
+	len = cont_print_text(text, size);
+	raw_spin_unlock(&logbuf_lock);
+	stop_critical_timings();
+	call_console_drivers(cont.level, text, len);
+	start_critical_timings();
+	local_irq_restore(flags);
+	return;
+out:
+	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+}
+
 /**
  * console_unlock - unlock the console system
  *
@@ -1983,19 +2037,7 @@
 	console_may_schedule = 0;
  
 	/* flush buffered message fragment immediately to console */
-	raw_spin_lock_irqsave(&logbuf_lock, flags);
-	if (cont.len && (cont.cons < cont.len || cont.flushed)) {
-		size_t len;
-
-		len = cont_print_text(text, sizeof(text));
-		raw_spin_unlock(&logbuf_lock);
-		stop_critical_timings();
-		call_console_drivers(cont.level, text, len);
-		start_critical_timings();
-		local_irq_restore(flags);
-	} else
-		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
-
+	console_cont_flush(text, sizeof(text));
 again:
 	for (;;) {
 		struct log *msg;
@@ -2032,6 +2074,7 @@
 			 * will properly dump everything later.
 			 */
 			msg->flags &= ~LOG_NOCONS;
+			console_prev = msg->flags;
 			goto skip;
 		}
...	...	@@ -231,6 +231,11 @@
231	231	static u64 log_next_seq;
232	232	static u32 log_next_idx;
233	233
	234	+/* the next printk record to write to the console */
	235	+static u64 console_seq;
	236	+static u32 console_idx;
	237	+static enum log_flags console_prev;
	238	+
234	239	/* the next printk record to read after the last 'clear' command */
235	240	static u64 clear_seq;
236	241	static u32 clear_idx;
...	...	@@ -1386,6 +1391,7 @@
1386	1391	u64 ts_nsec; /* time of first print */
1387	1392	u8 level; /* log level of first message */
1388	1393	u8 facility; /* log level of first message */
	1394	+ enum log_flags flags; /* prefix, newline flags */
1389	1395	bool flushed:1; /* buffer sealed and committed */
1390	1396	} cont;
1391	1397
...	...	@@ -1396,10 +1402,25 @@
1396	1402	if (cont.len == 0)
1397	1403	return;
1398	1404
1399		- log_store(cont.facility, cont.level, LOG_NOCONS \| flags,
1400		- cont.ts_nsec, NULL, 0, cont.buf, cont.len);
1401		-
1402		- cont.flushed = true;
	1405	+ if (cont.cons) {
	1406	+ /*
	1407	+ * If a fragment of this line was directly flushed to the
	1408	+ * console; wait for the console to pick up the rest of the
	1409	+ * line. LOG_NOCONS suppresses a duplicated output.
	1410	+ */
	1411	+ log_store(cont.facility, cont.level, flags \| LOG_NOCONS,
	1412	+ cont.ts_nsec, NULL, 0, cont.buf, cont.len);
	1413	+ cont.flags = flags;
	1414	+ cont.flushed = true;
	1415	+ } else {
	1416	+ /*
	1417	+ * If no fragment of this line ever reached the console,
	1418	+ * just submit it to the store and free the buffer.
	1419	+ */
	1420	+ log_store(cont.facility, cont.level, flags, 0,
	1421	+ NULL, 0, cont.buf, cont.len);
	1422	+ cont.len = 0;
	1423	+ }
1403	1424	}
1404	1425
1405	1426	static bool cont_add(int facility, int level, const char *text, size_t len)
1406	1427
...	...	@@ -1418,12 +1439,17 @@
1418	1439	cont.level = level;
1419	1440	cont.owner = current;
1420	1441	cont.ts_nsec = local_clock();
	1442	+ cont.flags = 0;
1421	1443	cont.cons = 0;
1422	1444	cont.flushed = false;
1423	1445	}
1424	1446
1425	1447	memcpy(cont.buf + cont.len, text, len);
1426	1448	cont.len += len;
	1449	+
	1450	+ if (cont.len > (sizeof(cont.buf) * 80) / 100)
	1451	+ cont_flush(LOG_CONT);
	1452	+
1427	1453	return true;
1428	1454	}
1429	1455
...	...	@@ -1432,7 +1458,7 @@
1432	1458	size_t textlen = 0;
1433	1459	size_t len;
1434	1460
1435		- if (cont.cons == 0) {
	1461	+ if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
1436	1462	textlen += print_time(cont.ts_nsec, text);
1437	1463	size -= textlen;
1438	1464	}
...	...	@@ -1447,7 +1473,8 @@
1447	1473	}
1448	1474
1449	1475	if (cont.flushed) {
1450		- text[textlen++] = '\n';
	1476	+ if (cont.flags & LOG_NEWLINE)
	1477	+ text[textlen++] = '\n';
1451	1478	/* got everything, release buffer */
1452	1479	cont.len = 0;
1453	1480	}
...	...	@@ -1545,7 +1572,7 @@
1545	1572	* or another task also prints continuation lines.
1546	1573	*/
1547	1574	if (cont.len && (lflags & LOG_PREFIX \|\| cont.owner != current))
1548		- cont_flush(0);
	1575	+ cont_flush(LOG_NEWLINE);
1549	1576
1550	1577	/* buffer line if possible, otherwise store it right away */
1551	1578	if (!cont_add(facility, level, text, text_len))
...	...	@@ -1563,7 +1590,7 @@
1563	1590	if (cont.len && cont.owner == current) {
1564	1591	if (!(lflags & LOG_PREFIX))
1565	1592	stored = cont_add(facility, level, text, text_len);
1566		- cont_flush(0);
	1593	+ cont_flush(LOG_NEWLINE);
1567	1594	}
1568	1595
1569	1596	if (!stored)
1570	1597
...	...	@@ -1661,10 +1688,13 @@
1661	1688	#define LOG_LINE_MAX 0
1662	1689	static u64 syslog_seq;
1663	1690	static u32 syslog_idx;
	1691	+static u64 console_seq;
	1692	+static u32 console_idx;
1664	1693	static enum log_flags syslog_prev;
1665	1694	static u64 log_first_seq;
1666	1695	static u32 log_first_idx;
1667	1696	static u64 log_next_seq;
	1697	+static enum log_flags console_prev;
1668	1698	static struct cont {
1669	1699	size_t len;
1670	1700	size_t cons;
1671	1701
...	...	@@ -1948,11 +1978,35 @@
1948	1978	this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
1949	1979	}
1950	1980
1951		-/* the next printk record to write to the console */
1952		-static u64 console_seq;
1953		-static u32 console_idx;
1954		-static enum log_flags console_prev;
	1981	+static void console_cont_flush(char *text, size_t size)
	1982	+{
	1983	+ unsigned long flags;
	1984	+ size_t len;
1955	1985
	1986	+ raw_spin_lock_irqsave(&logbuf_lock, flags);
	1987	+
	1988	+ if (!cont.len)
	1989	+ goto out;
	1990	+
	1991	+ /*
	1992	+ * We still queue earlier records, likely because the console was
	1993	+ * busy. The earlier ones need to be printed before this one, we
	1994	+ * did not flush any fragment so far, so just let it queue up.
	1995	+ */
	1996	+ if (console_seq < log_next_seq && !cont.cons)
	1997	+ goto out;
	1998	+
	1999	+ len = cont_print_text(text, size);
	2000	+ raw_spin_unlock(&logbuf_lock);
	2001	+ stop_critical_timings();
	2002	+ call_console_drivers(cont.level, text, len);
	2003	+ start_critical_timings();
	2004	+ local_irq_restore(flags);
	2005	+ return;
	2006	+out:
	2007	+ raw_spin_unlock_irqrestore(&logbuf_lock, flags);
	2008	+}
	2009	+
1956	2010	/**
1957	2011	* console_unlock - unlock the console system
1958	2012	*
...	...	@@ -1983,19 +2037,7 @@
1983	2037	console_may_schedule = 0;
1984	2038
1985	2039	/* flush buffered message fragment immediately to console */
1986		- raw_spin_lock_irqsave(&logbuf_lock, flags);
1987		- if (cont.len && (cont.cons < cont.len \|\| cont.flushed)) {
1988		- size_t len;
1989		-
1990		- len = cont_print_text(text, sizeof(text));
1991		- raw_spin_unlock(&logbuf_lock);
1992		- stop_critical_timings();
1993		- call_console_drivers(cont.level, text, len);
1994		- start_critical_timings();
1995		- local_irq_restore(flags);
1996		- } else
1997		- raw_spin_unlock_irqrestore(&logbuf_lock, flags);
1998		-
	2040	+ console_cont_flush(text, sizeof(text));
1999	2041	again:
2000	2042	for (;;) {
2001	2043	struct log *msg;
...	...	@@ -2032,6 +2074,7 @@
2032	2074	* will properly dump everything later.
2033	2075	*/
2034	2076	msg->flags &= ~LOG_NOCONS;
	2077	+ console_prev = msg->flags;
2035	2078	goto skip;
2036	2079	}
2037	2080