[PATCHSET] printk: implement printk_header() and merging printk

[PATCHSET] printk: implement printk_header() and merging printk

[Tejun Heo]

Hello, all.

This patchset implements printk_header() and mprintk - merging printk
- to make printing multiline messages and assembling message
piece-by-piece easier.

In a nutshell, printk_header() lets you do the following atomically
(against other messages).

 code:
  printk(KERN_INFO "ata1.00: ", "line0\nline1\nline2\n");

 output:
  <6>ata1.00: line0
  <6>         line1
  <6>         line2

And mprintk the following.

 code:
  DEFINE_MPRINTK(mp, 2 * 80);

  mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
  mprintk_push(&mp, "ATA %d", 7);
  mprintk_push(&mp, ", %u sectors\n", 1024);
  mprintk(&mp, "everything seems dandy\n");

 output:
  <6>ata1.00: ATA 7, 1024 sectors
  <6>         everything seems dandy

Please read the commit messages and comments for more detail.  If this
patchset is accepted, I'll write up Documentation/printk.txt which
contains describtion of the API and guidelines - "don't pack unrelated
messages into one" kind of stuff.

This patchset is against the current linux-2.6#master (031f2dcd) and
contains the following patches.

0001-printk-keep-log-level-on-multiline-messages.patch
0002-printk-implement-v-printk_header.patch
0003-printk-implement-merging-printk.patch
0004-libata-make-libata-use-printk_header-and-mprintk.patch

 drivers/ata/libata-core.c   |  202 +++++++++++++++----------
 drivers/ata/libata-eh.c     |  150 ++++++++----------
 drivers/ata/libata-pmp.c    |    5 
 drivers/ata/libata-scsi.c   |    6 
 drivers/ata/sata_inic162x.c |    2 
 drivers/ata/sata_nv.c       |    4 
 include/linux/kernel.h      |   83 ++++++++++
 include/linux/libata.h      |   35 ++--
 kernel/printk.c             |  354 ++++++++++++++++++++++++++++++++++++++++----
 9 files changed, 630 insertions(+), 211 deletions(-)

More than half of the code increase in kernel.h are from the dummy
declarations for !CONFIG_PRINTK.  More than one third of printk.c
increase are comments.  On my x86-64 configuration, printk.o grows
from 30152 to 34128.

libata code grows slightly but the increase is from converting the
printk wrapper from #define to proper functions.  The converted areas
- device configuration and EH reporting - were reduced in comlexity
and size.  With all-y, drivers/ata/built-in.o shrinks from 726509 to
717657 mostly due to the conversion away from macros.

Thanks.

--
tejun

[PATCH 1/4] printk: keep log level on multiline messages

[Tejun Heo]

When printing multiline messages, printk() resets log level to
default_message_loglevel after the first line.  This changes log level
unexpectedly when printing multiline messages.

For example, libata error messages are printed like the following.

<3>ata8.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40 tag 0 ncq 512 in
<4>         res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)

This patch makes printk use the log level of the last line if the
current line doesn't specify log level explicitly.

While at it, separate out is_loglevel() test.  This will be used by
later changes.

Signed-off-by: Tejun Heo <htejun@gmail.com>
---
 kernel/printk.c |   51 ++++++++++++++++++++++++---------------------------
 1 files changed, 24 insertions(+), 27 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 89011bf..6df1872 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -628,11 +628,17 @@ asmlinkage int printk(const char *fmt, ...)
 /* cpu currently holding logbuf_lock */
 static volatile unsigned int printk_cpu = UINT_MAX;
 
+static int is_loglevel(const char *p)
+{
+	return p[0] == '<' && p[1] >= '0' && p[1] <= '7' && p[2] == '>';
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
+	int last_lv = default_message_loglevel;
 	unsigned long flags;
 	int printed_len;
-	char *p;
+	const char *p;
 	static char printk_buf[1024];
 	static int log_level_unknown = 1;
 
@@ -659,48 +665,39 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	 */
 	for (p = printk_buf; *p; p++) {
 		if (log_level_unknown) {
-                        /* log_level_unknown signals the start of a new line */
+			/* log_level_unknown signals the start of a new line */
+			int lv = last_lv;
+
+			if (is_loglevel(p)) {
+				lv = p[1] - '0';
+				p += 3;
+				printed_len -= 3;
+			}
+
+			emit_log_char('<');
+			emit_log_char(lv + '0');
+			emit_log_char('>');
+			printed_len += 3;
+
 			if (printk_time) {
-				int loglev_char;
 				char tbuf[50], *tp;
 				unsigned tlen;
 				unsigned long long t;
 				unsigned long nanosec_rem;
 
-				/*
-				 * force the log level token to be
-				 * before the time output.
-				 */
-				if (p[0] == '<' && p[1] >='0' &&
-				   p[1] <= '7' && p[2] == '>') {
-					loglev_char = p[1];
-					p += 3;
-					printed_len -= 3;
-				} else {
-					loglev_char = default_message_loglevel
-						+ '0';
-				}
 				t = printk_clock();
 				nanosec_rem = do_div(t, 1000000000);
 				tlen = sprintf(tbuf,
-						"<%c>[%5lu.%06lu] ",
-						loglev_char,
+						"[%5lu.%06lu] ",
 						(unsigned long)t,
 						nanosec_rem/1000);
 
 				for (tp = tbuf; tp < tbuf + tlen; tp++)
 					emit_log_char(*tp);
 				printed_len += tlen;
-			} else {
-				if (p[0] != '<' || p[1] < '0' ||
-				   p[1] > '7' || p[2] != '>') {
-					emit_log_char('<');
-					emit_log_char(default_message_loglevel
-						+ '0');
-					emit_log_char('>');
-					printed_len += 3;
-				}
 			}
+
+			last_lv = lv;
 			log_level_unknown = 0;
 			if (!*p)
 				break;
-- 
1.5.2.4

[PATCH 2/4] printk: implement [v]printk_header()

[Tejun Heo]

Implement [v]printk_header() which takes @header argument and
automatically prints header in front of or indents multiline messages.
For example, if @header is "<7>ata1.00: " and the formatted message is
"<6>line0\nline1\n", the following gets written to the console.

<6>ata1.00: line0
<6>         line1

Header is printed only on the first lines and when log level changes
in the middle in case messages of different log level are sent to
different destinations.  Other lines are indented the same amount as
the length of the header.  This helps to distinguish where a multiline
message begins when messages of similar pattern repeats, for
example...

ata8.00: cmd 60/80:20:e1:71:02/00:00:00:00:00/40 tag 4 ncq 65536 in
         res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
ata8.00: cmd 60/0e:28:d0:71:02/00:00:00:00:00/40 tag 5 ncq 7168 in
         res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
ata8.00: cmd 60/7f:38:61:72:02/00:00:00:00:00/40 tag 7 ncq 65024 in
         res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)

Signed-off-by: Tejun Heo <htejun@gmail.com>
---
 include/linux/kernel.h |   12 ++++++
 kernel/printk.c        |   94 ++++++++++++++++++++++++++++++++++++++++++++---
 2 files changed, 100 insertions(+), 6 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 94bc996..ade3ac9 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -175,6 +175,10 @@ extern struct pid *session_of_pgrp(struct pid *pgrp);
 extern void dump_thread(struct pt_regs *regs, struct user *dump);
 
 #ifdef CONFIG_PRINTK
+asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
+asmlinkage int printk_header(const char *header, const char * fmt, ...)
+	__attribute__ ((format (printf, 2, 3))) __cold;
 asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
@@ -183,6 +187,14 @@ extern int log_buf_get_len(void);
 extern int log_buf_read(int idx);
 extern int log_buf_copy(char *dest, int idx, int len);
 #else
+static inline int vprintk_header(const char *header, const char *s, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
+static inline int vprintk_header(const char *header, const char *s, va_list args)
+{ return 0; }
+static inline int printk_header(const char *header, const char *s, ...)
+	__attribute__ ((format (printf, 2, 3)));
+static inline int __cold printk_header(const char *header, const char *s, ...)
+{ return 0; }
 static inline int vprintk(const char *s, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 static inline int vprintk(const char *s, va_list args) { return 0; }
diff --git a/kernel/printk.c b/kernel/printk.c
index 6df1872..1cde1d6 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -619,23 +619,86 @@ asmlinkage int printk(const char *fmt, ...)
 	int r;
 
 	va_start(args, fmt);
-	r = vprintk(fmt, args);
+	r = vprintk_header(NULL, fmt, args);
 	va_end(args);
 
 	return r;
 }
+EXPORT_SYMBOL(printk);
 
-/* cpu currently holding logbuf_lock */
-static volatile unsigned int printk_cpu = UINT_MAX;
+asmlinkage int vprintk(const char *fmt, va_list args)
+{
+	return vprintk_header(NULL, fmt, args);
+}
+EXPORT_SYMBOL(vprintk);
+
+/**
+ * printk_header - print a kernel message with header
+ * @header: header string
+ * @fmt: format string
+ *
+ * This is printk() with a twist.  @header points to string which will
+ * be used as message header.  If @header is NULL, this function is
+ * identical to printk().
+ *
+ * @header may contain loglevel in front of it.  Each new line
+ * including the first one in the message formatted from @fmt can also
+ * have loglevel.  When both exist, the latter is used.  In multiline
+ * messages, log level is inherited from the previous line if not
+ * explicitly specified.
+ *
+ * @header is printed when new line starts if @header hasn't been
+ * printed yet for the current log level.  That means, in a multiline
+ * message where all the lines are of the same log level, @header is
+ * printed only once before the first line.
+ *
+ * Lines which don't have @header printed in front of them are
+ * indented by the same number of characters in @header - they are
+ * aligned with lines which have @header in front of them.
+ *
+ * For example, if @header is "<7>ata1.00: " and the formatted message
+ * is "<6>line0\nline1\n<4>line2\nline3\n", the following gets written to
+ * the console.
+ *
+ * <6>ata1.00: line0
+ * <6>         line1
+ * <4>ata1.00: line2
+ * <4>         line3
+ */
+asmlinkage int printk_header(const char *header, const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	r = vprintk_header(header, fmt, args);
+	va_end(args);
+
+	return r;
+}
+EXPORT_SYMBOL(printk_header);
 
 static int is_loglevel(const char *p)
 {
 	return p[0] == '<' && p[1] >= '0' && p[1] <= '7' && p[2] == '>';
 }
 
-asmlinkage int vprintk(const char *fmt, va_list args)
+/* cpu currently holding logbuf_lock */
+static volatile unsigned int printk_cpu = UINT_MAX;
+
+/**
+ * vprintk_header - a variant of printk_header() which takes va_list argument
+ * @header: header string
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to printk_header() except that it takes
+ * va_list @args instead of variable argument list.
+ */
+asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
 {
 	int last_lv = default_message_loglevel;
+	unsigned int printed_header = 0;
 	unsigned long flags;
 	int printed_len;
 	const char *p;
@@ -656,6 +719,12 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	spin_lock(&logbuf_lock);
 	printk_cpu = smp_processor_id();
 
+	/* Parse header log level */
+	if (header && is_loglevel(header)) {
+		last_lv = header[1] - '0';
+		header += 3;
+	}
+
 	/* Emit the output into the temporary buffer */
 	printed_len = vscnprintf(printk_buf, sizeof(printk_buf), fmt, args);
 
@@ -697,6 +766,20 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 				printed_len += tlen;
 			}
 
+			if (header) {
+				const char *h = header;
+
+				while (*h) {
+					if (!(printed_header & (1 << lv)))
+						emit_log_char(*h);
+					else
+						emit_log_char(' ');
+					h++;
+					printed_len++;
+				}
+				printed_header |= 1 << lv;
+			}
+
 			last_lv = lv;
 			log_level_unknown = 0;
 			if (!*p)
@@ -747,8 +830,7 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	preempt_enable();
 	return printed_len;
 }
-EXPORT_SYMBOL(printk);
-EXPORT_SYMBOL(vprintk);
+EXPORT_SYMBOL(vprintk_header);
 
 #else
 
-- 
1.5.2.4

[PATCH 3/4] printk: implement merging printk

[Tejun Heo]

There often are times printk messages need to be assembled piece by
piece and it's usually done using one of the following methods.

* Calling printk() on partial message segments.  This used to be quite
  common but has a problem - the message can break up if someone else
  prints something in the middle.

* Prepping a temp buffer and build message piece-by-piece using
  snprintf().  This is the most generic solution but corner case
  handling can be tedious and on overflow messages can be lost and
  such overflows would go unnoticed if overflow detection isn't
  properly done.

* Collect all the partial data and perform printk() once with all the
  parameters.  This is often combined with the second.  This usually
  works but printing messages can become non-trivial programming
  problem and can get quite tedious if the message format varies
  depending on data.

None of the above is quite satisfactory.  This patch implement merging
printk - mprintk to deal with this problem.  It's basically a helper
to construct message piece-by-piece into the specified buffer.  The
caller still has to care about buffer size and how the buffer is
allocated but mprintk makes it easier.

* DEFINE_MPRINTK() macro makes it easy to define a mprintk instance
  with on-stack buffer.  Malloc'd buffer can also be used.

* Message is never lost.  On buffer overflow, all queued and to be
  queued messages are printed followed by warning message and stack
  dump.  The warning message and stack dump are printed only once per
  mprintk instance.  The caller also doesn't have to handle buffer
  malloc failure.  If buffer is initialized to NULL, mprintk simply
  bypasses the messages to printk().

* Has good support for multiline messages.  A mprintk instance can
  have header associated with it and the header can have log level.
  Header log level is used if a partial message doesn't specify log
  level explicitly.  When log level is specified explicitly in a
  partial message, the log level is applied to the partial message
  only.

A simple example.

  DEFINE_MPRINTK(mp, 2 * 80);

  mprintk_set_header(&mp, KERN_DEBUG "ata%u.%2u: ", 1, 0);
  mprintk_push(&mp, "ATA %d", 7);
  mprintk_push(&mp, ", %u sectors\n", 1024);
  mprintk(&mp, "everything seems dandy\n");

Which will be printed like the following as a single message.

<7>ata1.00: ATA 7, 1024 sectors
<7>         everything seems dandy

Signed-off-by: Tejun Heo <htejun@gmail.com>
---
 include/linux/kernel.h |   71 ++++++++++++++++
 kernel/printk.c        |  215 ++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 286 insertions(+), 0 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index ade3ac9..f92a4a1 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -175,6 +175,29 @@ extern struct pid *session_of_pgrp(struct pid *pgrp);
 extern void dump_thread(struct pt_regs *regs, struct user *dump);
 
 #ifdef CONFIG_PRINTK
+struct mprintk {
+	char *		header;
+	char *		body;
+	char *		cur;
+	char *		prv;
+	char *		end;
+	int		overflowed;
+};
+
+#define MPRINTK_INITIALIZER(_buf, _size)				\
+	{								\
+		.header		= NULL,					\
+		.body		= _buf,					\
+		.cur		= _buf,					\
+		.prv		= NULL,					\
+		.end		= _buf + _size,				\
+		.overflowed	= 0,					\
+	}
+
+#define DEFINE_MPRINTK(name, size)					\
+	char __##name##_buf[size];					\
+	struct mprintk name = MPRINTK_INITIALIZER(__##name##_buf, size)
+
 asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
 	__attribute__ ((format (printf, 2, 0)));
 asmlinkage int printk_header(const char *header, const char * fmt, ...)
@@ -183,10 +206,33 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
+
+static inline void mprintk_init(struct mprintk *mp, char *buf, size_t size)
+{
+	*mp = (struct mprintk)MPRINTK_INITIALIZER(buf, size);
+}
+extern int vmprintk_push(struct mprintk *mp, const char *fmt, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
+extern int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
+extern int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
+extern int mprintk_push(struct mprintk *mp, const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+extern int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+extern int mprintk(struct mprintk *mp, const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+
 extern int log_buf_get_len(void);
 extern int log_buf_read(int idx);
 extern int log_buf_copy(char *dest, int idx, int len);
 #else
+struct mprintk { };
+#define MPRINTK_INITIALIZER(_buf, _size)	{ }
+#define DEFINE_MPRINTK(name, size)		\
+	struct mprintk name = __MPRINTK_INITIALIZER(NULL, size)
+
 static inline int vprintk_header(const char *header, const char *s, va_list args)
 	__attribute__ ((format (printf, 2, 0)));
 static inline int vprintk_header(const char *header, const char *s, va_list args)
@@ -201,6 +247,31 @@ static inline int vprintk(const char *s, va_list args) { return 0; }
 static inline int printk(const char *s, ...)
 	__attribute__ ((format (printf, 1, 2)));
 static inline int __cold printk(const char *s, ...) { return 0; }
+static inline void mprintk_init(struct mprintk *mp, char *buf, size_t size) { }
+static inline int vmprintk_push(struct mprintk *mp, const char *fmt, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk_push(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int mprintk_push(struct mprintk *mp, const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+static inline int mprintk_push(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
+static inline int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+static inline int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
+static inline int mprintk(struct mprintk *mp, const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+static inline int mprintk(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
 static inline int log_buf_get_len(void) { return 0; }
 static inline int log_buf_read(int idx) { return 0; }
 static inline int log_buf_copy(char *dest, int idx, int len) { return 0; }
diff --git a/kernel/printk.c b/kernel/printk.c
index 1cde1d6..873ecd8 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -832,6 +832,221 @@ asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
 }
 EXPORT_SYMBOL(vprintk_header);
 
+static void mprintk_flush(struct mprintk *mp)
+{
+	printk_header(mp->header, "%s", mp->body);
+	mp->prv = NULL;
+	mp->cur = mp->body;
+}
+
+/**
+ * vmprintk_push - format and push message to merging printk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk_push() except that it takes
+ * va_list @args intead of argument list.
+ */
+int vmprintk_push(struct mprintk *mp, const char *fmt, va_list args)
+{
+	char *start = mp->cur;
+	size_t size = mp->end - start;
+	int printed = 0;
+	int ret;
+
+	if (!start)
+		return vprintk(fmt, args);
+
+	/*
+	 * Push header log level if the header has log level && the
+	 * previous push overrided log level && this push doesn't
+	 * override log level.
+	 */
+	if (mp->header && is_loglevel(mp->header) &&
+	    mp->prv && (mp->prv == mp->body || mp->prv[-1] == '\n') &&
+	    is_loglevel(mp->prv) && mp->cur[-1] == '\n') {
+		char tbuf[4];
+
+		vsnprintf(tbuf, sizeof(tbuf), fmt, args);
+
+		if (!is_loglevel(tbuf)) {
+			ret = snprintf(start, size, "<%c>", mp->header[1]);
+			printed += ret;
+			if (ret >= size)
+				goto overflow;
+			start += ret;
+			size -= ret;
+		}
+	}
+
+	ret = vsnprintf(start, size, fmt, args);
+	printed += ret;
+	if (ret >= size)
+		goto overflow;
+
+	mp->prv = mp->cur;
+	mp->cur += printed;
+
+	return printed;
+
+ overflow:
+	mp->cur[0] = '\0';
+	mprintk_flush(mp);
+	vprintk_header(mp->header, fmt, args);
+
+	if (!mp->overflowed) {
+		printk("\n" KERN_ERR
+		       "mprintk buffer overflow, please file a bug report\n");
+		dump_stack();
+		mp->overflowed = 1;
+	}
+
+	return printed;
+}
+EXPORT_SYMBOL(vmprintk_push);
+
+/**
+ * vmprintk_set_header - format and set header to merging printk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk_set_header() except that it
+ * takes va_list @args intead of argument list.
+ */
+int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+{
+	int ret;
+
+	if (!mp->cur)
+		return vprintk(fmt, args);
+
+	if (mp->header || mp->prv) {
+		printk(KERN_WARNING "vmprintk_set_header() called on "
+		       "dirty mprintk instance\n");
+		WARN_ON(1);
+		return 0;
+	}
+
+	ret = vmprintk_push(mp, fmt, args);
+	if (mp->prv) {
+		mp->header = mp->body;
+		mp->body = ++mp->cur;
+	}
+
+	return ret;
+}
+EXPORT_SYMBOL(vmprintk_set_header);
+
+/**
+ * vmprintk - format and push message to merging printk instance and flush it
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk() except that it takes
+ * va_list @args intead of argument list.
+ */
+int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+{
+	int ret = 0;
+
+	if (!mp->cur)
+		return vprintk(fmt, args);
+
+	if (fmt)
+		ret = vmprintk_push(mp, fmt, args);
+	mprintk_flush(mp);
+
+	return ret;
+}
+EXPORT_SYMBOL(vmprintk);
+
+/**
+ * mprintk_push - format and push message to merging printk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ *
+ * This function formats @fmt and the following list of arguments and
+ * append the result to @mp.  If @mp has header with log level and
+ * @fmt is multiline, this function takes care of restoring header
+ * log level if the previous push contained log level overrided and
+ * this push doesn't.
+ *
+ * If the buffer pointed to by @mp is too short to contain the pushed
+ * message, @mp is flushed, the message to push is printed directly
+ * and warning message with stack dump is printed.  If buffer is NULL,
+ * the formatted message is printed directly.  Message is never lost.
+ * The warning message and the stack dump are printed only once for
+ * each @mp instance.
+ *
+ * For example, if @mp header is set to "<7>ata1.00: " and the first
+ * push is "line0\n", second "<4>line1\nline2\n" and the third
+ * "line3\n", the following is the end result.
+ *
+ * <7>ata1.00: line0
+ * <4>ata1.00: line1	(different log level, header is printed again)
+ * <4>         line2
+ * <7>         line3
+ */
+int mprintk_push(struct mprintk *mp, const char *fmt, ...)
+{
+	va_list args;
+	int ret;
+
+	va_start(args, fmt);
+	ret = vmprintk_push(mp, fmt, args);
+	va_end(args);
+
+	return ret;
+}
+EXPORT_SYMBOL(mprintk_push);
+
+/**
+ * mprintk_set_header - set header of merging printk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ *
+ * Set header of @mp to the string formatted according to @fmt and
+ * arguments.
+ */
+int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+{
+	va_list args;
+	int ret;
+
+	va_start(args, fmt);
+	ret = vmprintk_set_header(mp, fmt, args);
+	va_end(args);
+
+	return ret;
+}
+EXPORT_SYMBOL(mprintk_set_header);
+
+/**
+ * mprintk - push a message to merging printk instance and flush it
+ * @mp: mprintk instance to use
+ * @fmt: format string (can be NULL)
+ *
+ * Push message formatted according to @fmt and arguments to @mp and
+ * flush it.  If @fmt is NULL, only the latter operation occurs.  NULL
+ * @fmt is allowed to avoid zero length formatting string warning from
+ * compiler.
+ */
+int mprintk(struct mprintk *mp, const char *fmt, ...)
+{
+	va_list args;
+	int ret;
+
+	va_start(args, fmt);
+	ret = vmprintk(mp, fmt, args);
+	va_end(args);
+
+	return ret;
+}
+EXPORT_SYMBOL(mprintk);
+
 #else
 
 asmlinkage long sys_syslog(int type, char __user *buf, int len)
-- 
1.5.2.4

[PATCH 4/4] libata: make libata use printk_header() and mprintk

[Tejun Heo]

Reimplement libata printk helpers using printk_header, implement
helpers to initialize mprintk and use mprintk during device
configuration and EH reporting.

This fixes various formatting related problems of libata messages such
as misaligned multiline messages, decoded register lines with leading
headers making them difficult to tell to which error they belong to,
awkward manual indents and complex message printing logics.  More
importantly, by making message assembly flexible, this patch makes
future changes to device configuration and EH reporting easier.

Signed-off-by: Tejun Heo <htejun@gmail.com>
---
 drivers/ata/libata-core.c   |  202 +++++++++++++++++++++++++++----------------
 drivers/ata/libata-eh.c     |  150 +++++++++++++++-----------------
 drivers/ata/libata-pmp.c    |    5 +-
 drivers/ata/libata-scsi.c   |    6 +-
 drivers/ata/sata_inic162x.c |    2 +-
 drivers/ata/sata_nv.c       |    4 +-
 include/linux/libata.h      |   35 ++++----
 7 files changed, 223 insertions(+), 181 deletions(-)

diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 4753a18..6fac482 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -125,6 +125,79 @@ MODULE_LICENSE("GPL");
 MODULE_VERSION(DRV_VERSION);
 
 
+int ata_port_printk(struct ata_port *ap, const char *lv, const char *fmt, ...)
+{
+	va_list args;
+	char hbuf[16];
+	int ret;
+
+	snprintf(hbuf, sizeof(hbuf), "%sata%u: ", lv, ap->print_id);
+
+	va_start(args, fmt);
+	ret = vprintk_header(hbuf, fmt, args);
+	va_end(args);
+
+	return ret;
+}
+
+int ata_link_printk(struct ata_link *link, const char *lv, const char *fmt, ...)
+{
+	va_list args;
+	char hbuf[16];
+	int ret;
+
+	if (link->ap->nr_pmp_links)
+		snprintf(hbuf, sizeof(hbuf), "%sata%u.%02u: ",
+			 lv, link->ap->print_id, link->pmp);
+	else
+		snprintf(hbuf, sizeof(hbuf), "%sata%u: ",
+			 lv, link->ap->print_id);
+
+	va_start(args, fmt);
+	ret = vprintk_header(hbuf, fmt, args);
+	va_end(args);
+
+	return ret;
+}
+
+int ata_dev_printk(struct ata_device *dev, const char *lv, const char *fmt, ...)
+{
+	va_list args;
+	char hbuf[16];
+	int ret;
+
+	snprintf(hbuf, sizeof(hbuf), "%sata%u.%02u: ",
+		 lv, dev->link->ap->print_id, dev->link->pmp + dev->devno);
+
+	va_start(args, fmt);
+	ret = vprintk_header(hbuf, fmt, args);
+	va_end(args);
+
+	return ret;
+}
+
+void ata_port_mp_header(struct ata_port *ap, const char *lv, struct mprintk *mp)
+{
+	mprintk_set_header(mp, "%sata%u: ", lv, ap->print_id);
+}
+
+void ata_link_mp_header(struct ata_link *link, const char *lv,
+			struct mprintk *mp)
+{
+	if (link->ap->nr_pmp_links)
+		mprintk_set_header(mp, "%sata%u.%02u: ",
+				   lv, link->ap->print_id, link->pmp);
+	else
+		mprintk_set_header(mp, "%sata%u: ", lv, link->ap->print_id);
+}
+
+void ata_dev_mp_header(struct ata_device *dev, const char *lv,
+		       struct mprintk *mp)
+{
+	mprintk_set_header(mp, "%sata%u.%02u: ", lv, dev->link->ap->print_id,
+			   dev->link->pmp + dev->devno);
+}
+
 /**
  *	ata_tf_to_fis - Convert ATA taskfile to SATA FIS structure
  *	@tf: Taskfile to convert
@@ -2046,18 +2119,16 @@ static inline u8 ata_dev_knobble(struct ata_device *dev)
 	return ((ap->cbl == ATA_CBL_SATA) && (!ata_id_is_sata(dev->id)));
 }
 
-static void ata_dev_config_ncq(struct ata_device *dev,
-			       char *desc, size_t desc_sz)
+static void ata_dev_config_ncq(struct ata_device *dev, struct mprintk *mp)
 {
 	struct ata_port *ap = dev->link->ap;
 	int hdepth = 0, ddepth = ata_id_queue_depth(dev->id);
 
-	if (!ata_id_has_ncq(dev->id)) {
-		desc[0] = '\0';
+	if (!ata_id_has_ncq(dev->id))
 		return;
-	}
+
 	if (dev->horkage & ATA_HORKAGE_NONCQ) {
-		snprintf(desc, desc_sz, "NCQ (not used)");
+		mprintk_push(mp, ", NCQ (not used)");
 		return;
 	}
 	if (ap->flags & ATA_FLAG_NCQ) {
@@ -2066,9 +2137,9 @@ static void ata_dev_config_ncq(struct ata_device *dev,
 	}
 
 	if (hdepth >= ddepth)
-		snprintf(desc, desc_sz, "NCQ (depth %d)", ddepth);
+		mprintk_push(mp, ", NCQ (depth %d)", ddepth);
 	else
-		snprintf(desc, desc_sz, "NCQ (depth %d/%d)", hdepth, ddepth);
+		mprintk_push(mp, ", NCQ (depth %d/%d)", hdepth, ddepth);
 }
 
 /**
@@ -2090,8 +2161,8 @@ int ata_dev_configure(struct ata_device *dev)
 	struct ata_eh_context *ehc = &dev->link->eh_context;
 	int print_info = ehc->i.flags & ATA_EHI_PRINTINFO;
 	const u16 *id = dev->id;
+	struct mprintk mp = MPRINTK_INITIALIZER(ap->sector_buf, ATA_SECT_SIZE);
 	unsigned int xfer_mask;
-	char revbuf[7];		/* XYZ-99\0 */
 	char fwrevbuf[ATA_ID_FW_REV_LEN+1];
 	char modelbuf[ATA_ID_PROD_LEN+1];
 	int rc;
@@ -2105,6 +2176,8 @@ int ata_dev_configure(struct ata_device *dev)
 	if (ata_msg_probe(ap))
 		ata_dev_printk(dev, KERN_DEBUG, "%s: ENTER\n", __FUNCTION__);
 
+	ata_dev_mp_header(dev, KERN_INFO, &mp);
+
 	/* set horkage */
 	dev->horkage |= ata_dev_blacklisted(dev);
 
@@ -2153,51 +2226,44 @@ int ata_dev_configure(struct ata_device *dev)
 	ata_id_c_string(dev->id, modelbuf, ATA_ID_PROD,
 			sizeof(modelbuf));
 
-	/* ATA-specific feature tests */
 	if (dev->class == ATA_DEV_ATA) {
+		/* ATA-specific feature tests */
 		if (ata_id_is_cfa(id)) {
-			if (id[162] & 1) /* CPRM may make this media unusable */
+			/* CPRM may make this media unusable */
+			if ((id[162] & 1) && print_info)
 				ata_dev_printk(dev, KERN_WARNING,
 					       "supports DRM functions and may "
 					       "not be fully accessable.\n");
-			snprintf(revbuf, 7, "CFA");
+			mprintk_push(&mp, "CFA: ");
 		} else
-			snprintf(revbuf, 7, "ATA-%d", ata_id_major_version(id));
+			mprintk_push(&mp, "ATA-%d: ", ata_id_major_version(id));
+
+		mprintk_push(&mp, "%s, %s, max %s\n",
+			     modelbuf, fwrevbuf, ata_mode_string(xfer_mask));
 
 		dev->n_sectors = ata_id_n_sectors(id);
+		mprintk_push(&mp, "%Lu sectors",
+			     (unsigned long long)dev->n_sectors);
 
-		if (dev->id[59] & 0x100)
+		if (dev->id[59] & 0x100) {
 			dev->multi_count = dev->id[59] & 0xff;
+			mprintk_push(&mp, ", multi %u", dev->multi_count);
+		}
 
 		if (ata_id_has_lba(id)) {
-			const char *lba_desc;
-			char ncq_desc[20];
-
-			lba_desc = "LBA";
 			dev->flags |= ATA_DFLAG_LBA;
+			mprintk_push(&mp, ", LBA");
+
 			if (ata_id_has_lba48(id)) {
 				dev->flags |= ATA_DFLAG_LBA48;
-				lba_desc = "LBA48";
-
+				mprintk_push(&mp, "48");
 				if (dev->n_sectors >= (1UL << 28) &&
 				    ata_id_has_flush_ext(id))
 					dev->flags |= ATA_DFLAG_FLUSH_EXT;
 			}
 
 			/* config NCQ */
-			ata_dev_config_ncq(dev, ncq_desc, sizeof(ncq_desc));
-
-			/* print device info to dmesg */
-			if (ata_msg_drv(ap) && print_info) {
-				ata_dev_printk(dev, KERN_INFO,
-					"%s: %s, %s, max %s\n",
-					revbuf, modelbuf, fwrevbuf,
-					ata_mode_string(xfer_mask));
-				ata_dev_printk(dev, KERN_INFO,
-					"%Lu sectors, multi %u: %s %s\n",
-					(unsigned long long)dev->n_sectors,
-					dev->multi_count, lba_desc, ncq_desc);
-			}
+			ata_dev_config_ncq(dev, &mp);
 		} else {
 			/* CHS */
 
@@ -2213,27 +2279,13 @@ int ata_dev_configure(struct ata_device *dev)
 				dev->sectors   = id[56];
 			}
 
-			/* print device info to dmesg */
-			if (ata_msg_drv(ap) && print_info) {
-				ata_dev_printk(dev, KERN_INFO,
-					"%s: %s, %s, max %s\n",
-					revbuf,	modelbuf, fwrevbuf,
-					ata_mode_string(xfer_mask));
-				ata_dev_printk(dev, KERN_INFO,
-					"%Lu sectors, multi %u, CHS %u/%u/%u\n",
-					(unsigned long long)dev->n_sectors,
-					dev->multi_count, dev->cylinders,
-					dev->heads, dev->sectors);
-			}
+			mprintk_push(&mp, ", CHS %u/%u/%u",
+				     dev->cylinders, dev->heads, dev->sectors);
 		}
 
 		dev->cdb_len = 16;
-	}
-
-	/* ATAPI-specific feature tests */
-	else if (dev->class == ATA_DEV_ATAPI) {
-		const char *cdb_intr_string = "";
-		const char *atapi_an_string = "";
+	} else if (dev->class == ATA_DEV_ATAPI) {
+		/* ATAPI-specific feature tests */
 		u32 sntf;
 
 		rc = atapi_cdb_len(id);
@@ -2246,6 +2298,14 @@ int ata_dev_configure(struct ata_device *dev)
 		}
 		dev->cdb_len = (unsigned int) rc;
 
+		mprintk_push(&mp, "ATAPI: %s, %s, max %s", modelbuf, fwrevbuf,
+			     ata_mode_string(xfer_mask));
+
+		if (ata_id_cdb_intr(dev->id)) {
+			dev->flags |= ATA_DFLAG_CDB_INTR;
+			mprintk_push(&mp, ", CDB intr");
+		}
+
 		/* Enable ATAPI AN if both the host and device have
 		 * the support.  If PMP is attached, SNTF is required
 		 * to enable ATAPI AN to discern between PHY status
@@ -2265,22 +2325,9 @@ int ata_dev_configure(struct ata_device *dev)
 					"(err_mask=0x%x)\n", err_mask);
 			else {
 				dev->flags |= ATA_DFLAG_AN;
-				atapi_an_string = ", ATAPI AN";
+				mprintk_push(&mp, ", ATAPI AN");
 			}
 		}
-
-		if (ata_id_cdb_intr(dev->id)) {
-			dev->flags |= ATA_DFLAG_CDB_INTR;
-			cdb_intr_string = ", CDB intr";
-		}
-
-		/* print device info to dmesg */
-		if (ata_msg_drv(ap) && print_info)
-			ata_dev_printk(dev, KERN_INFO,
-				       "ATAPI: %s, %s, max %s%s%s\n",
-				       modelbuf, fwrevbuf,
-				       ata_mode_string(xfer_mask),
-				       cdb_intr_string, atapi_an_string);
 	}
 
 	/* determine max_sectors */
@@ -2295,23 +2342,18 @@ int ata_dev_configure(struct ata_device *dev)
 			dev->flags |= ATA_DFLAG_DIPM;
 	}
 
-	if (dev->horkage & ATA_HORKAGE_DIAGNOSTIC) {
+	if ((dev->horkage & ATA_HORKAGE_DIAGNOSTIC) && print_info) {
 		/* Let the user know. We don't want to disallow opens for
 		   rescue purposes, or in case the vendor is just a blithering
 		   idiot */
-		if (print_info) {
-			ata_dev_printk(dev, KERN_WARNING,
-"Drive reports diagnostics failure. This may indicate a drive\n");
-			ata_dev_printk(dev, KERN_WARNING,
-"fault or invalid emulation. Contact drive vendor for information.\n");
-		}
+		ata_dev_printk(dev, KERN_WARNING,
+		"Drive reports diagnostics failure. This may indicate a drive\n"
+		"fault or invalid emulation. Contact drive vendor for information.\n");
 	}
 
 	/* limit bridge transfers to udma5, 200 sectors */
 	if (ata_dev_knobble(dev)) {
-		if (ata_msg_drv(ap) && print_info)
-			ata_dev_printk(dev, KERN_INFO,
-				       "applying bridge limits\n");
+		mprintk_push(&mp, ", applying bridge limits");
 		dev->udma_mask &= ATA_UDMA5;
 		dev->max_sectors = ATA_MAX_SECTORS;
 	}
@@ -2336,6 +2378,10 @@ int ata_dev_configure(struct ata_device *dev)
 	if (ap->ops->dev_config)
 		ap->ops->dev_config(dev);
 
+	/* print device info to dmesg */
+	if (ata_msg_drv(ap) && print_info)
+		mprintk(&mp, "\n");
+
 	if (ata_msg_probe(ap))
 		ata_dev_printk(dev, KERN_DEBUG, "%s: EXIT, drv_stat = 0x%x\n",
 			__FUNCTION__, ata_chk_status(ap));
@@ -7577,6 +7623,12 @@ EXPORT_SYMBOL_GPL(sata_deb_timing_hotplug);
 EXPORT_SYMBOL_GPL(sata_deb_timing_long);
 EXPORT_SYMBOL_GPL(ata_dummy_port_ops);
 EXPORT_SYMBOL_GPL(ata_dummy_port_info);
+EXPORT_SYMBOL_GPL(ata_port_printk);
+EXPORT_SYMBOL_GPL(ata_link_printk);
+EXPORT_SYMBOL_GPL(ata_dev_printk);
+EXPORT_SYMBOL_GPL(ata_port_mp_header);
+EXPORT_SYMBOL_GPL(ata_link_mp_header);
+EXPORT_SYMBOL_GPL(ata_dev_mp_header);
 EXPORT_SYMBOL_GPL(ata_std_bios_param);
 EXPORT_SYMBOL_GPL(ata_std_ports);
 EXPORT_SYMBOL_GPL(ata_host_init);
diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 21a81cd..ee2dcea 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -1786,17 +1786,12 @@ static void ata_eh_link_report(struct ata_link *link)
 {
 	struct ata_port *ap = link->ap;
 	struct ata_eh_context *ehc = &link->eh_context;
-	const char *frozen, *desc;
-	char tries_buf[6];
+	struct mprintk mp = MPRINTK_INITIALIZER(ap->sector_buf, ATA_SECT_SIZE);
 	int tag, nr_failed = 0;
 
 	if (ehc->i.flags & ATA_EHI_QUIET)
 		return;
 
-	desc = NULL;
-	if (ehc->i.desc[0] != '\0')
-		desc = ehc->i.desc;
-
 	for (tag = 0; tag < ATA_MAX_QUEUE; tag++) {
 		struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
 
@@ -1813,33 +1808,25 @@ static void ata_eh_link_report(struct ata_link *link)
 	if (!nr_failed && !ehc->i.err_mask)
 		return;
 
-	frozen = "";
-	if (ap->pflags & ATA_PFLAG_FROZEN)
-		frozen = " frozen";
+	if (ehc->i.dev)
+		ata_dev_mp_header(ehc->i.dev, KERN_ERR, &mp);
+	else
+		ata_link_mp_header(link, KERN_ERR, &mp);
 
-	memset(tries_buf, 0, sizeof(tries_buf));
+	mprintk_push(&mp, "exception Emask 0x%x SAct 0x%x SErr 0x%x action 0x%x",
+		     ehc->i.err_mask, link->sactive, ehc->i.serror,
+		     ehc->i.action);
+	if (ap->pflags & ATA_PFLAG_FROZEN)
+		mprintk_push(&mp, " frozen");
 	if (ap->eh_tries < ATA_EH_MAX_TRIES)
-		snprintf(tries_buf, sizeof(tries_buf) - 1, " t%d",
-			 ap->eh_tries);
+		mprintk_push(&mp, " t%d", ap->eh_tries);
+	mprintk_push(&mp, "\n");
 
-	if (ehc->i.dev) {
-		ata_dev_printk(ehc->i.dev, KERN_ERR, "exception Emask 0x%x "
-			       "SAct 0x%x SErr 0x%x action 0x%x%s%s\n",
-			       ehc->i.err_mask, link->sactive, ehc->i.serror,
-			       ehc->i.action, frozen, tries_buf);
-		if (desc)
-			ata_dev_printk(ehc->i.dev, KERN_ERR, "%s\n", desc);
-	} else {
-		ata_link_printk(link, KERN_ERR, "exception Emask 0x%x "
-				"SAct 0x%x SErr 0x%x action 0x%x%s%s\n",
-				ehc->i.err_mask, link->sactive, ehc->i.serror,
-				ehc->i.action, frozen, tries_buf);
-		if (desc)
-			ata_link_printk(link, KERN_ERR, "%s\n", desc);
-	}
+	if (ehc->i.desc[0] != '\0')
+		mprintk_push(&mp, "%s\n", ehc->i.desc);
 
 	if (ehc->i.serror)
-		ata_port_printk(ap, KERN_ERR,
+		mprintk_push(&mp,
 		  "SError: { %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s}\n",
 		  ehc->i.serror & SERR_DATA_RECOVERED ? "RecovData " : "",
 		  ehc->i.serror & SERR_COMM_RECOVERED ? "RecovComm " : "",
@@ -1859,85 +1846,90 @@ static void ata_eh_link_report(struct ata_link *link)
 		  ehc->i.serror & SERR_UNRECOG_FIS ? "UnrecFIS " : "",
 		  ehc->i.serror & SERR_DEV_XCHG ? "DevExch " : "");
 
+	mprintk(&mp, NULL); /* flush link / device wide messages */
+
 	for (tag = 0; tag < ATA_MAX_QUEUE; tag++) {
+		static const char *dma_str[] = {
+			[DMA_BIDIRECTIONAL]	= "bidi",
+			[DMA_TO_DEVICE]		= "out",
+			[DMA_FROM_DEVICE]	= "in",
+		};
+		static const char *prot_str[] = {
+			[ATA_PROT_PIO]		= "pio",
+			[ATA_PROT_DMA]		= "dma",
+			[ATA_PROT_NCQ]		= "ncq",
+			[ATA_PROT_ATAPI]	= "pio",
+			[ATA_PROT_ATAPI_DMA]	= "dma",
+		};
 		struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
 		struct ata_taskfile *cmd = &qc->tf, *res = &qc->result_tf;
 		const u8 *cdb = qc->cdb;
-		char data_buf[20] = "";
-		char cdb_buf[70] = "";
+		int need_newline = 0;
 
 		if (!(qc->flags & ATA_QCFLAG_FAILED) ||
 		    qc->dev->link != link || !qc->err_mask)
 			continue;
 
-		if (qc->dma_dir != DMA_NONE) {
-			static const char *dma_str[] = {
-				[DMA_BIDIRECTIONAL]	= "bidi",
-				[DMA_TO_DEVICE]		= "out",
-				[DMA_FROM_DEVICE]	= "in",
-			};
-			static const char *prot_str[] = {
-				[ATA_PROT_PIO]		= "pio",
-				[ATA_PROT_DMA]		= "dma",
-				[ATA_PROT_NCQ]		= "ncq",
-				[ATA_PROT_ATAPI]	= "pio",
-				[ATA_PROT_ATAPI_DMA]	= "dma",
-			};
-
-			snprintf(data_buf, sizeof(data_buf), " %s %u %s",
-				 prot_str[qc->tf.protocol], qc->nbytes,
-				 dma_str[qc->dma_dir]);
-		}
+		mprintk_push(&mp, "cmd %02x/%02x:%02x:%02x:%02x:%02x/"
+			     "%02x:%02x:%02x:%02x:%02x/%02x tag %d",
+			     cmd->command, cmd->feature, cmd->nsect,
+			     cmd->lbal, cmd->lbam, cmd->lbah,
+			     cmd->hob_feature, cmd->hob_nsect,
+			     cmd->hob_lbal, cmd->hob_lbam, cmd->hob_lbah,
+			     cmd->device, qc->tag);
+
+		if (qc->dma_dir != DMA_NONE)
+			mprintk_push(&mp, " %s %u %s",
+				     prot_str[qc->tf.protocol],
+				     qc->nbytes, dma_str[qc->dma_dir]);
+		mprintk_push(&mp, "\n");
 
 		if (is_atapi_taskfile(&qc->tf))
-			snprintf(cdb_buf, sizeof(cdb_buf),
-				 "cdb %02x %02x %02x %02x %02x %02x %02x %02x  "
-				 "%02x %02x %02x %02x %02x %02x %02x %02x\n         ",
-				 cdb[0], cdb[1], cdb[2], cdb[3],
-				 cdb[4], cdb[5], cdb[6], cdb[7],
-				 cdb[8], cdb[9], cdb[10], cdb[11],
-				 cdb[12], cdb[13], cdb[14], cdb[15]);
-
-		ata_dev_printk(qc->dev, KERN_ERR,
-			"cmd %02x/%02x:%02x:%02x:%02x:%02x/%02x:%02x:%02x:%02x:%02x/%02x "
-			"tag %d%s\n         %s"
-			"res %02x/%02x:%02x:%02x:%02x:%02x/%02x:%02x:%02x:%02x:%02x/%02x "
-			"Emask 0x%x (%s)%s\n",
-			cmd->command, cmd->feature, cmd->nsect,
-			cmd->lbal, cmd->lbam, cmd->lbah,
-			cmd->hob_feature, cmd->hob_nsect,
-			cmd->hob_lbal, cmd->hob_lbam, cmd->hob_lbah,
-			cmd->device, qc->tag, data_buf, cdb_buf,
-			res->command, res->feature, res->nsect,
-			res->lbal, res->lbam, res->lbah,
-			res->hob_feature, res->hob_nsect,
-			res->hob_lbal, res->hob_lbam, res->hob_lbah,
-			res->device, qc->err_mask, ata_err_string(qc->err_mask),
-			qc->err_mask & AC_ERR_NCQ ? " <F>" : "");
+			mprintk_push(&mp, "cdb %02x %02x %02x %02x %02x %02x %02x %02x  "
+				     "%02x %02x %02x %02x %02x %02x %02x %02x\n",
+				     cdb[0], cdb[1], cdb[2], cdb[3],
+				     cdb[4], cdb[5], cdb[6], cdb[7],
+				     cdb[8], cdb[9], cdb[10], cdb[11],
+				     cdb[12], cdb[13], cdb[14], cdb[15]);
+
+		mprintk_push(&mp, "res %02x/%02x:%02x:%02x:%02x:%02x/"
+			     "%02x:%02x:%02x:%02x:%02x/%02x Emask 0x%x (%s)%s\n",
+			     res->command, res->feature, res->nsect,
+			     res->lbal, res->lbam, res->lbah,
+			     res->hob_feature, res->hob_nsect,
+			     res->hob_lbal, res->hob_lbam, res->hob_lbah,
+			     res->device, qc->err_mask,
+			     ata_err_string(qc->err_mask),
+			     qc->err_mask & AC_ERR_NCQ ? " <F>" : "");
 
 		if (res->command & (ATA_BUSY | ATA_DRDY | ATA_DF | ATA_DRQ |
 				    ATA_ERR)) {
 			if (res->command & ATA_BUSY)
-				ata_dev_printk(qc->dev, KERN_ERR,
-				  "status: { Busy }\n");
+				mprintk_push(&mp, "status: { Busy } ");
 			else
-				ata_dev_printk(qc->dev, KERN_ERR,
-				  "status: { %s%s%s%s}\n",
+				mprintk_push(&mp, "status: { %s%s%s%s} ",
 				  res->command & ATA_DRDY ? "DRDY " : "",
 				  res->command & ATA_DF ? "DF " : "",
 				  res->command & ATA_DRQ ? "DRQ " : "",
 				  res->command & ATA_ERR ? "ERR " : "");
+			need_newline = 1;
 		}
 
 		if (cmd->command != ATA_CMD_PACKET &&
 		    (res->feature & (ATA_ICRC | ATA_UNC | ATA_IDNF |
-				     ATA_ABORTED)))
-			ata_dev_printk(qc->dev, KERN_ERR,
-			  "error: { %s%s%s%s}\n",
+				     ATA_ABORTED))) {
+			mprintk_push(&mp, "error: { %s%s%s%s}",
 			  res->feature & ATA_ICRC ? "ICRC " : "",
 			  res->feature & ATA_UNC ? "UNC " : "",
 			  res->feature & ATA_IDNF ? "IDNF " : "",
 			  res->feature & ATA_ABORTED ? "ABRT " : "");
+			need_newline = 1;
+		}
+
+		if (need_newline)
+			mprintk(&mp, "\n");
+		else
+			mprintk(&mp, NULL);
 	}
 }
 
diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c
index caef2bb..80bfa50 100644
--- a/drivers/ata/libata-pmp.c
+++ b/drivers/ata/libata-pmp.c
@@ -408,9 +408,8 @@ static int sata_pmp_configure(struct ata_device *dev, int print_info)
 
 		if (!(dev->flags & ATA_DFLAG_AN))
 			ata_dev_printk(dev, KERN_INFO,
-				"Asynchronous notification not supported, "
-				"hotplug won't\n         work on fan-out "
-				"ports. Use warm-plug instead.\n");
+			"Asynchronous notification not supported, hotplug won't\n"
+			"work on fan-out ports. Use warm-plug instead.\n");
 	}
 
 	return 0;
diff --git a/drivers/ata/libata-scsi.c b/drivers/ata/libata-scsi.c
index 264ae60..7c13663 100644
--- a/drivers/ata/libata-scsi.c
+++ b/drivers/ata/libata-scsi.c
@@ -3207,9 +3207,9 @@ void ata_scsi_scan_host(struct ata_port *ap, int sync)
 			goto repeat;
 		}
 
-		ata_port_printk(ap, KERN_ERR, "WARNING: synchronous SCSI scan "
-				"failed without making any progress,\n"
-				"                  switching to async\n");
+		ata_port_printk(ap, KERN_ERR,
+		"WARNING: synchronous SCSI scan failed without making any \n"
+		"         progress, switching to async\n");
 	}
 
 	queue_delayed_work(ata_aux_wq, &ap->hotplug_task,
diff --git a/drivers/ata/sata_inic162x.c b/drivers/ata/sata_inic162x.c
index 323c087..c45bd38 100644
--- a/drivers/ata/sata_inic162x.c
+++ b/drivers/ata/sata_inic162x.c
@@ -502,7 +502,7 @@ static void inic_dev_config(struct ata_device *dev)
 	if (dev->n_sectors >= 1 << 28) {
 		ata_dev_printk(dev, KERN_ERR,
 	"ERROR: This driver doesn't support LBA48 yet and may cause\n"
-	"                data corruption on such devices.  Disabling.\n");
+	"       data corruption on such devices.  Disabling.\n");
 		ata_dev_disable(dev);
 	}
 }
diff --git a/drivers/ata/sata_nv.c b/drivers/ata/sata_nv.c
index ed5dc7c..7874f61 100644
--- a/drivers/ata/sata_nv.c
+++ b/drivers/ata/sata_nv.c
@@ -1788,8 +1788,8 @@ static void nv_swncq_ncq_stop(struct ata_port *ap)
 			"EH in SWNCQ mode,QC:qc_active 0x%X sactive 0x%X\n",
 			ap->qc_active, ap->link.sactive);
 	ata_port_printk(ap, KERN_ERR,
-		"SWNCQ:qc_active 0x%X defer_bits 0x%X last_issue_tag 0x%x\n  "
-		"dhfis 0x%X dmafis 0x%X sdbfis 0x%X\n",
+		"SWNCQ: qc_active 0x%X defer_bits 0x%X last_issue_tag 0x%x\n"
+		"       dhfis 0x%X dmafis 0x%X sdbfis 0x%X\n",
 		pp->qc_active, pp->defer_queue.defer_bits, pp->last_issue_tag,
 		pp->dhfis_bits, pp->dmafis_bits, pp->sdbfis_bits);
 
diff --git a/include/linux/libata.h b/include/linux/libata.h
index 124033c..c31ea05 100644
--- a/include/linux/libata.h
+++ b/include/linux/libata.h
@@ -773,6 +773,23 @@ static inline int ata_port_is_dummy(struct ata_port *ap)
 	return ap->ops == &ata_dummy_port_ops;
 }
 
+extern int ata_port_printk(struct ata_port *ap, const char *lv,
+			   const char *fmt, ...)
+	__attribute__ ((format (printf, 3, 4)));
+extern int ata_link_printk(struct ata_link *link, const char *lv,
+			   const char *fmt, ...)
+	__attribute__ ((format (printf, 3, 4)));
+extern int ata_dev_printk(struct ata_device *dev, const char *lv,
+			  const char *fmt, ...)
+	__attribute__ ((format (printf, 3, 4)));
+
+extern void ata_port_mp_header(struct ata_port *ap, const char *lv,
+			       struct mprintk *mp);
+extern void ata_link_mp_header(struct ata_link *link, const char *lv,
+			       struct mprintk *mp);
+extern void ata_dev_mp_header(struct ata_device *dev, const char *lv,
+			      struct mprintk *mp);
+
 extern void sata_print_link_status(struct ata_link *link);
 extern void ata_port_probe(struct ata_port *);
 extern void ata_bus_reset(struct ata_port *ap);
@@ -1023,24 +1040,6 @@ extern void ata_do_eh(struct ata_port *ap, ata_prereset_fn_t prereset,
 		      ata_postreset_fn_t postreset);
 
 /*
- * printk helpers
- */
-#define ata_port_printk(ap, lv, fmt, args...) \
-	printk("%sata%u: "fmt, lv, (ap)->print_id , ##args)
-
-#define ata_link_printk(link, lv, fmt, args...) do { \
-	if ((link)->ap->nr_pmp_links) \
-		printk("%sata%u.%02u: "fmt, lv, (link)->ap->print_id,	\
-		       (link)->pmp , ##args); \
-	else \
-		printk("%sata%u: "fmt, lv, (link)->ap->print_id , ##args); \
-	} while(0)
-
-#define ata_dev_printk(dev, lv, fmt, args...) \
-	printk("%sata%u.%02u: "fmt, lv, (dev)->link->ap->print_id,	\
-	       (dev)->link->pmp + (dev)->devno , ##args)
-
-/*
  * ata_eh_info helpers
  */
 extern void __ata_ehi_push_desc(struct ata_eh_info *ehi, const char *fmt, ...)
-- 
1.5.2.4

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Tejun Heo]

Tejun Heo wrote:
> Hello, all.
> 
> This patchset implements printk_header() and mprintk - merging printk
> - to make printing multiline messages and assembling message
> piece-by-piece easier.
> 
> In a nutshell, printk_header() lets you do the following atomically
> (against other messages).
> 
>  code:
>   printk(KERN_INFO "ata1.00: ", "line0\nline1\nline2\n");

That should have been printk_header instead of printk.  Sorry.

-- 
tejun

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Randy Dunlap]

On Wed, 16 Jan 2008 10:00:06 +0900 Tejun Heo wrote:

> Hello, all.
> 
> This patchset implements printk_header() and mprintk - merging printk
> - to make printing multiline messages and assembling message
> piece-by-piece easier.
> 
> In a nutshell, printk_header() lets you do the following atomically
> (against other messages).
> 
>  code:
+   printk_header(KERN_INFO "ata1.00: ", "line0\nline1\nline2\n");
> 
>  output:
>   <6>ata1.00: line0
>   <6>         line1
>   <6>         line2
> 
> And mprintk the following.
> 
>  code:
>   DEFINE_MPRINTK(mp, 2 * 80);
> 
>   mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
>   mprintk_push(&mp, "ATA %d", 7);
>   mprintk_push(&mp, ", %u sectors\n", 1024);
>   mprintk(&mp, "everything seems dandy\n");

Looks pretty good to me except that I would change mprintk_push to
mprintk_add or mprintk_append (I think that I prefer _add).

>  output:
>   <6>ata1.00: ATA 7, 1024 sectors
>   <6>         everything seems dandy
> 
> Please read the commit messages and comments for more detail.  If this
> patchset is accepted, I'll write up Documentation/printk.txt which
> contains describtion of the API and guidelines - "don't pack unrelated
> messages into one" kind of stuff.
> 
> This patchset is against the current linux-2.6#master (031f2dcd) and
> contains the following patches.
> 
> 0001-printk-keep-log-level-on-multiline-messages.patch
> 0002-printk-implement-v-printk_header.patch
> 0003-printk-implement-merging-printk.patch
> 0004-libata-make-libata-use-printk_header-and-mprintk.patch
> 
>  drivers/ata/libata-core.c   |  202 +++++++++++++++----------
>  drivers/ata/libata-eh.c     |  150 ++++++++----------
>  drivers/ata/libata-pmp.c    |    5 
>  drivers/ata/libata-scsi.c   |    6 
>  drivers/ata/sata_inic162x.c |    2 
>  drivers/ata/sata_nv.c       |    4 
>  include/linux/kernel.h      |   83 ++++++++++
>  include/linux/libata.h      |   35 ++--
>  kernel/printk.c             |  354 ++++++++++++++++++++++++++++++++++++++++----
>  9 files changed, 630 insertions(+), 211 deletions(-)
> 
> More than half of the code increase in kernel.h are from the dummy
> declarations for !CONFIG_PRINTK.  More than one third of printk.c
> increase are comments.  On my x86-64 configuration, printk.o grows
> from 30152 to 34128.
> 
> libata code grows slightly but the increase is from converting the
> printk wrapper from #define to proper functions.  The converted areas
> - device configuration and EH reporting - were reduced in comlexity
> and size.  With all-y, drivers/ata/built-in.o shrinks from 726509 to
> 717657 mostly due to the conversion away from macros.


---
~Randy

Re: [PATCH 4/4] libata: make libata use printk_header() and mprintk

[Randy Dunlap]

On Wed, 16 Jan 2008 10:00:10 +0900 Tejun Heo wrote:

> Reimplement libata printk helpers using printk_header, implement
> helpers to initialize mprintk and use mprintk during device
> configuration and EH reporting.
> 
> This fixes various formatting related problems of libata messages such
> as misaligned multiline messages, decoded register lines with leading
> headers making them difficult to tell to which error they belong to,
> awkward manual indents and complex message printing logics.  More
> importantly, by making message assembly flexible, this patch makes
> future changes to device configuration and EH reporting easier.
> 
> Signed-off-by: Tejun Heo <htejun@gmail.com>
> ---
>  drivers/ata/libata-core.c   |  202 +++++++++++++++++++++++++++----------------
>  drivers/ata/libata-eh.c     |  150 +++++++++++++++-----------------
>  drivers/ata/libata-pmp.c    |    5 +-
>  drivers/ata/libata-scsi.c   |    6 +-
>  drivers/ata/sata_inic162x.c |    2 +-
>  drivers/ata/sata_nv.c       |    4 +-
>  include/linux/libata.h      |   35 ++++----
>  7 files changed, 223 insertions(+), 181 deletions(-)
> 
> diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
> index 4753a18..6fac482 100644
> --- a/drivers/ata/libata-core.c
> +++ b/drivers/ata/libata-core.c
> @@ -125,6 +125,79 @@ MODULE_LICENSE("GPL");
>  MODULE_VERSION(DRV_VERSION);
>  
>  

> @@ -2295,23 +2342,18 @@ int ata_dev_configure(struct ata_device *dev)
>  			dev->flags |= ATA_DFLAG_DIPM;
>  	}
>  
> -	if (dev->horkage & ATA_HORKAGE_DIAGNOSTIC) {
> +	if ((dev->horkage & ATA_HORKAGE_DIAGNOSTIC) && print_info) {
>  		/* Let the user know. We don't want to disallow opens for
>  		   rescue purposes, or in case the vendor is just a blithering
>  		   idiot */
> -		if (print_info) {
> -			ata_dev_printk(dev, KERN_WARNING,
> -"Drive reports diagnostics failure. This may indicate a drive\n");
> -			ata_dev_printk(dev, KERN_WARNING,
> -"fault or invalid emulation. Contact drive vendor for information.\n");
> -		}

Looks to me like several of these + lines have indent problems:
following lines (i.e., not first line) of function call should be
indented more than the first line:

> +		ata_dev_printk(dev, KERN_WARNING,
> +		"Drive reports diagnostics failure. This may indicate a drive\n"
> +		"fault or invalid emulation. Contact drive vendor for information.\n");
>  	}
>  
>  	/* limit bridge transfers to udma5, 200 sectors */
>  	if (ata_dev_knobble(dev)) {
> -		if (ata_msg_drv(ap) && print_info)
> -			ata_dev_printk(dev, KERN_INFO,
> -				       "applying bridge limits\n");
> +		mprintk_push(&mp, ", applying bridge limits");
>  		dev->udma_mask &= ATA_UDMA5;
>  		dev->max_sectors = ATA_MAX_SECTORS;
>  	}

> diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c
> index caef2bb..80bfa50 100644
> --- a/drivers/ata/libata-pmp.c
> +++ b/drivers/ata/libata-pmp.c
> @@ -408,9 +408,8 @@ static int sata_pmp_configure(struct ata_device *dev, int print_info)
>  
>  		if (!(dev->flags & ATA_DFLAG_AN))
>  			ata_dev_printk(dev, KERN_INFO,
> -				"Asynchronous notification not supported, "
> -				"hotplug won't\n         work on fan-out "
> -				"ports. Use warm-plug instead.\n");

More indent needed below.

> +			"Asynchronous notification not supported, hotplug won't\n"
> +			"work on fan-out ports. Use warm-plug instead.\n");
>  	}
>  
>  	return 0;
> diff --git a/drivers/ata/libata-scsi.c b/drivers/ata/libata-scsi.c
> index 264ae60..7c13663 100644
> --- a/drivers/ata/libata-scsi.c
> +++ b/drivers/ata/libata-scsi.c
> @@ -3207,9 +3207,9 @@ void ata_scsi_scan_host(struct ata_port *ap, int sync)
>  			goto repeat;
>  		}
>  
> -		ata_port_printk(ap, KERN_ERR, "WARNING: synchronous SCSI scan "
> -				"failed without making any progress,\n"
> -				"                  switching to async\n");
> +		ata_port_printk(ap, KERN_ERR,

More indent needed below.

> +		"WARNING: synchronous SCSI scan failed without making any \n"
> +		"         progress, switching to async\n");
>  	}
>  
>  	queue_delayed_work(ata_aux_wq, &ap->hotplug_task,



---
~Randy

Re: [PATCH 4/4] libata: make libata use printk_header() and mprintk

[Tejun Heo]

Randy Dunlap wrote:
>> -			ata_dev_printk(dev, KERN_WARNING,
>> -"Drive reports diagnostics failure. This may indicate a drive\n");
>> -			ata_dev_printk(dev, KERN_WARNING,
>> -"fault or invalid emulation. Contact drive vendor for information.\n");
>> -		}
> 
> Looks to me like several of these + lines have indent problems:
> following lines (i.e., not first line) of function call should be
> indented more than the first line:

Putting one more tab would put good part of those lines off the 80col
limit.  Hmmm... but I agree it looks ugly.  I'll add one or two spaces
there.

>> +		ata_dev_printk(dev, KERN_WARNING,
>> +		"Drive reports diagnostics failure. This may indicate a drive\n"
>> +		"fault or invalid emulation. Contact drive vendor for information.\n");

Thanks.

-- 
tejun

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Tejun Heo]

Hello,

Randy Dunlap wrote:
>>   mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
>>   mprintk_push(&mp, "ATA %d", 7);
>>   mprintk_push(&mp, ", %u sectors\n", 1024);
>>   mprintk(&mp, "everything seems dandy\n");
> 
> Looks pretty good to me except that I would change mprintk_push to
> mprintk_add or mprintk_append (I think that I prefer _add).

I think push and flush sound good when used together but then again the
flush function isn't visible in the interface and push has LIFO ring to
it.  I'm okay with add.  append seems a bit too long.

Thanks.

-- 
tejun

Re: [PATCH 3/4] printk: implement merging printk

[Randy Dunlap]

On Wed, 16 Jan 2008 10:00:09 +0900 Tejun Heo wrote:


> ---
>  include/linux/kernel.h |   71 ++++++++++++++++
>  kernel/printk.c        |  215 ++++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 286 insertions(+), 0 deletions(-)
> 
> diff --git a/include/linux/kernel.h b/include/linux/kernel.h
> index ade3ac9..f92a4a1 100644
> --- a/include/linux/kernel.h
> +++ b/include/linux/kernel.h
> @@ -175,6 +175,29 @@ extern struct pid *session_of_pgrp(struct pid *pgrp);
>  extern void dump_thread(struct pt_regs *regs, struct user *dump);
>  
>  #ifdef CONFIG_PRINTK
> +struct mprintk {
> +	char *		header;
> +	char *		body;
> +	char *		cur;
> +	char *		prv;
> +	char *		end;

We aren't very consistent about this, but I think that we would prefer

	char		*header;

etc. there.


> +	int		overflowed;
> +};
> +
> +#define MPRINTK_INITIALIZER(_buf, _size)				\
> +	{								\
> +		.header		= NULL,					\
> +		.body		= _buf,					\
> +		.cur		= _buf,					\
> +		.prv		= NULL,					\
> +		.end		= _buf + _size,				\
> +		.overflowed	= 0,					\
> +	}
> +
> +#define DEFINE_MPRINTK(name, size)					\
> +	char __##name##_buf[size];					\
> +	struct mprintk name = MPRINTK_INITIALIZER(__##name##_buf, size)

---
~Randy

Re: [PATCH 3/4] printk: implement merging printk

[Tejun Heo]

Randy Dunlap wrote:
> On Wed, 16 Jan 2008 10:00:09 +0900 Tejun Heo wrote:
> 
> 
>> ---
>>  include/linux/kernel.h |   71 ++++++++++++++++
>>  kernel/printk.c        |  215 ++++++++++++++++++++++++++++++++++++++++++++++++
>>  2 files changed, 286 insertions(+), 0 deletions(-)
>>
>> diff --git a/include/linux/kernel.h b/include/linux/kernel.h
>> index ade3ac9..f92a4a1 100644
>> --- a/include/linux/kernel.h
>> +++ b/include/linux/kernel.h
>> @@ -175,6 +175,29 @@ extern struct pid *session_of_pgrp(struct pid *pgrp);
>>  extern void dump_thread(struct pt_regs *regs, struct user *dump);
>>  
>>  #ifdef CONFIG_PRINTK
>> +struct mprintk {
>> +	char *		header;
>> +	char *		body;
>> +	char *		cur;
>> +	char *		prv;
>> +	char *		end;
> 
> We aren't very consistent about this, but I think that we would prefer
> 
> 	char		*header;
> 
> etc. there.

That's my preference too.  Dunno why I wrote like the above here.  Will
change.

Thanks.

-- 
tejun

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Matt Mackall]

On Wed, 2008-01-16 at 10:00 +0900, Tejun Heo wrote:
> And mprintk the following.
> 
>  code:
>   DEFINE_MPRINTK(mp, 2 * 80);
> 
>   mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
>   mprintk_push(&mp, "ATA %d", 7);
>   mprintk_push(&mp, ", %u sectors\n", 1024);
>   mprintk(&mp, "everything seems dandy\n");

I prefer Matthew Wilcox's stringbuf approach which does proper memory
management and isn't specific to printk:

http://www.ussg.iu.edu/hypermail/linux/kernel/0710.3/0517.html

-- 
Mathematics is the supreme nostalgia of our time.

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Matthew Wilcox]

On Fri, Jan 18, 2008 at 12:41:08PM -0600, Matt Mackall wrote:
> On Wed, 2008-01-16 at 10:00 +0900, Tejun Heo wrote:
> > And mprintk the following.
> > 
> >  code:
> >   DEFINE_MPRINTK(mp, 2 * 80);
> > 
> >   mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
> >   mprintk_push(&mp, "ATA %d", 7);
> >   mprintk_push(&mp, ", %u sectors\n", 1024);
> >   mprintk(&mp, "everything seems dandy\n");
> 
> I prefer Matthew Wilcox's stringbuf approach which does proper memory
> management and isn't specific to printk:
> 
> http://www.ussg.iu.edu/hypermail/linux/kernel/0710.3/0517.html

Do you have any strong feelings whether we should merge my stringbufs or
rusty's version?  I have no particular preference.

-- 
Intel are signing my paycheques ... these opinions are still mine
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours.  We can't possibly take such
a retrograde step."

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Matt Mackall]

On Fri, 2008-01-18 at 11:44 -0700, Matthew Wilcox wrote:
> On Fri, Jan 18, 2008 at 12:41:08PM -0600, Matt Mackall wrote:
> > On Wed, 2008-01-16 at 10:00 +0900, Tejun Heo wrote:
> > > And mprintk the following.
> > > 
> > >  code:
> > >   DEFINE_MPRINTK(mp, 2 * 80);
> > > 
> > >   mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
> > >   mprintk_push(&mp, "ATA %d", 7);
> > >   mprintk_push(&mp, ", %u sectors\n", 1024);
> > >   mprintk(&mp, "everything seems dandy\n");
> > 
> > I prefer Matthew Wilcox's stringbuf approach which does proper memory
> > management and isn't specific to printk:
> > 
> > http://www.ussg.iu.edu/hypermail/linux/kernel/0710.3/0517.html
> 
> Do you have any strong feelings whether we should merge my stringbufs or
> rusty's version?  I have no particular preference.

My vague recollection was that I preferred Rusty's. But it's been a
while.

-- 
Mathematics is the supreme nostalgia of our time.

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Tejun Heo]

Matt Mackall wrote:
> On Wed, 2008-01-16 at 10:00 +0900, Tejun Heo wrote:
>> And mprintk the following.
>>
>>  code:
>>   DEFINE_MPRINTK(mp, 2 * 80);
>>
>>   mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
>>   mprintk_push(&mp, "ATA %d", 7);
>>   mprintk_push(&mp, ", %u sectors\n", 1024);
>>   mprintk(&mp, "everything seems dandy\n");
> 
> I prefer Matthew Wilcox's stringbuf approach which does proper memory
> management and isn't specific to printk:
> 
> http://www.ussg.iu.edu/hypermail/linux/kernel/0710.3/0517.html

Yeap, that's generic and nice but I think both 'generic' and 'proper
memory management' are weakness if what you're trying to do is to
support collecting messages in pieces and putting it out via printk.
Please consider the following scenario.

You're in an interrupt handler and detected a severe error condition
which should be notified to the user but the information is rather
complex and best built in pieces, so you create a stringbuf and does
sb_printf() to it w/ GFP_ATOMIC but alas memory allocation failed and
you end up printing "out of memory" unless you detect the failure and go
back and printk messages piece-by-piece manually.  I would rather
assemble the message manually from the get-go into an on-stack buffer.

By being specifially 'printk' and let the user supply buffer, which in
most cases can be on-stack (messages shouldn't be too long anyway),
mprintk either can avoid those problems from the beginning or can
automatically work around when problem arises (initialized with NULL
buffer from allocation failure) without losing any message, so it's
essentially as simple as using printk.  There is no error handling (both
mprintk and kfree can handle NULL pointer) and the message is guaranteed
to go out no matter what.

Auto-expanding string buffer is nice but I don't think it fits the bill
here.

Thanks.

-- 
tejun

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Matt Mackall]

On Sat, 2008-01-19 at 07:58 +0900, Tejun Heo wrote:
> Matt Mackall wrote:
> > On Wed, 2008-01-16 at 10:00 +0900, Tejun Heo wrote:
> >> And mprintk the following.
> >>
> >>  code:
> >>   DEFINE_MPRINTK(mp, 2 * 80);
> >>
> >>   mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
> >>   mprintk_push(&mp, "ATA %d", 7);
> >>   mprintk_push(&mp, ", %u sectors\n", 1024);
> >>   mprintk(&mp, "everything seems dandy\n");
> > 
> > I prefer Matthew Wilcox's stringbuf approach which does proper memory
> > management and isn't specific to printk:
> > 
> > http://www.ussg.iu.edu/hypermail/linux/kernel/0710.3/0517.html
> 
> Yeap, that's generic and nice but I think both 'generic' and 'proper
> memory management' are weakness if what you're trying to do is to
> support collecting messages in pieces and putting it out via printk.
> Please consider the following scenario.
> 
> You're in an interrupt handler and detected a severe error condition
> which should be notified to the user but the information is rather
> complex and best built in pieces, so you create a stringbuf and does
> sb_printf() to it w/ GFP_ATOMIC but alas memory allocation failed and
> you end up printing "out of memory" unless you detect the failure and go
> back and printk messages piece-by-piece manually.  I would rather
> assemble the message manually from the get-go into an on-stack buffer.

I suppose. I still find this approach less than ideal, especially
putting something potentially large on the stack. The dangers are
perhaps worse than a malloc, really. 

I also don't like your interface much. Consider this alternative:

struct mprintk *mp = mprintk_begin(KERN_INFO "ata%u.%2u: ", 1, 0);
mprintk(mp, "ATA %d", 7);
mprintk(mp, ", %u sectors\n", 1024);
mprintk(mp, "everything seems dandy\n");
mprintk_end(mp);

That keeps all the "normal" printks short and makes the flush more
explict.

Now we make mprintk_begin attempt to do a kmalloc of a moderate size
(512 bytes?) and failing that, return null. Then mprintk can fall
through to printk in the NULL case.

-- 
Mathematics is the supreme nostalgia of our time.

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Tejun Heo]

Matt Mackall wrote:
> I suppose. I still find this approach less than ideal, especially
> putting something potentially large on the stack. The dangers are
> perhaps worse than a malloc, really. 

I pondered on this a bit but the thing is we already use several
hundreds bytes in a function which builds complex messages.  The
original ata_eh_report() implementation allocates 424 bytes on stack for
temp buffers and local variables.  In addition to that, it calls printk
with upto 30 arguments (~240 bytes).  While the new implementation
allocates 232 bytes sans the buffer and the maximum number of arguments
is about sixteen (~128 bytes).  ata_eh_report() uses a fixed buffer but
320byte buffer should be sufficient.

In total, it's 664 vs 680 and that's for a really big message.  mprintk
also allows fixed or malloc'd buffers so if you wanna go bigger,
malloc'd buffer should do the job.

> I also don't like your interface much. Consider this alternative:
> 
> struct mprintk *mp = mprintk_begin(KERN_INFO "ata%u.%2u: ", 1, 0);
> mprintk(mp, "ATA %d", 7);
> mprintk(mp, ", %u sectors\n", 1024);
> mprintk(mp, "everything seems dandy\n");
> mprintk_end(mp);
> 
> That keeps all the "normal" printks short and makes the flush more
> explict.

I like that the more used function is shorter.  Hmmm... The reason why I
first used mprintk_push() is to make it clear that the function
accumulates messages unlike mprintk() which flushes what's accumulated
and prints its own message.

> Now we make mprintk_begin attempt to do a kmalloc of a moderate size
> (512 bytes?) and failing that, return null. Then mprintk can fall
> through to printk in the NULL case.

If you wanna do that implicitly, you need GFP_ flag in mprintk_begin()
and atomic allocation should be used from interrupt handlers and friends
and they fail easily under the right (or wrong) conditions.  Forcing
kmalloc isn't a good idea.  Having multiple initializers is one way to
do it.  Any suggestions?

Thanks.

-- 
tejun

Re: [PATCHSET] printk: implement printk_header() and merging printk

[Matt Mackall]

On Tue, 2008-01-22 at 10:00 +0900, Tejun Heo wrote:
> Matt Mackall wrote:
> > I suppose. I still find this approach less than ideal, especially
> > putting something potentially large on the stack. The dangers are
> > perhaps worse than a malloc, really. 
> 
> I pondered on this a bit but the thing is we already use several
> hundreds bytes in a function which builds complex messages.

Well there are lots of current and potential future users of this
function, many of them down at the end of long call chains. So I'm more
worried about the new cases that embrace this approach and suddenly add
300 bytes of stack. In fact, if this is at all popular, we can expect to
have more than one of these frames on the stack in various paths. 

Given that it only exists to make output prettier, it doesn't -really-
justify increased stack usage.

> > I also don't like your interface much. Consider this alternative:
> > 
> > struct mprintk *mp = mprintk_begin(KERN_INFO "ata%u.%2u: ", 1, 0);
> > mprintk(mp, "ATA %d", 7);
> > mprintk(mp, ", %u sectors\n", 1024);
> > mprintk(mp, "everything seems dandy\n");
> > mprintk_end(mp);
> > 
> > That keeps all the "normal" printks short and makes the flush more
> > explict.
> 
> I like that the more used function is shorter.  Hmmm... The reason why I
> first used mprintk_push() is to make it clear that the function
> accumulates messages unlike mprintk() which flushes what's accumulated
> and prints its own message.
> 
> > Now we make mprintk_begin attempt to do a kmalloc of a moderate size
> > (512 bytes?) and failing that, return null. Then mprintk can fall
> > through to printk in the NULL case.
> 
> If you wanna do that implicitly, you need GFP_ flag in mprintk_begin()
> and atomic allocation should be used from interrupt handlers and friends
> and they fail easily under the right (or wrong) conditions.  Forcing
> kmalloc isn't a good idea.  Having multiple initializers is one way to
> do it.  Any suggestions?

Adding a gfp_flags arg isn't too painful. And we've generally avoided
having separate function calls for atomic vs non-atomic allocation.

Btw, we can also easily hide Willy or Rusty's stringbuf implementation
under the covers here and still have a scheme that automatically falls
back to direct printk..

-- 
Mathematics is the supreme nostalgia of our time.