Skip to contentSkip to conversation

New message-logging API (kprint)

RFC PATCH In review Vegard Nossum 6 participants 18 messages Oct 4, 2007 – Oct 8, 2007

Subsystems (17)
lore
Share & tools
lore
#0 lore raw

RFC PATCH 1/1 New message-logging API (kprint)

Description: This patch largely implements the kprint API as previously posted to the LKML and described in Documentation/kprint.txt (see patch).

The main purpose of this change is provide a unified logging API to the kernel and at the same time make it easy to add extensions, now and later.

My changes and additions are as follows:

1. A general-purpose ring-buffer data structure. This is used by kprint to store the messages, similarly to what printk() does. I've looked, but couldn't find something like this in the kernel already.

2. A generalized printf()-like function (currently called by the somewhat confusing name of args_printf). The function, instead of writing to a string, calls one of several functions submitted through a struct args_ops.

This allows us to skip all the characters from the format string and only output the characters resulting from argument conversion.

It should be noted that this function is a generalization of, and largely copies, the existing snprintf() function. It would be possible to implement snprintf() in terms of the new function if that is preferred.

3. kprint header and source files. These files implements separating the format string from its arguments, and saving them along with extension- specific attributes (for example the current time) to the log.

4. A redefinition of the legacy printk(). The new definition redirects calls made from C to the new kprint() system in a mostly backwards-compatible way. The incompatibility stems from the fact that kprint() does not return the number of characters written to the log. There are several reasons for this; firstly, in order to filter out certain log-levels, the actual call must happen from within an if-block, and thus no value can be returned.

5. Changes to calls in the rest of the kernel that expects kprint() to return a value. These changes are few and mostly trivial. One of the pitfalls of actually using the return value of printk() is that the number is unreliable in terms of how much is written to the log, and how much is written to the console.

6. Calling syslog (in glibc, klogctl()) with a (type|0x10) will access the new kprint buffer instead of the regular log buffer. The kprint buffer is different in that it doesn't record the actual formatted message, but the format string and the (formatted) arguments. Example:

6 0 42949372960000000 arch/um/kernel/mem.c 89 mem_init unknown mem, "Memory: %luk available\x0a", "255104"
7 0 42949372960000000 init/calibrate.c 135 calibrate_delay unknown calibrate, "Calibrating delay loop... ",
4 0 42949373260000000 init/calibrate.c 170 calibrate_delay unknown calibrate, "%lu.%02lu BogoMIPS (lpj=%lu)\x0a", "4246" "73" "21233664" 4 0 42949373260000000 fs/namespace.c 1830 mnt_init unknown namespace, "Mount-cache hash table entries: %d\x0a", "512" 6 0 42949373260000000 net/socket.c 2116 sock_register unknown socket, "NET: Registered protocol family %d\x0a", "16" 6 0 42949373300000000 net/socket.c 2116 sock_register unknown socket, "NET: Registered protocol family %d\x0a", "2"

Each log entry consists of three fields separated by a comma. The first field records attributes assigned with the message. In the example above, these attributes are, in order, log-level, class, timestamp, source file, line in source file, current function, subsystem, and driver/module name.

The second field contains the format string of the message. This can be used to identify a particular string and provide user-space translations of the kernel messages.

The last field contains the arguments to the format string. These arguments can be used to reconstruct (i.e. format) a message at a later time, possibly with a different format string (i.e. a translation).

7. The kprint configuration options can be found under General setup -> Logging.

There are also several unresolved issues: (Help would be appreciated!)

1. As there is not yet a good way to provide compile-time filtering of multi- line messages, this feature is completely omitted for now. Note that printing multiple related messages, or continuing a single message across calls to printk() has always been broken because of the race condition that arises when several tasks want to print messages at the same time, and at least one of those tasks want to print multiple lines or a continuation.

2. The "new" syslog() doesn't check if the caller has the right privileges. To be honest, I don't really know how to do it, apart from looking at what do_syslog() currently does.

3. Certain drivers, like the AIC7xxx SCSI drivers, and a few of the ATM drivers rely on the return value of printk(), and consequently will not compile. I think this is inherently buggy, but as the code is not always trivial to change, the solution for now is to disable these drivers.

Thank you for reading :)

Kind regards,
Vegard Nossum

Documentation/kprint.txt new file +238 -0
new file mode 100644
index 0000000..3046cbc
@@ -0,0 +1,238 @@
+New kernel-message logging API
+
+
+1. Requirements
+
+   * Backwards compatibility with printk(), syslog(), etc. There is no way the 
+whole kernel can be converted to a new interface in one go. printk() is used 
+all over the kernel, in many different ways, including calls from assembly, 
+multi-line prints spread over several calls, etc.
+
+   * Extensibility. Features like eliminating messages below a given threshold 
+or recording the location (i.e. source file/line) of a message [1] should be 
+both selectable at compile-time and (if compiled in) at run-time.
+
+2. API
+
+2.1. linux/kprint.h
+
+  This header defines the primary (i.e. lowest-level) interface to kprint that 
+is made available to the rest of the kernel.
+
+2.1.1. kprint()
+
+	#define kprint(fmt, ...)
+
+  This function is the equivalent of the old printk(), except that it does not 
+take a log-level parameter, but emits messages using the default log-level. The 
+string must be a single line of information (i.e. it must not contain any 
+newlines). kprint() is implemented as a macro, and must not be called from 
+assembly.
+
+2.1.2. Log-levels
+
+  To support the different log-levels, there exists one kprint_*() function for 
+each log-level, for example kprint_info(). This contrasts with the printk() 
+interface, but allows the log-level argument to be passed as an argument 
+(instead of prepending it to the message string) and omitted if the default 
+log-level should be used.
+
+  The string must be a single line of information. Calling 
+kprint_emerg("Oops.") is equivalent to calling printk(KERN_EMERG "Oops.\n"). 
+These functions are implemented as macros, and must not be called from 
+assembly. The different log-levels (and their functions) are:
+
+	enum kprint_loglevel {
+		KPRINT_EMERG,	/* kprint_emerg() */
+		KPRINT_ALERT,	/* kprint_alert() */
+		KPRINT_CRIT,	/* kprint_crit() */
+		KPRINT_ERROR,	/* kprint_err() */
+		KPRINT_WARNING,	/* kprint_warn() */
+		KPRINT_NOTICE,	/* kprint_notice() */
+		KPRINT_INFO,	/* kprint_info() */
+		KPRINT_DEBUG,	/* kprint_debug() */
+	};
+
+  The individual log-levels can be enabled/disabled in the kernel configuration 
+and subsequently removed from the kernel (by the compiler) entirely. It is not 
+an option to filter out messages that are simply above a certain log-level, 
+although it could be more convenient; controlling each log-level is the more 
+general approach and can be used to emulate the threshold filter. [8]
+
+2.1.3. Classification tags
+
+  It turns out that many messages share a similar purpose. It would be useful 
+to classify these by a different scheme than severity [6]. Therefore, an 
+additional four special-purpose macros are defined:
+
+   * printk_detected()    A "hardware detected" message
+   * printk_registered()  A "device driver (un-)registered" message
+   * printk_setting()     A "hardware setting change" message
+   * printk_copyright()   A copyright message, such as module authorship
+                          information
+
+  Each message will be assigned the appropriate log-level for the message class 
+in question.
+
+2.1.4. Blocks
+
+  Note: Blocks are not implemented. The details of the API are not yet worked
+        out.
+
+  In order to print several related lines as one chunk, the emitter should 
+first allocate an object of the type struct kprint_block. This struct is 
+initialized with the function kprint_block_init() which takes as arguments a 
+pointer to an object of the type struct kprint_block followed by the log-level 
+number. The emitter may then make as many or as few calls to kprint_block() 
+that is desired. A final call to kprint_block_flush() appends the messages to 
+the kernel message log in a single, atomic operation. After it has been 
+flushed, the struct is not usable again (unless it is re-initialized). If for 
+any reason the struct should be de-initialized without writing it to the log, a 
+call to kprint_block_abort() must be made.
+
+Example: {
+	struct kprint_block out;
+	kprint_block_init(&out, KPRINT_DEBUG);
+	kprint_block(&out, "Stack trace:");
+
+	while(unwind_stack()) {
+		kprint_block(&out, "%p %s", address, symbol);
+	}
+	kprint_block_flush(&out);
+}
+
+2.1.5. Subsystem/driver tags
+
+  Many parts of the kernel already prefix their log messages with a subsystem 
+and/or driver tag to identify the source of a particular message. With the 
+kprint interface, these tags are redundant. Instead, the macros SUBSYSTEM and 
+KBUILD_MODNAME are used and recorded along with each log message. Therefore, 
+each source file should define the macro SUBSYSTEM before any of the kprint 
+functions are used. If this macro is not defined, the recorded subsystem will 
+be an empty string. [6][7]
+
+2.1.6. Early- and assembly functions
+
+  It may happen that certain parts of the kernel might wish to emit messages to 
+the log (and console, if any) in an early part of the boot procedure, for 
+example before the main memory allocation routines have been set up properly. 
+For this purpose, a function kprint_early() exists. This "early" is a minimal 
+way for the kernel to log its functions, and may as such not include all the 
+features of the full kprint system. When the kernel is beyond the critical 
+"early" point, the messages (if any) in the "early" log may be moved into the 
+main logging store and kprint_early() must not be used again. kprint_early() is 
+a function and may be called from assembly.
+
+  To allow non-early calls from assembly, a function kprint_asm() exists. This 
+function takes a log-level number followed by a string literal and a variable 
+number of arguments.
+
+2.1.7 Backwards compatibility
+
+  The legacy printk() function is replaced by a backwards-compatible interface 
+but different implementation. In short, printk should parse messages, remove 
+(and convert) initial log-level tokens, remove any newlines (splitting the 
+string into several lines), and call the appropriate kprint()-system functions.
+
+  Because printk() itself remains a function with the same specification, all 
+printing/logging mechanisms based on it, such as dev_printk(), sdev_printk(), 
+and ata_dev_printk() will remain functional. Alternatively, the macros could be 
+changed to use the new kprint API.
+
+
+2.2. linux/kprint-light.h
+
+  The kprint "light" interface provides a simpler interface that covers the 
+most frequent usage patterns. It should be noted that this interface is 
+preferred over the primary interface as it encourages the use of a smaller set 
+of log-levels [5].
+
+  The interface consists primarily of the three macros, err(), warn(), and 
+info() that emit messages at the corresponding log-level.
+
+  This header is optional and must not be included by other header files. The 
+names defined by this header are already used by different parts of the kernel, 
+but in different ways. With an optional header, new code (or code converted to 
+the kprint API) can explicitly request these definitions while leaving old 
+locations unchanged.
+
+
+3. Internals
+
+  Most of the kprint entry-points (especially kprint() and its log-level 
+variations) are implemented as macros in order to be able to transparently pass 
+extra information into the main kprint machinery. This makes the interface 
+abstract, because we can change the behaviour (through the configuration and by 
+adding extensions) without changing the calling code. As an example, prepending 
+the current file and line (the __FILE__ and __LINE__ macros) to the message can 
+be done in such a way that it can be discarded at run-time, or recorded along 
+with (but separate from) the messages. This allows the compiler to completely 
+optimize out calls that are below a certain log-level severity level [2][3].
+
+  With such a modular interface, message attributes (for example the current 
+time) and arguments can also be recorded separately from the actual format 
+string, instead of written already formatted to a ring buffer of characters. 
+Parameters would be formatted to their own strings (regardless of the original 
+type) and saved in a list.
+
+Example: {
+	struct kprint_message {
+		const char *format;
+		struct kprint_arg *args;
+
+	#ifdef KPRINT_TIMESTAMP
+		unsigned long long timestamp;
+	#endif
+
+	#ifndef KPRINT_LOCATION
+		const char *file;
+		unsigned int line;
+
+		const char *function;
+	#endif
+	};
+
+	struct kprint_arg {
+		struct kprint_arg *next;
+
+		/* The string formatted argument, regardless
+		 * of original type. */
+		char *arg;
+	};
+}
+
+  This can be a great help, for example in (user-space) localisation of kernel 
+messages [4], since the "static" message (ie. format string) can be translated 
+separately and the arguments re-attached at run-time, possibly in a different 
+order. A new kernel-/user-space interface would be needed to retrieve the 
+messages in this format, though the syslog() and /proc/kmsg interfaces will 
+retain backwards compatibility by formatting messages as they are requested 
+from user-space.
+
+  This does not mean that user-space is obliged provide any form of 
+lookup-/translation tables in order to read the kernel log; the kernel simply 
+hands over the format string used to format a particular message in addition to 
+the full log message, and this format string may be used to easily look up 
+translations (if they exist).
+
+4. Considerations
+
+  This scheme is obviously much more complex than the printk() is today. But at 
+the same time, it is also much more powerful, extensible, and clearly/cleanly 
+defined.
+
+  The kernel can still used a fixed-size ring-buffer for storing the kernel 
+log. With a fixed, static buffer, we are certain to never  run into memory-
+related problems, even if the rest of the system is unstable or unusable.
+
+
+References
+
+[1] http://lkml.org/lkml/2007/9/21/267 (Joe Perches)
+[2] http://lkml.org/lkml/2007/9/20/352 (Rob Landley)
+[3] http://lkml.org/lkml/2007/9/21/151 (Dick Streefland)
+[4] http://lkml.org/lkml/2007/6/13/146 (Michael Holzheu)
+[5] http://lkml.org/lkml/2007/9/24/320 (Jesse Barnes)
+[6] http://lkml.org/lkml/2007/9/22/162 (Miguel Ojeda)
+[7] http://lkml.org/lkml/2007/9/25/62 (Vegard Nossum)
+[8] http://lkml.org/lkml/2007/9/22/157 (Joe Perches)
arch/i386/kernel/traps.c +1 -1
index 47b0bef..70eda51 100644
@@ -198,7 +198,7 @@ EXPORT_SYMBOL(dump_trace);
 static void
 print_trace_warning_symbol(void *data, char *msg, unsigned long symbol)
 {
-	printk(data);
+	printk("%s", data);
 	print_symbol(msg, symbol);
 	printk("\n");
 }
arch/um/include/user.h +4 -2
index d380e6d..c971d93 100644
@@ -19,9 +19,11 @@
  */
 #include <linux/types.h>
 
-extern void panic(const char *fmt, ...)
+extern int printk_asm(const char *fmt, ...)
 	__attribute__ ((format (printf, 1, 2)));
-extern int printk(const char *fmt, ...)
+#define printk printk_asm
+
+extern void panic(const char *fmt, ...)
 	__attribute__ ((format (printf, 1, 2)));
 extern void schedule(void);
 extern int in_aton(char *str);
crypto/tcrypt.c +2 -3
index 11f9359..acdfc45 100644
@@ -874,9 +874,8 @@ static void test_available(void)
 	char **name = check;
 
 	while (*name) {
-		printk("alg %s ", *name);
-		printk(crypto_has_alg(*name, 0, 0) ?
-		       "found\n" : "not found\n");
+		printk("algorithm %s %s\n", *name, crypto_has_alg(*name, 0, 0)
+			? "found" : "not found");
 		name++;
 	}
 }
drivers/char/mem.c +6 -4
index bbee97f..83bd492 100644
@@ -890,10 +890,12 @@ static ssize_t kmsg_write(struct file * file, const char __user * buf,
 	ret = -EFAULT;
 	if (!copy_from_user(tmp, buf, count)) {
 		tmp[count] = 0;
-		ret = printk("%s", tmp);
-		if (ret > count)
-			/* printk can add a prefix */
-			ret = count;
+		printk("%s", tmp);
+
+		/* Instead of saying how many bytes were written to the log,
+		 * including log-level, timestamp, etc., we simply return the
+		 * string length. */
+		ret = strlen(tmp);
 	}
 	kfree(tmp);
 	return ret;
drivers/ide/ide-lib.c +2 -1
index 92a6c7b..5f3061f 100644
@@ -447,7 +447,8 @@ static u8 ide_dump_ata_status(ide_drive_t *drive, const char *msg, u8 stat)
 		printk("%s: %s: error=0x%02x { ", drive->name, msg, err);
 		if (err & ABRT_ERR)	printk("DriveStatusError ");
 		if (err & ICRC_ERR)
-			printk((err & ABRT_ERR) ? "BadCRC " : "BadSector ");
+			printk("%s", (err & ABRT_ERR)
+				? "BadCRC " : "BadSector ");
 		if (err & ECC_ERR)	printk("UncorrectableError ");
 		if (err & ID_ERR)	printk("SectorIdNotFound ");
 		if (err & TRK0_ERR)	printk("TrackZeroNotFound ");
drivers/md/md.c +4 -1
index f883b7e..a04cbcf 100644
@@ -62,7 +62,10 @@
 #define MdpMinorShift 6
 
 #define DEBUG 0
-#define dprintk(x...) ((void)(DEBUG && printk(x)))
+#define dprintk(x...)		\
+	if(DEBUG) {		\
+		 printk(x);	\
+	}
 
 
 #ifndef MODULE
drivers/media/dvb/frontends/tda10021.c +9 -4
index e725f61..c564f64 100644
@@ -351,10 +351,15 @@ static int tda10021_get_frontend(struct dvb_frontend* fe, struct dvb_frontend_pa
 	afc = tda10021_readreg(state, 0x19);
 	if (verbose) {
 		/* AFC only valid when carrier has been recovered */
-		printk(sync & 2 ? "DVB: TDA10021(%d): AFC (%d) %dHz\n" :
-				  "DVB: TDA10021(%d): [AFC (%d) %dHz]\n",
-			state->frontend.dvb->num, afc,
-		       -((s32)p->u.qam.symbol_rate * afc) >> 10);
+		if(sync & 2) {
+			printk("DVB: TDA10021(%d): AFC (%d) %dHz\n",
+				state->frontend.dvb->num, afc,
+			       -((s32)p->u.qam.symbol_rate * afc) >> 10);
+		} else {
+			printk("DVB: TDA10021(%d): [AFC (%d) %dHz]\n",
+				state->frontend.dvb->num, afc,
+			       -((s32)p->u.qam.symbol_rate * afc) >> 10);;
+		}
 	}
 
 	p->inversion = ((state->reg0 & 0x20) == 0x20) ^ (state->config->invert != 0) ? INVERSION_ON : INVERSION_OFF;
drivers/media/dvb/frontends/tda10023.c +9 -4
index 4bb06f9..c3c6e23 100644
@@ -414,10 +414,15 @@ static int tda10023_get_frontend(struct dvb_frontend* fe, struct dvb_frontend_pa
 
 	if (verbose) {
 		/* AFC only valid when carrier has been recovered */
-		printk(sync & 2 ? "DVB: TDA10023(%d): AFC (%d) %dHz\n" :
-				  "DVB: TDA10023(%d): [AFC (%d) %dHz]\n",
-			state->frontend.dvb->num, afc,
-		       -((s32)p->u.qam.symbol_rate * afc) >> 10);
+		if(sync & 2) {
+			printk("DVB: TDA10023(%d): AFC (%d) %dHz\n",
+				state->frontend.dvb->num, afc,
+			       -((s32)p->u.qam.symbol_rate * afc) >> 10);
+		} else {
+			printk("DVB: TDA10023(%d): [AFC (%d) %dHz]\n",
+				state->frontend.dvb->num, afc,
+			       -((s32)p->u.qam.symbol_rate * afc) >> 10);
+		}
 	}
 
 	p->inversion = (inv&0x20?0:1);
drivers/media/dvb/frontends/ves1820.c +7 -2
index 9b57576..e9af469 100644
@@ -319,8 +319,13 @@ static int ves1820_get_frontend(struct dvb_frontend* fe, struct dvb_frontend_par
 	afc = ves1820_readreg(state, 0x19);
 	if (verbose) {
 		/* AFC only valid when carrier has been recovered */
-		printk(sync & 2 ? "ves1820: AFC (%d) %dHz\n" :
-			"ves1820: [AFC (%d) %dHz]\n", afc, -((s32) p->u.qam.symbol_rate * afc) >> 10);
+		if(sync & 2) {
+			printk("ves1820: AFC (%d) %dHz\n", afc,
+				-((s32) p->u.qam.symbol_rate * afc) >> 10);
+		} else {
+			printk("ves1820: [AFC (%d) %dHz]\n", afc,
+				-((s32) p->u.qam.symbol_rate * afc) >> 10);
+		}
 	}
 
 	if (!state->config->invert) {
drivers/media/video/em28xx/em28xx-core.c +12 -4
index 255a47d..5a1f398 100644
@@ -148,8 +148,12 @@ int em28xx_read_reg_req_len(struct em28xx *dev, u8 req, u16 reg,
 			      USB_DIR_IN | USB_TYPE_VENDOR | USB_RECIP_DEVICE,
 			      0x0000, reg, buf, len, HZ);
 
-	if (reg_debug){
-		printk(ret < 0 ? " failed!\n" : "%02x values: ", ret);
+	if (reg_debug) {
+		if(ret < 0)
+			printk(" failed!\n");
+		else
+			printk("%02x values: ", ret);
+
 		for (byte = 0; byte < len; byte++) {
 			printk(" %02x", buf[byte]);
 		}
@@ -177,8 +181,12 @@ int em28xx_read_reg_req(struct em28xx *dev, u8 req, u16 reg)
 			      USB_DIR_IN | USB_TYPE_VENDOR | USB_RECIP_DEVICE,
 			      0x0000, reg, &val, 1, HZ);
 
-	if (reg_debug)
-		printk(ret < 0 ? " failed!\n" : "%02x\n", val);
+	if (reg_debug) {
+		if(ret < 0)
+			printk(" failed!\n");
+		else
+			printk("%02x\n", val);
+	}
 
 	if (ret < 0)
 		return ret;
drivers/media/video/usbvideo/usbvideo.h +6 -1
index 051775d..39fdadc 100644
@@ -22,7 +22,12 @@
 #include <linux/mutex.h>
 
 /* Most helpful debugging aid */
-#define assert(expr) ((void) ((expr) ? 0 : (err("assert failed at line %d",__LINE__))))
+#define assert(expr)							\
+	do {								\
+		if(!(expr)) {						\
+			err("assert failed at line %d", __LINE__);	\
+		}							\
+	} while(0)
 
 #define USBVIDEO_REPORT_STATS	1	/* Set to 0 to block statistics on close */
 
drivers/net/e100.c +7 -3
index 280313b..b4a7dbc 100644
@@ -182,9 +182,13 @@ MODULE_PARM_DESC(debug, "Debug level (0=none,...,16=all)");
 MODULE_PARM_DESC(eeprom_bad_csum_allow, "Allow bad eeprom checksums");
 MODULE_PARM_DESC(use_io, "Force use of i/o access mode");
 #define DPRINTK(nlevel, klevel, fmt, args...) \
-	(void)((NETIF_MSG_##nlevel & nic->msg_enable) && \
-	printk(KERN_##klevel PFX "%s: %s: " fmt, nic->netdev->name, \
-		__FUNCTION__ , ## args))
+	do {								\
+		if(NETIF_MSG_##nlevel & nic->msg_enable) {		\
+			printk(KERN_##klevel PFX "%s: %s: " fmt,	\
+				nic->netdev->name,			\
+				__FUNCTION__ , ## args);		\
+		}							\
+	} while(0)
 
 #define INTEL_8255X_ETHERNET_DEVICE(device_id, ich) {\
 	PCI_VENDOR_ID_INTEL, device_id, PCI_ANY_ID, PCI_ANY_ID, \
drivers/net/e1000/e1000.h +8 -4
index 16a6edf..5445616 100644
@@ -90,10 +90,14 @@ struct e1000_adapter;
 #define E1000_ERR(args...) printk(KERN_ERR "e1000: " args)
 
 #define PFX "e1000: "
-#define DPRINTK(nlevel, klevel, fmt, args...) \
-	(void)((NETIF_MSG_##nlevel & adapter->msg_enable) && \
-	printk(KERN_##klevel PFX "%s: %s: " fmt, adapter->netdev->name, \
-		__FUNCTION__ , ## args))
+#define DPRINTK(nlevel, klevel, fmt, args...)				\
+	do {								\
+		if(NETIF_MSG_##nlevel & adapter->msg_enable) {		\
+			printk(KERN_##klevel PFX "%s: %s: " fmt,	\
+				adapter->netdev->name, __FUNCTION__,	\
+				## args);				\
+		}							\
+	} while(0)
 
 #define E1000_MAX_INTR 10
 
drivers/net/irda/ma600.c +4 -1
index f5e6836..bd59424 100644
@@ -44,7 +44,10 @@
 
 #ifndef NDEBUG
 	#undef IRDA_DEBUG
-	#define IRDA_DEBUG(n, args...) (printk(KERN_DEBUG args))
+	#define IRDA_DEBUG(n, args...)			\
+		do {					\
+			printk(KERN_DEBUG args);	\
+		} while(0)
 
 	#undef ASSERT
 	#define ASSERT(expr, func) \
drivers/net/ixgb/ixgb.h +7 -4
index 3569d5b..f40502b 100644
@@ -82,10 +82,13 @@ struct ixgb_adapter;
 #endif
 
 #define PFX "ixgb: "
-#define DPRINTK(nlevel, klevel, fmt, args...) \
-	(void)((NETIF_MSG_##nlevel & adapter->msg_enable) && \
-	printk(KERN_##klevel PFX "%s: %s: " fmt, adapter->netdev->name, \
-		__FUNCTION__ , ## args))
+#define DPRINTK(nlevel, klevel, fmt, args...)				\
+	do {								\
+		if(NETIF_MSG_##nlevel & adapter->msg_enable) {		\
+			printk(KERN_##klevel PFX "%s: %s: " fmt,	\
+			adapter->netdev->name, __FUNCTION__, ## args);	\
+		}							\
+	} while(0)
 
 
 /* TX/RX descriptor defines */
drivers/net/lib8390.c +11 -6
index c429a50..d2e2238 100644
@@ -1,4 +1,3 @@
-/* 8390.c: A general NS8390 ethernet driver core for linux. */
 /*
 	Written 1992-94 by Donald Becker.
 
@@ -451,11 +450,17 @@ static irqreturn_t __ei_interrupt(int irq, void *dev_id)
 	{
 #if 1 /* This might just be an interrupt for a PCI device sharing this line */
 		/* The "irqlock" check is only for testing. */
-		printk(ei_local->irqlock
-			   ? "%s: Interrupted while interrupts are masked! isr=%#2x imr=%#2x.\n"
-			   : "%s: Reentering the interrupt handler! isr=%#2x imr=%#2x.\n",
-			   dev->name, ei_inb_p(e8390_base + EN0_ISR),
-			   ei_inb_p(e8390_base + EN0_IMR));
+		if(ei_local->irqlock) {
+			printk("%s: Interrupted while interrupts are masked! "
+				"isr=%#2x imr=%#2x.\n", 
+				dev->name, ei_inb_p(e8390_base + EN0_ISR),
+				ei_inb_p(e8390_base + EN0_IMR));
+		} else {
+			printk("%s: Reentering the interrupt handler! "
+				"isr=%#2x imr=%#2x.\n",
+				dev->name, ei_inb_p(e8390_base + EN0_ISR),
+				ei_inb_p(e8390_base + EN0_IMR));
+		}
 #endif
 		spin_unlock(&ei_local->page_lock);
 		return IRQ_NONE;
drivers/net/pcmcia/axnet_cs.c +9 -3
index 50dff1b..8051b5c 100644
@@ -1213,11 +1213,17 @@ static irqreturn_t ax_interrupt(int irq, void *dev_id)
 	{
 #if 1 /* This might just be an interrupt for a PCI device sharing this line */
 		/* The "irqlock" check is only for testing. */
-		printk(ei_local->irqlock
-			   ? "%s: Interrupted while interrupts are masked! isr=%#2x imr=%#2x.\n"
-			   : "%s: Reentering the interrupt handler! isr=%#2x imr=%#2x.\n",
+		if(ei_local->irqlock) {
+			printk("%s: Interrupted while interrupts are masked! "
+				" isr=%#2x imr=%#2x.\n",
 			   dev->name, inb_p(e8390_base + EN0_ISR),
 			   inb_p(e8390_base + EN0_IMR));
+		} else {
+			printk("%s: Reentering the interrupt handler! "
+				"isr=%#2x imr=%#2x.\n",
+			   dev->name, inb_p(e8390_base + EN0_ISR),
+			   inb_p(e8390_base + EN0_IMR));
+		}
 #endif
 		spin_unlock(&ei_local->page_lock);
 		return IRQ_NONE;
drivers/pcmcia/rsrc_nonstatic.c +8 -2
index bfcaad6..d90ebb6 100644
@@ -248,7 +248,10 @@ static void do_io_probe(struct pcmcia_socket *s, kio_addr_t base, kio_addr_t num
 	}
     }
 
-    printk(any ? "\n" : " clean.\n");
+    if(any)
+	printk("\n");
+    else
+	printk(" clean.\n");
 }
 #endif
 
@@ -396,7 +399,10 @@ static int do_mem_probe(u_long base, u_long num, struct pcmcia_socket *s)
 	    bad += j-i;
 	}
     }
-    printk(bad ? "\n" : " clean.\n");
+    if(bad)
+	printk("\n");
+    else
+	printk(" clean.\n");
     return (num - bad);
 }
 
drivers/scsi/advansys.c +1 -1
index 79c0b6e..712bf9f 100644
@@ -7417,7 +7417,7 @@ static int asc_prt_line(char *buf, int buflen, char *fmt, ...)
 	ret = vsprintf(s, fmt, args);
 	ASC_ASSERT(ret < ASC_PRTLINE_SIZE);
 	if (buf == NULL) {
-		(void)printk(s);
+		printk(s);
 		ret = 0;
 	} else {
 		ret = min(buflen, ret);
include/asm-generic/pgtable-nopmd.h +4 -1
index 29ff5d8..3f9e8d8 100644
@@ -28,7 +28,10 @@ static inline int pud_none(pud_t pud)		{ return 0; }
 static inline int pud_bad(pud_t pud)		{ return 0; }
 static inline int pud_present(pud_t pud)	{ return 1; }
 static inline void pud_clear(pud_t *pud)	{ }
-#define pmd_ERROR(pmd)				(pud_ERROR((pmd).pud))
+#define pmd_ERROR(pmd)			\
+	do {				\
+		pud_ERROR((pmd).pud);	\
+	} while(0)
 
 #define pud_populate(mm, pmd, pte)		do { } while (0)
 
include/asm-generic/pgtable-nopud.h +4 -1
index 5664645..b091db1 100644
@@ -26,7 +26,10 @@ static inline int pgd_none(pgd_t pgd)		{ return 0; }
 static inline int pgd_bad(pgd_t pgd)		{ return 0; }
 static inline int pgd_present(pgd_t pgd)	{ return 1; }
 static inline void pgd_clear(pgd_t *pgd)	{ }
-#define pud_ERROR(pud)				(pgd_ERROR((pud).pgd))
+#define pud_ERROR(pud)			\
+	do {				\
+		pgd_ERROR((pud).pgd);	\
+	} while(0)
 
 #define pgd_populate(mm, pgd, pud)		do { } while (0)
 /*
include/linux/args.h new file +29 -0
new file mode 100644
index 0000000..7ad1e02
@@ -0,0 +1,29 @@
+/*
+ * Copyright (C) 2007  Vegard Nossum
+ */
+
+#ifndef LINUX_ARGS_H
+#define LINUX_ARGS_H
+
+#include <linux/kernel.h>
+
+struct args_ops {
+	void (*begin)(void *data);
+	void (*end)(void *data);
+	void (*put_format)(void *data, char c);
+
+	void (*begin_param)(void *data);
+	void (*end_param)(void *data);
+	void (*put_param)(void *data, char c);
+
+	void (*unknown_conversion)(void *data, char c);
+};
+
+extern void args_printf(void *data, const struct args_ops *ops,
+	const char *fmt, ...)
+	__attribute__ ((format (printf, 3, 4)));
+extern void args_vprintf(void *data, const struct args_ops *ops,
+	const char *fmt, va_list args)
+	__attribute__ ((format (printf, 3, 0)));
+
+#endif
include/linux/kernel.h +24 -3
index 47160fe..f014b7c 100644
@@ -14,6 +14,7 @@
 #include <linux/compiler.h>
 #include <linux/bitops.h>
 #include <linux/log2.h>
+#include <linux/kprint.h>
 #include <asm/byteorder.h>
 #include <asm/bug.h>
 
@@ -155,15 +156,35 @@ extern void dump_thread(struct pt_regs *regs, struct user *dump);
 #ifdef CONFIG_PRINTK
 asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
-asmlinkage int printk(const char * fmt, ...)
+asmlinkage int printk_asm(const char * fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
 #else
 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; }
-static inline int printk(const char *s, ...)
+static inline int printk_asm(const char *s, ...)
 	__attribute__ ((format (printf, 1, 2)));
-static inline int __cold printk(const char *s, ...) { return 0; }
+static inline int __cold printk_asm(const char *s, ...) { return 0; }
+#endif
+
+#ifdef __ASSEMBLY__
+/* Redirect printk() to a backwards-compatible kprint. */
+#define printk kprint_asm
+#endif
+
+#ifndef __ASSEMBLY__
+/* Redirect printk() to kprint. */
+#define printk(fmt, ...)						\
+	do {								\
+		if(fmt[0] == '<' && fmt[1] >= '0' &&			\
+			fmt[1] <= '9' && fmt[2] == '>')			\
+		{							\
+			kprint_wrapper(fmt[1] - '0', KPRINT_NO_CLASS,	\
+				fmt, ## __VA_ARGS__);			\
+		} else {						\
+			kprint(fmt, ## __VA_ARGS__);			\
+		}							\
+	} while(0)
 #endif
 
 unsigned long int_sqrt(unsigned long);
include/linux/kprint-light.h new file +25 -0
new file mode 100644
index 0000000..f51ce71
@@ -0,0 +1,25 @@
+/*
+ * Message-logging API
+ * Copyright (C) 2007  Vegard Nossum
+ */
+
+/**
+ * Do not include this header from other headers! (i.e. Don't enforce these
+ * definitions on anybody, since they're fairly common names.)
+ */
+
+#ifndef LINUX_KPRINT_LIGHT_H
+#define LINUX_KPRINT_LIGHT_H
+
+#include <linux/kprint.h>
+
+#define err(fmt, ...) \
+	kprint_err(fmt, ## __VA_ARGS__)
+
+#define warn(fmt, ...) \
+	kprint_warn(fmt, ## __VA_ARGS__)
+
+#define info(fmt, ...) \
+	kprint_info(fmt, ## __VA_ARGS__)
+
+#endif
include/linux/kprint.h new file +201 -0

201 lines not on this page · raw message

include/linux/ringbuffer.h new file +34 -0
new file mode 100644
index 0000000..814bbe5
@@ -0,0 +1,34 @@
+/*
+ * General-purpose ring-buffer data structure
+ * Copyright (C) 2007  Vegard Nossum
+ */
+
+#ifndef LINUX_RINGBUFFER_H
+#define LINUX_RINGBUFFER_H
+
+#include <linux/kernel.h>
+
+struct ringbuffer {
+	char *data;
+	unsigned int size;
+	unsigned int mask;
+
+	unsigned int wr;
+	unsigned int rd;
+
+	unsigned int fill_count;
+};
+
+void ringbuffer_init(struct ringbuffer *rb, char *data, unsigned int size);
+void ringbuffer_clear(struct ringbuffer *rb);
+unsigned int ringbuffer_fill_count(struct ringbuffer *rb);
+unsigned int ringbuffer_write(struct ringbuffer *rb,
+	const char *data, unsigned int size);
+unsigned int ringbuffer_read(struct ringbuffer *rb,
+	char  *data, unsigned int size);
+unsigned int ringbuffer_write_user(struct ringbuffer *rb,
+	const char __user *data, unsigned int size);
+unsigned int ringbuffer_read_user(struct ringbuffer *rb,
+	char __user *data, unsigned int size);
+
+#endif
include/net/sctp/sctp.h +5 -1
index c9cc00c..224a672 100644
@@ -288,7 +288,11 @@ struct sctp_mib {
 #if SCTP_DEBUG
 extern int sctp_debug_flag;
 #define SCTP_DEBUG_PRINTK(whatever...) \
-	((void) (sctp_debug_flag && printk(KERN_DEBUG whatever)))
+	do { \
+		if(sctp_debug_flag) { \
+			 printk(KERN_DEBUG whatever); \
+		} \
+	} while(0)
 #define SCTP_DEBUG_PRINTK_IPADDR(lead, trail, leadparm, saddr, otherparms...) \
 	if (sctp_debug_flag) { \
 		if (saddr->sa.sa_family == AF_INET6) { \
include/scsi/scsi_device.h +10 -4
index d5057bc..4186d93 100644
@@ -157,10 +157,16 @@ struct scsi_device {
 	dev_printk(prefix, &(sdev)->sdev_gendev, fmt, ##a)
 
 #define scmd_printk(prefix, scmd, fmt, a...)				\
-        (scmd)->request->rq_disk ?					\
-	sdev_printk(prefix, (scmd)->device, "[%s] " fmt,		\
-		    (scmd)->request->rq_disk->disk_name, ##a) :		\
-	sdev_printk(prefix, (scmd)->device, fmt, ##a)
+	do {								\
+		if((scmd)->request->rq_disk) {				\
+			sdev_printk(prefix, (scmd)->device,		\
+				"[%s] " fmt,				\
+				(scmd)->request->rq_disk->disk_name,	\
+				##a);					\
+		} else {						\
+			sdev_printk(prefix, (scmd)->device, fmt, ##a);	\
+		}							\
+	} while(0)
 
 enum scsi_target_state {
 	STARGET_RUNNING = 1,
include/scsi/sd.h +9 -4
index ce02ad1..3d98e29 100644
@@ -62,9 +62,14 @@ static void sd_print_sense_hdr(struct scsi_disk *, struct scsi_sense_hdr *);
 static void sd_print_result(struct scsi_disk *, int);
 
 #define sd_printk(prefix, sdsk, fmt, a...)				\
-        (sdsk)->disk ?							\
-	sdev_printk(prefix, (sdsk)->device, "[%s] " fmt,		\
-		    (sdsk)->disk->disk_name, ##a) :			\
-	sdev_printk(prefix, (sdsk)->device, fmt, ##a)
+	do {								\
+		if((sdsk)->disk) {					\
+			sdev_printk(prefix, (sdsk)->device,		\
+			"[%s] " fmt,					\
+			(sdsk)->disk->disk_name, ##a);			\
+		} else {						\
+			sdev_printk(prefix, (sdsk)->device, fmt, ##a);	\
+		}							\
+	} while(0)
 
 #endif /* _SCSI_DISK_H */
init/Kconfig +2 -0
index d54d0ca..9848295 100644
@@ -571,6 +571,8 @@ config SLOB
 
 endchoice
 
+source "kernel/Kconfig.kprint"
+
 endmenu		# General setup
 
 config RT_MUTEXES
init/do_mounts_initrd.c +1 -1
index fd4fc12..385a39e 100644
@@ -98,7 +98,7 @@ static void __init handle_initrd(void)
 			error = sys_ioctl(fd, BLKFLSBUF, 0);
 			sys_close(fd);
 		}
-		printk(!error ? "okay\n" : "failed\n");
+		printk("%s\n", error ? "failed" : "okay");
 	}
 }
 
kernel/Kconfig.kprint new file +125 -0

125 lines not on this page · raw message

kernel/Makefile +1 -1
index 2a99983..3eb28f3 100644
@@ -9,7 +9,7 @@ obj-y     = sched.o fork.o exec_domain.o panic.o printk.o profile.o \
 	    rcupdate.o extable.o params.o posix-timers.o \
 	    kthread.o wait.o kfifo.o sys_ni.o posix-cpu-timers.o mutex.o \
 	    hrtimer.o rwsem.o latency.o nsproxy.o srcu.o die_notifier.o \
-	    utsname.o
+	    utsname.o kprint.o
 
 obj-$(CONFIG_STACKTRACE) += stacktrace.o
 obj-y += time/
kernel/kprint.c new file +345 -0

345 lines not on this page · raw message

kernel/printk.c +7 -2
index 8451dfc..d6a81cc 100644
@@ -312,8 +312,13 @@ out:
 	return error;
 }
 
+extern int do_syslog_kprint(int type, char __user *buf, int len);
+
 asmlinkage long sys_syslog(int type, char __user *buf, int len)
 {
+	if(type & 0x10)
+		return do_syslog_kprint(type & ~0x10, buf, len);
+
 	return do_syslog(type, buf, len);
 }
 
@@ -504,7 +509,7 @@ static int have_callable_console(void)
  * printf(3)
  */
 
-asmlinkage int printk(const char *fmt, ...)
+asmlinkage int printk_asm(const char *fmt, ...)
 {
 	va_list args;
 	int r;
@@ -639,7 +644,7 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	preempt_enable();
 	return printed_len;
 }
-EXPORT_SYMBOL(printk);
+EXPORT_SYMBOL(printk_asm);
 EXPORT_SYMBOL(vprintk);
 
 #else
lib/Makefile +2 -1
index 6b0ba8c..608b552 100644
@@ -5,7 +5,8 @@
 lib-y := ctype.o string.o vsprintf.o kasprintf.o cmdline.o \
 	 rbtree.o radix-tree.o dump_stack.o \
 	 idr.o int_sqrt.o bitmap.o extable.o prio_tree.o \
-	 sha1.o irq_regs.o reciprocal_div.o argv_split.o
+	 sha1.o irq_regs.o reciprocal_div.o argv_split.o \
+	 ringbuffer.o
 
 lib-$(CONFIG_MMU) += ioremap.o
 lib-$(CONFIG_SMP) += cpumask.o
lib/ringbuffer.c new file +155 -0

155 lines not on this page · raw message

lib/vsprintf.c +321 -0

345 lines not on this page · raw message

net/tipc/dbg.c +1 -1
index e809d2a..d00fa22 100644
@@ -288,7 +288,7 @@ static void print_to_console(char *crs, int len)
 		char c = crs[sz];
 
 		crs[sz] = 0;
-		printk((const char *)crs);
+		printk("%s", crs);
 		crs[sz] = c;
 		rest -= sz;
 		crs += sz;
#1 lore raw
Quoted 7 lines · On Thu, 04 Oct 2007 22:04:07 +0200 Vegard Nossum wrote:

Description: This patch largely implements the kprint API as previously posted to the LKML and described in Documentation/kprint.txt (see patch).

The main purpose of this change is provide a unified logging API to the kernel and at the same time make it easy to add extensions, now and later.

My changes and additions are as follows:

$ diffstat -p1 -w70 kprint.patch 
 Documentation/kprint.txt                 |  238 ++++++++++++++
 arch/i386/kernel/traps.c                 |    2 
 arch/um/include/user.h                   |    6 
 crypto/tcrypt.c                          |    5 
 drivers/char/mem.c                       |   10 
 drivers/ide/ide-lib.c                    |    3 
 drivers/md/md.c                          |    5 
 drivers/media/dvb/frontends/tda10021.c   |   13 
 drivers/media/dvb/frontends/tda10023.c   |   13 
 drivers/media/dvb/frontends/ves1820.c    |    9 
 drivers/media/video/em28xx/em28xx-core.c |   16 
 drivers/media/video/usbvideo/usbvideo.h  |    7 
 drivers/net/e100.c                       |   10 
 drivers/net/e1000/e1000.h                |   12 
 drivers/net/irda/ma600.c                 |    5 
 drivers/net/ixgb/ixgb.h                  |   11 
 drivers/net/lib8390.c                    |   17 -
 drivers/net/pcmcia/axnet_cs.c            |   12 
 drivers/pcmcia/rsrc_nonstatic.c          |   10 
 drivers/scsi/advansys.c                  |    2 
 include/asm-generic/pgtable-nopmd.h      |    5 
 include/asm-generic/pgtable-nopud.h      |    5 
 include/linux/args.h                     |   29 +
 include/linux/kernel.h                   |   27 +
 include/linux/kprint-light.h             |   25 +
 include/linux/kprint.h                   |  201 ++++++++++++
 include/linux/ringbuffer.h               |   34 ++
 include/net/sctp/sctp.h                  |    6 
 include/scsi/scsi_device.h               |   14 
 include/scsi/sd.h                        |   13 
 init/Kconfig                             |    2 
 init/do_mounts_initrd.c                  |    2 
 kernel/Kconfig.kprint                    |  125 +++++++
 kernel/Makefile                          |    2 
 kernel/kprint.c                          |  345 +++++++++++++++++++++
 kernel/printk.c                          |    9 
 lib/Makefile                             |    3 
 lib/ringbuffer.c                         |  155 +++++++++
 lib/vsprintf.c                           |  321 +++++++++++++++++++
 net/tipc/dbg.c                           |    3 
 40 files changed, 1660 insertions(+), 72 deletions(-)
#2 lore raw
Quoted 11 lines · Randy Dunlap
Quoted 8 lines · On Thu, 04 Oct 2007 22:04:07 +0200 Vegard Nossum wrote:

Description: This patch largely implements the kprint API as previously posted to the LKML and described in Documentation/kprint.txt (see patch).

The main purpose of this change is provide a unified logging API to the kernel and at the same time make it easy to add extensions, now and later.

My changes and additions are as follows:

$ diffstat -p1 -w70 kprint.patch

...

Quoted 1 line
 40 files changed, 1660 insertions(+), 72 deletions(-)

I started this thread by posting an idea I had for shrinking the kernel by allowing more code to be configured out. The API change was exactly one new parameter, with a direct 1->1 mapping from the old API to the new one, which was trivial to convert and which the compiler would catch if you missed one.

The result of the discussion is a patch adding 1600 lines to the kernel, without removing anything.

Last I checked, the current prink() worked just fine. Why is this _not_ the dreaded "infrastructure in search of a use"? What exactly can we _not_ do with the current code? What does this allow us to remove and simplify?

I'm confused about what people are trying to accomplish here...

Rob

Signature · 2 lines
"One of my most productive days was throwing away 1000 lines of code."
  - Ken Thompson.
#3 lore raw
Quoted 20 lines · Rob Landley
Quoted 11 lines · Randy Dunlap
Quoted 8 lines · On Thu, 04 Oct 2007 22:04:07 +0200 Vegard Nossum wrote:

Description: This patch largely implements the kprint API as previously posted to the LKML and described in Documentation/kprint.txt (see patch).

The main purpose of this change is provide a unified logging API to the kernel and at the same time make it easy to add extensions, now and later.

My changes and additions are as follows:

$ diffstat -p1 -w70 kprint.patch

...

Quoted 1 line
 40 files changed, 1660 insertions(+), 72 deletions(-)

I started this thread by posting an idea I had for shrinking the kernel by allowing more code to be configured out. The API change was exactly one new parameter, with a direct 1->1 mapping from the old API to the new one, which was trivial to convert and which the compiler would catch if you missed one.

Quoted 9 lines

The result of the discussion is a patch adding 1600 lines to the kernel, without removing anything.

Last I checked, the current prink() worked just fine. Why is this _not_ the dreaded "infrastructure in search of a use"? What exactly can we _not_ do with the current code? What does this allow us to remove and simplify?

I'm confused about what people are trying to accomplish here...

I think we all are trying to give ideas to improve the current logging API.

If something works, it's great; but it doesn't mean that it can't be improved, right?

Signature · 2 lines
Miguel Ojeda
http://maxextreme.googlepages.com/index.htm
#4 lore raw
Quoted 11 lines · Miguel Ojeda
Quoted 6 lines

Last I checked, the current prink() worked just fine. Why is this _not_ the dreaded "infrastructure in search of a use"? What exactly can we _not_ do with the current code? What does this allow us to remove and simplify?

I'm confused about what people are trying to accomplish here...

I think we all are trying to give ideas to improve the current logging API.

If something works, it's great; but it doesn't mean that it can't be improved, right?

I'm all for improving the kernel, but my definition of "improved" does not include every possible change. I balance "smaller and simpler" with "more features". Complexity is a cost, we should get something in return.

Making the same functionality simpler makes it "cheaper" from a development standpoint. Smaller and simpler means less overhead, less to understand, less to go wrong. It's also attractive to me personally, because I am a Bear of Very Little Brain and between the dozen or so projects I try to follow, I have trouble fitting all the details in my head when they're tricky or they change ever time I look at them. (Especially when I get distracted from one of those projects for 3-6 months and come back to find it changed.)

I recognize constantly having to learn new things as part of the cost of living, and making things more complicated happens as you add features. But when somebody reinvents the wheel it's really nice to have clearly spelled out the advantages of the new wheel vs the old one. It's nice for there to _be_ clear advantages, offsetting the increased complexity cost.

In this case, upon asking, the only potential advantage here seems to be "now we can translate dmesg output into Chinese more easily", which is something you could already do in userspace already via regular expressions in a translating dmesg, and which has the primary effect of making the resulting dmesg useless to report to lkml without really improving the amount of sense it makes to nontechnical end users (who really aren't the target of the english dmesg output, either). The "linux developer who can't read english" niche is inherently somewhat problematic, as has been discussed here before.

The cost of this patch is making the kernel bigger, the in-kernel printk api more complicated, and the userspace dmesg noticeably more complex just to implement the same functionality against the new API. Documenting the changes is nice, but doesn't reduce this increase in complexity.

The original idea (selectively compile out printk() instances based on log level to conserve space) is explicitly not addressed by this patch, and in fact this patch might actually make it harder to implement (by complicating the code).

*shrug* That doesn't mean my objections are important to anyone else, just that I don't personally see any reason to be enthusiastic about this patch.

Rob

Signature · 2 lines
"One of my most productive days was throwing away 1000 lines of code."
  - Ken Thompson.
#5 lore raw
Quoted 11 lines · Rob Landley
Quoted 5 lines · Miguel Ojeda

I think we all are trying to give ideas to improve the current logging API.

If something works, it's great; but it doesn't mean that it can't be improved, right?

I'm all for improving the kernel, but my definition of "improved" does not include every possible change. I balance "smaller and simpler" with "more features". Complexity is a cost, we should get something in return.

Quoted 7 lines

Making the same functionality simpler makes it "cheaper" from a development standpoint. Smaller and simpler means less overhead, less to understand, less to go wrong. It's also attractive to me personally, because I am a Bear of Very Little Brain and between the dozen or so projects I try to follow, I have trouble fitting all the details in my head when they're tricky or they change ever time I look at them. (Especially when I get distracted from one of those projects for 3-6 months and come back to find it changed.)

I fully agree. However, I just gave away some ideas that I believe they can make printk() easier and more understandable than it is right now (for example, standardizing kprint_[registered,detected,...] messages is something that I think it can simplify everyday use of messages, both to people who has to code it, review/search the code and people that reads the kernel output).

Quoted 6 lines

I recognize constantly having to learn new things as part of the cost of living, and making things more complicated happens as you add features. But when somebody reinvents the wheel it's really nice to have clearly spelled out the advantages of the new wheel vs the old one. It's nice for there to _be_ clear advantages, offsetting the increased complexity cost.

I got your point, and I agree. However, I also see the possibilities that a change of the logging API can bring: If someday it gets improved, maybe such day should be improved as far as possible. This kind of stuff that affect so many things are not going to change for long periods of time, as you said.

Still, I know some kind of changes can be really complex and maybe are unproductive. I think the point is to get a middle point between new complexity vs. new features.

Quoted 3 lines

In this case, upon asking, the only potential advantage here seems to be "now we can translate dmesg output into Chinese more easily", which is something

Well, other improvements suggested are not just about internationalization.

Quoted 7 lines

you could already do in userspace already via regular expressions in a translating dmesg, and which has the primary effect of making the resulting dmesg useless to report to lkml without really improving the amount of sense it makes to nontechnical end users (who really aren't the target of the english dmesg output, either). The "linux developer who can't read english" niche is inherently somewhat problematic, as has been discussed here before.

I didn't talk about internationalization (in fact, I think it is going to be pretty complex to get it right and, worse, to get it up-to-date in each release without error in translations)

Quoted 5 lines

The cost of this patch is making the kernel bigger, the in-kernel printk api more complicated, and the userspace dmesg noticeably more complex just to implement the same functionality against the new API. Documenting the changes is nice, but doesn't reduce this increase in complexity.

Quoted 7 lines

The original idea (selectively compile out printk() instances based on log level to conserve space) is explicitly not addressed by this patch, and in fact this patch might actually make it harder to implement (by complicating the code).

*shrug* That doesn't mean my objections are important to anyone else, just that I don't personally see any reason to be enthusiastic about this patch.

Take a look to other suggested changes, maybe you like some of them and you will have found a reason to be enthusiastic :)

Quoted 2 lines

Rob

Signature · 2 lines
Miguel Ojeda
http://maxextreme.googlepages.com/index.htm
#6 lore raw
Quoted 40 lines · On Sat, 6 Oct 2007 01:01:10 +0200 "Miguel Ojeda" <[email protected]> wrote:
Quoted 11 lines · Rob Landley
Quoted 5 lines · Miguel Ojeda

I think we all are trying to give ideas to improve the current logging API.

If something works, it's great; but it doesn't mean that it can't be improved, right?

I'm all for improving the kernel, but my definition of "improved" does not include every possible change. I balance "smaller and simpler" with "more features". Complexity is a cost, we should get something in return.

Quoted 7 lines

Making the same functionality simpler makes it "cheaper" from a development standpoint. Smaller and simpler means less overhead, less to understand, less to go wrong. It's also attractive to me personally, because I am a Bear of Very Little Brain and between the dozen or so projects I try to follow, I have trouble fitting all the details in my head when they're tricky or they change ever time I look at them. (Especially when I get distracted from one of those projects for 3-6 months and come back to find it changed.)

I fully agree. However, I just gave away some ideas that I believe they can make printk() easier and more understandable than it is right now (for example, standardizing kprint_[registered,detected,...] messages is something that I think it can simplify everyday use of messages, both to people who has to code it, review/search the code and people that reads the kernel output).

Quoted 6 lines

I recognize constantly having to learn new things as part of the cost of living, and making things more complicated happens as you add features. But when somebody reinvents the wheel it's really nice to have clearly spelled out the advantages of the new wheel vs the old one. It's nice for there to _be_ clear advantages, offsetting the increased complexity cost.

I got your point, and I agree. However, I also see the possibilities that a change of the logging API can bring: If someday it gets improved, maybe such day should be improved as far as possible. This kind of stuff that affect so many things are not going to change for long periods of time, as you said.

Quoted 3 lines

Still, I know some kind of changes can be really complex and maybe are unproductive. I think the point is to get a middle point between new complexity vs. new features.

The beauty of printk is it's current simplicity. And even with that developers get it wrong. The changes seem like added complexity with little real gain.

Plus none of the changes address the issue of getting better information. The kernel is already so noisy that most distributions boot with the quiet flag to shut it up. So less messages is probably better!

Quoted 37 lines
Quoted 3 lines

In this case, upon asking, the only potential advantage here seems to be "now we can translate dmesg output into Chinese more easily", which is something

Well, other improvements suggested are not just about internationalization.

Quoted 7 lines

you could already do in userspace already via regular expressions in a translating dmesg, and which has the primary effect of making the resulting dmesg useless to report to lkml without really improving the amount of sense it makes to nontechnical end users (who really aren't the target of the english dmesg output, either). The "linux developer who can't read english" niche is inherently somewhat problematic, as has been discussed here before.

I didn't talk about internationalization (in fact, I think it is going to be pretty complex to get it right and, worse, to get it up-to-date in each release without error in translations)

Quoted 5 lines

The cost of this patch is making the kernel bigger, the in-kernel printk api more complicated, and the userspace dmesg noticeably more complex just to implement the same functionality against the new API. Documenting the changes is nice, but doesn't reduce this increase in complexity.

Quoted 7 lines

The original idea (selectively compile out printk() instances based on log level to conserve space) is explicitly not addressed by this patch, and in fact this patch might actually make it harder to implement (by complicating the code).

*shrug* That doesn't mean my objections are important to anyone else, just that I don't personally see any reason to be enthusiastic about this patch.

Take a look to other suggested changes, maybe you like some of them and you will have found a reason to be enthusiastic :)

Quoted 2 lines

Rob

Signature · 1 line
Stephen Hemminger <[email protected]>
#7 lore raw
Quoted 48 lines · Stephen Hemminger
Quoted 40 lines · On Sat, 6 Oct 2007 01:01:10 +0200 "Miguel Ojeda" <[email protected]> wrote:
Quoted 11 lines · Rob Landley
Quoted 5 lines · Miguel Ojeda

I think we all are trying to give ideas to improve the current logging API.

If something works, it's great; but it doesn't mean that it can't be improved, right?

I'm all for improving the kernel, but my definition of "improved" does not include every possible change. I balance "smaller and simpler" with "more features". Complexity is a cost, we should get something in return.

Quoted 7 lines

Making the same functionality simpler makes it "cheaper" from a development standpoint. Smaller and simpler means less overhead, less to understand, less to go wrong. It's also attractive to me personally, because I am a Bear of Very Little Brain and between the dozen or so projects I try to follow, I have trouble fitting all the details in my head when they're tricky or they change ever time I look at them. (Especially when I get distracted from one of those projects for 3-6 months and come back to find it changed.)

I fully agree. However, I just gave away some ideas that I believe they can make printk() easier and more understandable than it is right now (for example, standardizing kprint_[registered,detected,...] messages is something that I think it can simplify everyday use of messages, both to people who has to code it, review/search the code and people that reads the kernel output).

Quoted 6 lines

I recognize constantly having to learn new things as part of the cost of living, and making things more complicated happens as you add features. But when somebody reinvents the wheel it's really nice to have clearly spelled out the advantages of the new wheel vs the old one. It's nice for there to _be_ clear advantages, offsetting the increased complexity cost.

I got your point, and I agree. However, I also see the possibilities that a change of the logging API can bring: If someday it gets improved, maybe such day should be improved as far as possible. This kind of stuff that affect so many things are not going to change for long periods of time, as you said.

Quoted 3 lines

Still, I know some kind of changes can be really complex and maybe are unproductive. I think the point is to get a middle point between new complexity vs. new features.

Quoted 7 lines

The beauty of printk is it's current simplicity. And even with that developers get it wrong. The changes seem like added complexity with little real gain.

Plus none of the changes address the issue of getting better information. The kernel is already so noisy that most distributions boot with the quiet flag to shut it up. So less messages is probably better!

I agree. On the one hand, some changes are complex (like "blocks" implementation) and maybe they will not help at all. I'm not agreeing with every change :)

On the other hand, the new tags (more standarized messages and simplified code) and all the information given by the new syslog retrieved from userspace (formatted messages => better information possibly) can do a lot of good (and maybe even more in the future, with a lot more stuff inside the kernel), without creating noise at boot at all. That kind of changes I think they would do more good than bad.

Signature · 2 lines
Miguel Ojeda
http://maxextreme.googlepages.com/index.htm
#8 lore raw
In reply to Miguel Ojeda
Quoted 6 lines · Miguel Ojeda
Quoted 3 lines

*shrug* That doesn't mean my objections are important to anyone else, just that I don't personally see any reason to be enthusiastic about this patch.

Take a look to other suggested changes, maybe you like some of them and you will have found a reason to be enthusiastic :)

Is there any way to serialize the changes? It's hard to review a big lump.

Rob

Signature · 2 lines
"One of my most productive days was throwing away 1000 lines of code."
  - Ken Thompson.
#9 lore raw
Quoted 9 lines · On Sun, 7 Oct 2007 16:56:01 -0500 Rob Landley wrote:
Quoted 6 lines · Miguel Ojeda
Quoted 3 lines

*shrug* That doesn't mean my objections are important to anyone else, just that I don't personally see any reason to be enthusiastic about this patch.

Take a look to other suggested changes, maybe you like some of them and you will have found a reason to be enthusiastic :)

Is there any way to serialize the changes? It's hard to review a big lump.

There are also parts of the patch that could be submitted independently of any message-logging API changes.

---
~Randy

#10 lore raw
In reply to Rob Landley
Quoted 4 lines · Rob Landley

The original idea (selectively compile out printk() instances based on log level to conserve space) is explicitly not addressed by this patch, and in fact this patch might actually make it harder to implement (by complicating the code).

This is wrong. The patch provides log-level-based filtering at compile time, effectively making the kernel smaller.

Quoted 2 lines

*shrug* That doesn't mean my objections are important to anyone else, just that I don't personally see any reason to be enthusiastic about this patch.

I agree; you are right about the other things, Maybe I can try to fit some of these things into printk itself (thanks for the tip, Alan), and we'll see how far we can get.

Thanks.

Vegard

#11 lore raw
Quoted 8 lines · Vegard Nossum
Quoted 4 lines · Rob Landley

The original idea (selectively compile out printk() instances based on log level to conserve space) is explicitly not addressed by this patch, and in fact this patch might actually make it harder to implement (by complicating the code).

This is wrong. The patch provides log-level-based filtering at compile time, effectively making the kernel smaller.

I made it about halfway through the patch and the only compile time filtering I found was:

drivers/md/md.c +0 -0
@@ -62,7 +62,10 @@

 #define MdpMinorShift 6

 #define DEBUG 0
-#define dprintk(x...) ((void)(DEBUG && printk(x))) +#define dprintk(x...)          \
+       if(DEBUG) {             \
+                printk(x);     \
+       }

If you say it does, I'll take your word for it, but there's so much churn in there I didn't find it before my interest ran out...

Rob

Signature · 2 lines
"One of my most productive days was throwing away 1000 lines of code."
  - Ken Thompson.
#12 lore raw
Quoted 25 lines · On Sun, 7 Oct 2007 16:50:49 -0500 Rob Landley <[email protected]> wrote:
Quoted 8 lines · Vegard Nossum
Quoted 4 lines · Rob Landley

The original idea (selectively compile out printk() instances based on log level to conserve space) is explicitly not addressed by this patch, and in fact this patch might actually make it harder to implement (by complicating the code).

This is wrong. The patch provides log-level-based filtering at compile time, effectively making the kernel smaller.

I made it about halfway through the patch and the only compile time filtering I found was:

drivers/md/md.c +0 -0
@@ -62,7 +62,10 @@
  #define MdpMinorShift 6


 #define DEBUG 0

drivers/md/md.c +4 -1
-#define dprintk(x...) ((void)(DEBUG && printk(x)))
+#define dprintk(x...)          \
+       if(DEBUG) {             \
+                printk(x);     \
+       }
Quoted 3 lines

If you say it does, I'll take your word for it, but there's so much churn in there I didn't find it before my interest ran out...

BTW that change might actually break code (dangling else problems). The original way was safer.

Signature · 1 line
Stephen Hemminger <[email protected]>
#13 lore raw
Quoted 20 lines · Stephen Hemminger
Quoted 17 lines · On Sun, 7 Oct 2007 16:50:49 -0500 Rob Landley <[email protected]> wrote:
Quoted 1 line · Vegard Nossum

On 10/5/07, Rob Landley <[email protected]> wrote:

I made it about halfway through the patch and the only compile time filtering I found was:

drivers/md/md.c +4 -1
@@ -62,7 +62,10 @@
 #define MdpMinorShift 6
 
 #define DEBUG 0
-#define dprintk(x...) ((void)(DEBUG && printk(x)))
+#define dprintk(x...)\
+if(DEBUG) {\
+ printk(x);\
+}
 
Quoted 6 lines
Quoted 3 lines

If you say it does, I'll take your word for it, but there's so much churn in there I didn't find it before my interest ran out...

BTW that change might actually break code (dangling else problems). The original way was safer.

Yep, thanks. I think containing it in do {} while(0) should fix, though, no?

Vegard

#14 lore raw
Quoted 28 lines · On Mon, 8 Oct 2007 17:33:53 +0200 "Vegard Nossum" <[email protected]>…
Quoted 20 lines · Stephen Hemminger
Quoted 17 lines · On Sun, 7 Oct 2007 16:50:49 -0500 Rob Landley <[email protected]> wrote:
Quoted 1 line · Vegard Nossum

On 10/5/07, Rob Landley <[email protected]> wrote:

I made it about halfway through the patch and the only compile time filtering I found was:

drivers/md/md.c +4 -1
@@ -62,7 +62,10 @@
 #define MdpMinorShift 6
 
 #define DEBUG 0
-#define dprintk(x...) ((void)(DEBUG && printk(x)))
+#define dprintk(x...)\
+if(DEBUG) {\
+ printk(x);\
+}
 
Quoted 6 lines
Quoted 3 lines

If you say it does, I'll take your word for it, but there's so much churn in there I didn't find it before my interest ran out...

BTW that change might actually break code (dangling else problems). The original way was safer.

Quoted 3 lines

Yep, thanks. I think containing it in do {} while(0) should fix, though, no?

Vegard

The correct fix is to just replace dprintk() with pr_debug()

Signature · 1 line
Stephen Hemminger <[email protected]>
#15 lore raw
In reply to Rob Landley
Quoted 15 lines · Rob Landley
Quoted 11 lines · Randy Dunlap
Quoted 8 lines · On Thu, 04 Oct 2007 22:04:07 +0200 Vegard Nossum wrote:

Description: This patch largely implements the kprint API as previously posted to the LKML and described in Documentation/kprint.txt (see patch).

The main purpose of this change is provide a unified logging API to the kernel and at the same time make it easy to add extensions, now and later.

My changes and additions are as follows:

$ diffstat -p1 -w70 kprint.patch

...

Quoted 1 line
 40 files changed, 1660 insertions(+), 72 deletions(-)
Quoted 7 lines

I started this thread by posting an idea I had for shrinking the kernel by allowing more code to be configured out. The API change was exactly one new parameter, with a direct 1->1 mapping from the old API to the new one, which was trivial to convert and which the compiler would catch if you missed one.

The result of the discussion is a patch adding 1600 lines to the kernel, without removing anything.

Of course. If you look at the diffstat, as kindly posted by Randy, you'll notice that about 500-600 of those lines are documentation, configuration files, and headers.

What's really a concern (and a valid argument) is the overhead introduced for each call to printk(); the defconfig kernel on x86 increases with about 210K. I will try to improve this.

Quoted 3 lines

Last I checked, the current prink() worked just fine. Why is this _not_ the dreaded "infrastructure in search of a use"? What exactly can we _not_ do with the current code? What does this allow us to remove and simplify?

With the current code, localisation is not possible to do in a sane way. My change is a "catch all" in desired features -- not just removing some unwanted printks.

Vegard

#16 lore raw
Quoted 25 lines · Vegard Nossum
Quoted 24 lines · Rob Landley
Quoted 12 lines · Randy Dunlap
Quoted 9 lines · On Thu, 04 Oct 2007 22:04:07 +0200 Vegard Nossum wrote:

Description: This patch largely implements the kprint API as previously posted to the LKML and described in Documentation/kprint.txt (see patch).

The main purpose of this change is provide a unified logging API to the kernel and at the same time make it easy to add extensions, now and later.

My changes and additions are as follows:

$ diffstat -p1 -w70 kprint.patch

...

Quoted 1 line
 40 files changed, 1660 insertions(+), 72 deletions(-)

I started this thread by posting an idea I had for shrinking the kernel by allowing more code to be configured out. The API change was exactly one new parameter, with a direct 1->1 mapping from the old API to the new one, which was trivial to convert and which the compiler would catch if you missed one.

Quoted 6 lines
Quoted 2 lines

The result of the discussion is a patch adding 1600 lines to the kernel, without removing anything.

Of course. If you look at the diffstat, as kindly posted by Randy, you'll notice that about 500-600 of those lines are documentation, configuration files, and headers.

Yay documentation, and I read it, but it's still adding complexity:

Quoted 4 lines

6. Calling syslog (in glibc, klogctl()) with a (type|0x10) will access the new kprint buffer instead of the regular log buffer. The kprint buffer is different in that it doesn't record the actual formatted message, but the format string and the (formatted) arguments. Example:

This adds a new buffer in parallel with the old buffer. The new one is significantly more complex to use from userspace, and has no advantages for the _current_ uses of it, therefore the old one will never _stop_ being used, and thus can probably never be removed.

But it's not bloat. Right.

Quoted 11 lines

What's really a concern (and a valid argument) is the overhead introduced for each call to printk(); the defconfig kernel on x86 increases with about 210K. I will try to improve this.

Quoted 4 lines

Last I checked, the current prink() worked just fine. Why is this _not_ the dreaded "infrastructure in search of a use"? What exactly can we _not_ do with the current code? What does this allow us to remove and simplify?

With the current code, localisation is not possible to do in a sane way.

Run dmesg through a filter in userspace using lots of regular expressions. Your average perl junkie could knock out a basic prototype in 20 minutes.

This also gives you the option of _not_ using the filter to get the raw dmesg output in english, which is the only thing this list can diagnose.

If you think that's going to break when kernel guys change the code each release, explain how your new one _wouldn't_.

Quoted 2 lines

My change is a "catch all" in desired features -- not just removing some unwanted printks.

That's a good thing? It's infrastructure in search of a use, implementing things that might, at some future date, be interesting, and complicating the code to do it in both the kernel and userspace.

I'm missing the "advantage" part. I'm not close to perfect so I could just be failing to see its obvious greatness, but I continue to fail to see it...

Quoted 1 line

Vegard

Rob

Signature · 2 lines
"One of my most productive days was throwing away 1000 lines of code."
  - Ken Thompson.
#17 lore raw
Quoted 5 lines
Quoted 2 lines

With the current code, localisation is not possible to do in a sane way.

Run dmesg through a filter in userspace using lots of regular expressions. Your average perl junkie could knock out a basic prototype in 20 minutes.

He did say "sane".

Good internationalisation requires you know where the messages are and where the substitutions (%foo) are. So the entire operation would in fact require

1. An option to set "translation friendly please"

2. A tiny modification to the snprintfoo code to support putting
some kind of marker before/after arguments and maybe doubling a symbol to avoid vagueness

The submission is overkill compared to what is required for translation tools and syslog.

Alan