Skip to contentSkip to conversation

Use vprintk rather that vsnprintf where possible

PATCH In review Matt Mackall 6 participants 7 messages Dec 4, 2008 – Dec 7, 2008

Subsystems (13)
SCSI XFS filesystem OCFS2 CPU frequency scaling framework +9 more subsystems
lore
Share & tools
lore

Matt Mackall

author
#0 lore raw

PATCH 1/1 Use vprintk rather that vsnprintf where possible

This does away with lots of large static and on-stack buffers as well as a few associated locks.

Signed-off-by Matt Mackall <[email protected]>
drivers/cpufreq/cpufreq.c +2 -9
diff -r 3341d5094f06 -r b44f20542755 drivers/cpufreq/cpufreq.c
@@ -220,9 +220,7 @@
 void cpufreq_debug_printk(unsigned int type, const char *prefix,
 			const char *fmt, ...)
 {
-	char s[256];
 	va_list args;
-	unsigned int len;
 	unsigned long flags;
 
 	WARN_ON(!prefix);

@@ -235,15 +233,10 @@
 		}
 		spin_unlock_irqrestore(&disable_ratelimit_lock, flags);
 
-		len = snprintf(s, 256, KERN_DEBUG "%s: ", prefix);
-
 		va_start(args, fmt);
-		len += vsnprintf(&s[len], (256 - len), fmt, args);
+		printk(KERN_DEBUG "%s: ", prefix);
+		vprintk(fmt, args);
 		va_end(args);
-
-		printk(s);
-
-		WARN_ON(len < 5);
 	}
 }
 EXPORT_SYMBOL(cpufreq_debug_printk);
drivers/scsi/arm/fas216.c +2 -4
diff -r 3341d5094f06 -r b44f20542755 drivers/scsi/arm/fas216.c
@@ -290,10 +290,8 @@
 static void
 fas216_do_log(FAS216_Info *info, char target, char *fmt, va_list ap)
 {
-	static char buf[1024];
-
-	vsnprintf(buf, sizeof(buf), fmt, ap);
-	printk("scsi%d.%c: %s", info->host->host_no, target, buf);
+	printk("scsi%d.%c: ", info->host->host_no, target, buf);
+	vprintk(fmt, ap);
 }
 
 static void fas216_log_command(FAS216_Info *info, int level,
drivers/scsi/nsp32.c +12 -17
diff -r 3341d5094f06 -r b44f20542755 drivers/scsi/nsp32.c
@@ -323,36 +323,31 @@
 #define NSP32_DEBUG_INIT		BIT(17)
 #define NSP32_SPECIAL_PRINT_REGISTER	BIT(20)
 
-#define NSP32_DEBUG_BUF_LEN		100
-
 static void nsp32_message(const char *func, int line, char *type, char *fmt, ...)
 {
 	va_list args;
-	char buf[NSP32_DEBUG_BUF_LEN];
-
 	va_start(args, fmt);
-	vsnprintf(buf, sizeof(buf), fmt, args);
+#ifndef NSP32_DEBUG
+	printk("%snsp32: ", type);
+#else
+	printk("%snsp32: %s (%d): ", type, func, line);
+#endif
+	vprintk(fmt, args);
+	printk("\n");
 	va_end(args);
-
-#ifndef NSP32_DEBUG
-	printk("%snsp32: %s\n", type, buf);
-#else
-	printk("%snsp32: %s (%d): %s\n", type, func, line, buf);
-#endif
 }
 
 #ifdef NSP32_DEBUG
 static void nsp32_dmessage(const char *func, int line, int mask, char *fmt, ...)
 {
 	va_list args;
-	char buf[NSP32_DEBUG_BUF_LEN];
-
-	va_start(args, fmt);
-	vsnprintf(buf, sizeof(buf), fmt, args);
-	va_end(args);
 
 	if (mask & NSP32_DEBUG_MASK) {
-		printk("nsp32-debug: 0x%x %s (%d): %s\n", mask, func, line, buf);
+		va_start(args, fmt);
+		printk("nsp32-debug: 0x%x %s (%d): ", mask, func, line);
+		vprintk(fmt, args);
+		printk("\n");
+		va_end(args);
 	}
 }
 #endif
drivers/scsi/pcmcia/nsp_cs.c +12 -16
diff -r 3341d5094f06 -r b44f20542755 drivers/scsi/pcmcia/nsp_cs.c
@@ -132,8 +132,6 @@
 #define NSP_DEBUG_DATA_IO      		BIT(18)
 #define NSP_SPECIAL_PRINT_REGISTER	BIT(20)
 
-#define NSP_DEBUG_BUF_LEN		150
-
 static inline void nsp_inc_resid(struct scsi_cmnd *SCpnt, int residInc)
 {
 	scsi_set_resid(SCpnt, scsi_get_resid(SCpnt) + residInc);

@@ -142,31 +140,29 @@
 static void nsp_cs_message(const char *func, int line, char *type, char *fmt, ...)
 {
 	va_list args;
-	char buf[NSP_DEBUG_BUF_LEN];
 
 	va_start(args, fmt);
-	vsnprintf(buf, sizeof(buf), fmt, args);
+#ifndef NSP_DEBUG
+	printk("%snsp_cs: ", type);
+#else
+	printk("%snsp_cs: %s (%d): ", type, func, line);
+#endif
+	vprintk(fmt, args);
+	printk("\n");
 	va_end(args);
-
-#ifndef NSP_DEBUG
-	printk("%snsp_cs: %s\n", type, buf);
-#else
-	printk("%snsp_cs: %s (%d): %s\n", type, func, line, buf);
-#endif
 }
 
 #ifdef NSP_DEBUG
 static void nsp_cs_dmessage(const char *func, int line, int mask, char *fmt, ...)
 {
 	va_list args;
-	char buf[NSP_DEBUG_BUF_LEN];
-
-	va_start(args, fmt);
-	vsnprintf(buf, sizeof(buf), fmt, args);
-	va_end(args);
 
 	if (mask & NSP_DEBUG_MASK) {
-		printk("nsp_cs-debug: 0x%x %s (%d): %s\n", mask, func, line, buf);
+		va_start(args, fmt);
+		printk("nsp_cs-debug: 0x%x %s (%d): ", mask, func, line);
+		vprintk(fmt, args);
+		printk("\n");
+		va_end(args);
 	}
 }
 #endif
fs/adfs/super.c +5 -7
diff -r 3341d5094f06 -r b44f20542755 fs/adfs/super.c
@@ -37,16 +37,14 @@
 
 void __adfs_error(struct super_block *sb, const char *function, const char *fmt, ...)
 {
-	char error_buf[128];
 	va_list args;
-
 	va_start(args, fmt);
-	vsnprintf(error_buf, sizeof(error_buf), fmt, args);
+	printk(KERN_CRIT "ADFS-fs error (device %s)%s%s: ",
+		sb->s_id, function ? ": " : "",
+		function ? function : "");
+	vprintk(fmt, args);
+	printk("\n");
 	va_end(args);
-
-	printk(KERN_CRIT "ADFS-fs error (device %s)%s%s: %s\n",
-		sb->s_id, function ? ": " : "",
-		function ? function : "", error_buf);
 }
 
 static int adfs_checkdiscrecord(struct adfs_discrecord *dr)
fs/affs/amigaffs.c +9 -13
diff -r 3341d5094f06 -r b44f20542755 fs/affs/amigaffs.c
@@ -12,8 +12,6 @@
 
 extern struct timezone sys_tz;
 
-static char ErrorBuffer[256];
-
 /*
  * Functions for accessing Amiga-FFS structures.
  */

@@ -444,14 +442,13 @@
 void
 affs_error(struct super_block *sb, const char *function, const char *fmt, ...)
 {
-	va_list	 args;
-
+	va_list	args;
 	va_start(args,fmt);
-	vsnprintf(ErrorBuffer,sizeof(ErrorBuffer),fmt,args);
+	printk(KERN_CRIT "AFFS error (device %s): %s(): ", sb->s_id, function);
+	vprintk(fmt, args);
+	printk("\n");
 	va_end(args);
 
-	printk(KERN_CRIT "AFFS error (device %s): %s(): %s\n", sb->s_id,
-		function,ErrorBuffer);
 	if (!(sb->s_flags & MS_RDONLY))
 		printk(KERN_WARNING "AFFS: Remounting filesystem read-only\n");
 	sb->s_flags |= MS_RDONLY;

@@ -460,14 +457,13 @@
 void
 affs_warning(struct super_block *sb, const char *function, const char *fmt, ...)
 {
-	va_list	 args;
-
+	va_list	args;
 	va_start(args,fmt);
-	vsnprintf(ErrorBuffer,sizeof(ErrorBuffer),fmt,args);
+	printk(KERN_WARNING "AFFS warning (device %s): %s(): ", sb->s_id,
+		function);
+	vprintk(fmt, args);
+	printk("\n");
 	va_end(args);
-
-	printk(KERN_WARNING "AFFS warning (device %s): %s(): %s\n", sb->s_id,
-		function,ErrorBuffer);
 }
 
 /* Check if the name is valid for a affs object. */
fs/befs/debug.c +9 -38

79 lines not on this page · raw message

fs/hpfs/super.c +2 -5
diff -r 3341d5094f06 -r b44f20542755 fs/hpfs/super.c
@@ -46,18 +46,15 @@
 	}
 }
 
-/* Filesystem error... */
-static char err_buf[1024];
-
 void hpfs_error(struct super_block *s, const char *fmt, ...)
 {
 	va_list args;
 
 	va_start(args, fmt);
-	vsnprintf(err_buf, sizeof(err_buf), fmt, args);
+	printk("HPFS: filesystem error: ");
+	vprintk(fmt, args);
 	va_end(args);
 
-	printk("HPFS: filesystem error: %s", err_buf);
 	if (!hpfs_sb(s)->sb_was_error) {
 		if (hpfs_sb(s)->sb_err == 2) {
 			printk("; crashing the system because you wanted it\n");
fs/jfs/super.c +3 -4
diff -r 3341d5094f06 -r b44f20542755 fs/jfs/super.c
@@ -91,15 +91,14 @@
 
 void jfs_error(struct super_block *sb, const char * function, ...)
 {
-	static char error_buf[256];
 	va_list args;
 
 	va_start(args, function);
-	vsnprintf(error_buf, sizeof(error_buf), function, args);
+	printk(KERN_ERR "ERROR: (device %s): ", sb->s_id);
+	vprintk(function, args);
+	printk("\n");
 	va_end(args);
 
-	printk(KERN_ERR "ERROR: (device %s): %s\n", sb->s_id, error_buf);
-
 	jfs_handle_error(sb);
 }
fs/ntfs/debug.c +20 -30

80 lines not on this page · raw message

fs/ocfs2/super.c +10 -12
diff -r 3341d5094f06 -r b44f20542755 fs/ocfs2/super.c
@@ -1861,22 +1861,20 @@
 	ocfs2_set_ro_flag(osb, 0);
 }
 
-static char error_buf[1024];
-
 void __ocfs2_error(struct super_block *sb,
 		   const char *function,
 		   const char *fmt, ...)
 {
 	va_list args;
 
-	va_start(args, fmt);
-	vsnprintf(error_buf, sizeof(error_buf), fmt, args);
-	va_end(args);
-
 	/* Not using mlog here because we want to show the actual
 	 * function the error came from. */
-	printk(KERN_CRIT "OCFS2: ERROR (device %s): %s: %s\n",
-	       sb->s_id, function, error_buf);
+	va_start(args, fmt);
+	printk(KERN_CRIT "OCFS2: ERROR (device %s): %s: ",
+	       sb->s_id, function);
+	vprintk(fmt, args);
+	printk("\n");
+	va_end(args);
 
 	ocfs2_handle_error(sb);
 }

@@ -1891,12 +1889,12 @@
 	va_list args;
 
 	va_start(args, fmt);
-	vsnprintf(error_buf, sizeof(error_buf), fmt, args);
+	printk(KERN_CRIT "OCFS2: abort (device %s): %s: ",
+	       sb->s_id, function);
+	vprintk(fmt, args);
+	printk("\n");
 	va_end(args);
 
-	printk(KERN_CRIT "OCFS2: abort (device %s): %s: %s\n",
-	       sb->s_id, function, error_buf);
-
 	/* We don't have the cluster support yet to go straight to
 	 * hard readonly in here. Until then, we want to keep
 	 * ocfs2_abort() so that we can at least mark critical
fs/partitions/ldm.c +3 -4
diff -r 3341d5094f06 -r b44f20542755 fs/partitions/ldm.c
@@ -52,14 +52,13 @@
 static void _ldm_printk (const char *level, const char *function,
 			 const char *fmt, ...)
 {
-	static char buf[128];
 	va_list args;
 
 	va_start (args, fmt);
-	vsnprintf (buf, sizeof (buf), fmt, args);
+	printk("%s%s(): ", level, function, buf);
+	vprintk(fmt, args);
+	printk("\n");
 	va_end (args);
-
-	printk ("%s%s(): %s\n", level, function, buf);
 }
 
 /**
fs/udf/super.c +8 -8
diff -r 3341d5094f06 -r b44f20542755 fs/udf/super.c
@@ -76,8 +76,6 @@
 
 #define UDF_DEFAULT_BLOCKSIZE 2048
 
-static char error_buf[1024];
-
 /* These are the "meat" - everything else is stuffing */
 static int udf_fill_super(struct super_block *, void *, int);
 static void udf_put_super(struct super_block *);

@@ -2040,10 +2038,11 @@
 		sb->s_dirt = 1;
 	}
 	va_start(args, fmt);
-	vsnprintf(error_buf, sizeof(error_buf), fmt, args);
+	printk(KERN_CRIT "UDF-fs error (device %s): %s: ",
+		sb->s_id, function);
+	vprintk(fmt, args);
+	printk("\n");
 	va_end(args);
-	printk(KERN_CRIT "UDF-fs error (device %s): %s: %s\n",
-		sb->s_id, function, error_buf);
 }
 
 void udf_warning(struct super_block *sb, const char *function,

@@ -2052,10 +2051,11 @@
 	va_list args;
 
 	va_start(args, fmt);
-	vsnprintf(error_buf, sizeof(error_buf), fmt, args);
+	printk(KERN_WARNING "UDF-fs warning (device %s): %s: ",
+	       sb->s_id, function);
+	vprintk(fmt, args);
+	printk("\n");
 	va_end(args);
-	printk(KERN_WARNING "UDF-fs warning (device %s): %s: %s\n",
-	       sb->s_id, function, error_buf);
 }
 
 static void udf_put_super(struct super_block *sb)
fs/ufs/super.c +23 -23

90 lines not on this page · raw message

fs/xfs/support/debug.c +7 -19
diff -r 3341d5094f06 -r b44f20542755 fs/xfs/support/debug.c
@@ -18,9 +18,6 @@
 #include <xfs.h>
 #include "debug.h"
 
-static char		message[1024];	/* keep it off the stack */
-static DEFINE_SPINLOCK(xfs_err_lock);
-
 /* Translate from CE_FOO to KERN_FOO, err_level(CE_FOO) == KERN_FOO */
 #define XFS_MAX_ERR_LEVEL	7
 #define XFS_ERR_MASK		((1 << 3) - 1)

@@ -40,17 +37,13 @@
 	level &= XFS_ERR_MASK;
 	if (level > XFS_MAX_ERR_LEVEL)
 		level = XFS_MAX_ERR_LEVEL;
-	spin_lock_irqsave(&xfs_err_lock,flags);
+
 	va_start(ap, fmt);
 	if (*fmt == '!') fp++;
-	len = vsnprintf(message, sizeof(message), fp, ap);
-	if (len >= sizeof(message))
-		len = sizeof(message) - 1;
-	if (message[len-1] == '\n')
-		message[len-1] = 0;
-	printk("%s%s\n", err_level[level], message);
+	printk("%s", err_level[level]);
+	vprintk(fp, ap);
+	printk("\n");
 	va_end(ap);
-	spin_unlock_irqrestore(&xfs_err_lock,flags);
 	BUG_ON(level == CE_PANIC);
 }
 

@@ -63,14 +56,9 @@
 	level &= XFS_ERR_MASK;
 	if(level > XFS_MAX_ERR_LEVEL)
 		level = XFS_MAX_ERR_LEVEL;
-	spin_lock_irqsave(&xfs_err_lock,flags);
-	len = vsnprintf(message, sizeof(message), fmt, ap);
-	if (len >= sizeof(message))
-		len = sizeof(message) - 1;
-	if (message[len-1] == '\n')
-		message[len-1] = 0;
-	printk("%s%s\n", err_level[level], message);
-	spin_unlock_irqrestore(&xfs_err_lock,flags);
+	printk("%s", err_level[level]);
+	vprintk(fmt, ap);
+	printk("\n");
 	BUG_ON(level == CE_PANIC);
 }
Signature · 1 line
Mathematics is the supreme nostalgia of our time.
#1 lore raw

drivers/cpufreq/cpufreq.c line 238

Quoted 9 lines · Matt Mackall

This does away with lots of large static and on-stack buffers as well as a few associated locks.

drivers/cpufreq/cpufreq.c +2 -3
-               len = snprintf(s, 256, KERN_DEBUG "%s: ", prefix);
-
               va_start(args, fmt);
-               len += vsnprintf(&s[len], (256 - len), fmt, args);
+               printk(KERN_DEBUG "%s: ", prefix);
+               vprintk(fmt, args);

If we convert to two printk calls for a single line, does that not possibly get mixed up with printks from other locations and lead to hardly readable log output?

Thanks,
Kay

#2 lore raw
Quoted 11 lines · Kay Sievers

drivers/cpufreq/cpufreq.c line 238

Quoted 9 lines · Matt Mackall

This does away with lots of large static and on-stack buffers as well as a few associated locks.

drivers/cpufreq/cpufreq.c +2 -3
-               len = snprintf(s, 256, KERN_DEBUG "%s: ", prefix);
-
               va_start(args, fmt);
-               len += vsnprintf(&s[len], (256 - len), fmt, args);
+               printk(KERN_DEBUG "%s: ", prefix);
+               vprintk(fmt, args);
Quoted 3 lines

If we convert to two printk calls for a single line, does that not possibly get mixed up with printks from other locations and lead to hardly readable log output?

That's right.

Nick.

author
#3 lore raw
In reply to Kay Sievers
Quoted 11 lines · Kay Sievers

drivers/cpufreq/cpufreq.c line 238

Quoted 9 lines · Matt Mackall

This does away with lots of large static and on-stack buffers as well as a few associated locks.

drivers/cpufreq/cpufreq.c +2 -3
-               len = snprintf(s, 256, KERN_DEBUG "%s: ", prefix);
-
               va_start(args, fmt);
-               len += vsnprintf(&s[len], (256 - len), fmt, args);
+               printk(KERN_DEBUG "%s: ", prefix);
+               vprintk(fmt, args);
Quoted 3 lines

If we convert to two printk calls for a single line, does that not possibly get mixed up with printks from other locations and lead to hardly readable log output?

Once upon a time it was not uncommon to get printks interleaved on a character by character basis when things went wrong. That was a bit of a problem but still decipherable with some effort. This shouldn't be much of a problem at all and indeed there are numerous other places where printing is done in multiple pieces.

If we want to deal with the interleaving problem, we should do it by making printk itself smarter rather than having users do bloaty, gross things. Look at the code that's getting replaced here. Some of these things use stack space which has much worse potential failure modes. Others use locking on a static buffer - if that ever hits, we probably lose a message. And the remainder use a static buffer with no locking:
potential garbage output. And of course, the static buffer is wasting space when not in use, which is almost all the time.

Signature · 1 line
Mathematics is the supreme nostalgia of our time.
#4 lore raw
In reply to Kay Sievers
Quoted 3 lines · Kay Sievers

If we convert to two printk calls for a single line, does that not possibly get mixed up with printks from other locations and lead to hardly readable log output?

Yes it does.

There are hundreds of possible interleaves in kernel source today. Adding a couple more isn't horrible.

The changes Matt proposes are good because they make the kernel image smaller with a very minimal chance of deciphering difficulty.

Someday there'll be a "multiline_printk_start/end" mechanism that will avoid interleaving.

#5 lore raw
In reply to Matt Mackall

A diffstat would have been nice, so that a small driver maintainer like me can quickly check whether s/he should have a closer look:

 drivers/cpufreq/cpufreq.c    |   11 +--------
 drivers/scsi/arm/fas216.c    |    6 +----
 drivers/scsi/nsp32.c         |   29 ++++++++++--------------
 drivers/scsi/pcmcia/nsp_cs.c |   28 ++++++++++--------------
 fs/adfs/super.c              |   12 ++++------
 fs/affs/amigaffs.c           |   22 +++++++-----------
 fs/befs/debug.c              |   47 +++++++---------------------------------
 fs/hpfs/super.c              |    7 +-----
 fs/jfs/super.c               |    7 ++----
 fs/ntfs/debug.c              |   50 +++++++++++++++++--------------------------
 fs/ocfs2/super.c             |   22 ++++++++----------
 fs/partitions/ldm.c          |    7 ++----
 fs/udf/super.c               |   16 ++++++-------
 fs/ufs/super.c               |   46 +++++++++++++++++++--------------------
 fs/xfs/support/debug.c       |   28 ++++++------------------
 15 files changed, 127 insertions(+), 211 deletions(-)

shows at a glance who's affected by this.

Also, I'm a big fan of diff's -p option.

Thanks,

Signature · 4 lines
Tilman Schmidt                    E-Mail: [email protected]
Bonn, Germany
Diese Nachricht besteht zu 100% aus wiederverwerteten Bits.
Ungeöffnet mindestens haltbar bis: (siehe Rückseite)
#6 lore raw
In reply to Matt Mackall
Quoted 3 lines · On Thu, 04 Dec 2008 14:41:49 -0600 Matt Mackall <[email protected]> wrote:

This does away with lots of large static and on-stack buffers as well as a few associated locks.

Please add diffstats to the patches.

 drivers/cpufreq/cpufreq.c    |   11 +------
 drivers/scsi/arm/fas216.c    |    6 +---
 drivers/scsi/nsp32.c         |   25 +++++++----------
 drivers/scsi/pcmcia/nsp_cs.c |   24 +++++++---------
 fs/adfs/super.c              |   12 +++-----
 fs/affs/amigaffs.c           |   22 ++++++---------
 fs/befs/debug.c              |   47 ++++++---------------------------
 fs/hpfs/super.c              |    7 +---
 fs/jfs/super.c               |    7 ++--
 fs/ntfs/debug.c              |   46 ++++++++++++--------------------
 fs/ocfs2/super.c             |   22 +++++++--------
 fs/partitions/ldm.c          |    7 ++--
 fs/udf/super.c               |   16 +++++------
 fs/ufs/super.c               |   46 ++++++++++++++++----------------
 fs/xfs/support/debug.c       |   26 ++++--------------
 15 files changed, 121 insertions(+), 203 deletions(-)

argh. I count at least thirteen separate developers who need to review this patch. Many of them would ideally be the ones who merge their piece of it. If they have issues or request updates, that churns the whole patch.

I think I'll skip this one.

Overall it looks sensible (better than what we have now). But maintainers are funny things. Parts of it will survive, others won't.