printk: implement printk_header() and merging printk

PATCH In review Tejun Heo 4 participants 19 messages Jan 16, 2008 – Jan 22, 2008 libata

lore

Share & tools

lore

Tejun Heo

author

2008-01-16 01:00 UTC #1 lore raw

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

In reply to 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 <[email protected]>

---
 kernel/printk.c |   51 ++++++++++++++++++++++++---------------------------
 1 files changed, 24 insertions(+), 27 deletions(-)

kernel/printk.c +24 ~~-27~~

index 89011bf..6df1872 100644
@@ -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;

Signature · 1 line

1.5.2.4

Tejun Heo

author

2008-01-16 01:00 UTC #2 lore raw

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

In reply to 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 <[email protected]>

---
 include/linux/kernel.h |   12 ++++++
 kernel/printk.c        |   94 ++++++++++++++++++++++++++++++++++++++++++++---
 2 files changed, 100 insertions(+), 6 deletions(-)

include/linux/kernel.h +12 -0

index 94bc996..ade3ac9 100644
@@ -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; }

kernel/printk.c +88 -6

131 lines not on this page · raw message

Signature · 1 line

1.5.2.4

Tejun Heo

author

2008-01-16 01:00 UTC #0 lore raw

PATCH 1/1 printk: implement printk_header() and merging printk

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

Tejun Heo

author

2008-01-16 01:00 UTC #3 lore raw

PATCH 3/4 printk: implement merging printk

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 <[email protected]>

---
 include/linux/kernel.h |   71 ++++++++++++++++
 kernel/printk.c        |  215 ++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 286 insertions(+), 0 deletions(-)

include/linux/kernel.h +71 -0

index ade3ac9..f92a4a1 100644
@@ -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; }

kernel/printk.c +215 -0

221 lines not on this page · raw message

Signature · 1 line

1.5.2.4

Tejun Heo

author

2008-01-16 01:00 UTC #6 lore raw

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

In reply to 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 <[email protected]>

---
 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(-)

drivers/ata/libata-core.c +127 ~~-75~~

index 4753a18..6fac482 100644
@@ -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);

drivers/ata/libata-eh.c +71 ~~-79~~

206 lines not on this page · raw message

drivers/ata/libata-pmp.c +2 -3

index caef2bb..80bfa50 100644
@@ -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;

drivers/ata/libata-scsi.c +3 -3

index 264ae60..7c13663 100644
@@ -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,

drivers/ata/sata_inic162x.c +1 -1

index 323c087..c45bd38 100644
@@ -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);
 	}
 }

drivers/ata/sata_nv.c +2 -2

index ed5dc7c..7874f61 100644
@@ -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);

include/linux/libata.h +17 ~~-18~~

index 124033c..c31ea05 100644
@@ -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, ...)

Signature · 1 line

1.5.2.4

Tejun Heo

author

2008-01-16 01:07 UTC #9 lore raw

In reply to Tejun Heo

Quoted 11 lines · 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");

That should have been printk_header instead of printk. Sorry.

Signature · 1 line

tejun

Randy Dunlap

2008-01-16 02:48 UTC #10 lore raw

In reply to Tejun Heo

Quoted 10 lines · 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");

Quoted 8 lines

output:
<6>ata1.00: line0
<6> line1
<6> line2
And mprintk the following.

Quoted 7 lines

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).

Quoted 33 lines

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.

Quoted 5 lines

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

Randy Dunlap

2008-01-16 02:48 UTC #7 lore raw

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

In reply to Tejun Heo

Quoted 36 lines · 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 <[email protected]>
---
 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(-)
drivers/ata/libata-core.c +0 -1
index 4753a18..6fac482 100644
@@ -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) {

drivers/ata/libata-core.c int ata_dev_configure(struct ata_device *dev) · line 2307

Quoted 10 lines

drivers/ata/libata-core.c +1 -6

+	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:

Quoted 20 lines

drivers/ata/libata-core.c +4 -3

+		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;
 	}

drivers/ata/libata-pmp.c +0 -0

index caef2bb..80bfa50 100644

drivers/ata/libata-pmp.c static int sata_pmp_configure(struct ata_device *dev, int print_info) · line 413

Quoted 6 lines

drivers/ata/libata-pmp.c +0 -3

@@ -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.

Quoted 10 lines

drivers/ata/libata-pmp.c +2 -0

+			"Asynchronous notification not supported, hotplug won't\n"
+			"work on fan-out ports. Use warm-plug instead.\n");
 	}
 
 	return 0;

drivers/ata/libata-scsi.c +0 -0

index 264ae60..7c13663 100644

drivers/ata/libata-scsi.c void ata_scsi_scan_host(struct ata_port *ap, int sync) · line 3210

Quoted 7 lines

drivers/ata/libata-scsi.c +1 -3

@@ -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.

drivers/ata/libata-scsi.c void ata_scsi_scan_host(struct ata_port *ap, int sync) · line 3215

Quoted 5 lines

drivers/ata/libata-scsi.c +2 -0

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

---
~Randy

Tejun Heo

author

2008-01-16 02:53 UTC #8 lore raw

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

Quoted 9 lines · Randy Dunlap

drivers/ata/libata-core.c int ata_dev_configure(struct ata_device *dev) · line 2307
Quoted 5 lines
drivers/ata/libata-core.c +0 -5
-			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.

Quoted 3 lines

drivers/ata/libata-core.c int ata_dev_configure(struct ata_device *dev) · line 2351
Quoted 3 lines
drivers/ata/libata-core.c +3 -0
+		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.

Signature · 1 line

tejun

Tejun Heo

author

2008-01-16 02:58 UTC #11 lore raw

In reply to Randy Dunlap

Hello,

Quoted 7 lines · Randy Dunlap

Quoted 4 lines
  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.

Signature · 1 line

tejun

Randy Dunlap

2008-01-16 03:04 UTC #4 lore raw

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

In reply to Tejun Heo

Quoted 10 lines · 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(-)

include/linux/kernel.h +0 -0

index ade3ac9..f92a4a1 100644

include/linux/kernel.h extern struct pid *session_of_pgrp(struct pid *pgrp); · line 183

Quoted 9 lines

include/linux/kernel.h +6 -0

@@ -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.

Quoted 6 lines

include/linux/kernel.h +6 -0

+	int		overflowed;
+};
+
+#define MPRINTK_INITIALIZER(_buf, _size)				\
+	{								\
+		.header		= NULL,					\

include/linux/kernel.h extern struct pid *session_of_pgrp(struct pid *pgrp); · line 199

Quoted 10 lines

include/linux/kernel.h +10 -0

+		.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

Tejun Heo

author

2008-01-16 03:08 UTC #5 lore raw

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

Quoted 25 lines · Randy Dunlap

Quoted 10 lines · 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(-)
include/linux/kernel.h +0 -0
index ade3ac9..f92a4a1 100644
include/linux/kernel.h extern struct pid *session_of_pgrp(struct pid *pgrp); · line 183
Quoted 9 lines
include/linux/kernel.h +6 -0
@@ -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

Quoted 3 lines

	char		*header;
etc. there.

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

Thanks.

Signature · 1 line

tejun

Matt Mackall

2008-01-18 18:42 UTC #12 lore raw

In reply to Tejun Heo

Quoted 9 lines · Tejun Heo

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

Signature · 1 line

Mathematics is the supreme nostalgia of our time.

Matthew Wilcox

2008-01-18 18:44 UTC #13 lore raw

Quoted 11 lines · Matt Mackall

Quoted 9 lines · Tejun Heo
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");

Quoted 4 lines

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.

Signature · 4 lines

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."

Matt Mackall

2008-01-18 19:07 UTC #14 lore raw

Quoted 12 lines · Matthew Wilcox

Quoted 11 lines · Matt Mackall
Quoted 9 lines · Tejun Heo
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");

Quoted 7 lines

Quoted 4 lines
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.

Signature · 1 line

Mathematics is the supreme nostalgia of our time.

Tejun Heo

author

2008-01-18 22:58 UTC #15 lore raw

In reply to Matt Mackall

Quoted 11 lines · Matt Mackall

Quoted 9 lines · Tejun Heo
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");

Quoted 4 lines

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.

Signature · 1 line

tejun

Matt Mackall

2008-01-21 21:44 UTC #16 lore raw

Quoted 22 lines · Tejun Heo

Quoted 11 lines · Matt Mackall
Quoted 9 lines · Tejun Heo
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");
Quoted 4 lines
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.

Quoted 7 lines

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.

Signature · 1 line

Mathematics is the supreme nostalgia of our time.

Tejun Heo

author

2008-01-22 01:01 UTC #17 lore raw

Quoted 3 lines · Matt Mackall

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.

Quoted 10 lines

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.

Quoted 3 lines

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.

Signature · 1 line

tejun

Matt Mackall

2008-01-22 01:30 UTC #18 lore raw

Quoted 7 lines · Tejun Heo

Quoted 3 lines · Matt Mackall
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.

Quoted 20 lines

Quoted 10 lines
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.
Quoted 3 lines
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.

Quoted 5 lines

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..

Signature · 1 line

Mathematics is the supreme nostalgia of our time.