printk: Add printk_flush() to force buffered text to console

Fengguang Wu had a config that caused the system to lockup. It reported:

[    6.086395] type=2000 audit(1339501575.085:1): initialized
[    6.116356] Kprobe smoke test started
[    6.125915] Kprobe smoke test passed successfully
[    6.127478] rcu-torture:--- Start of test: nreaders=2 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0

+fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0

and then froze. So naturally, the suspected bug was with rcu-torture. Fengguang did a git bisect and discovered that the crash came with a function trace update. He also noticed that if he reverted that update, the system got farther and showed:

[    1.611901] Testing tracer function: PASSED

His time was wasted by the fact that the function tracing self test first prints:

"Testing tracer function: "

then runs the test, and if it succeeds, it prints "PASSED", giving us the nice output you see above.

But with the new printk() changes, text without a newline gets buffered and does not print out to the console at the location of the printk. This caused the "Testing tracer function: " not to print out and because the test caused the kernel to lock up, we are clueless to the fact that the problem was with the function tracer test and not the rcu_torture test. As it made sense that the rcu_torture test could lock up the system, many kernel developer hours were wasted chasing the wrong wild goose.

If the "Testing tracer function: " had printed out in the first place, we would have caught the correct wild goose and saved precious kernel developer's time.

Thus a need for the following utility. That is to add a 'printk_flush()' that acts like a fflush() in userspace to flush out the buffers used by the printing facility so we don't have unexpected hunts for nature roaming fowl.

I hooked onto the 'facility' infrastructure and used '0x1ffc' (the max number) as a way to communicate printk() commands to the msg_print_text() which is performed at a later time (console_unlock()).

I tested this out, (adding pr_flush() after my printk) and now the lockup shows:

[    9.018231] Kprobe smoke test passed successfully
[    9.023084] rcu-torture:--- Start of test: nreaders=4 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_hold
off=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0
[    9.066065] Testing tracer function:

To prevent the flush to cause the next printk to have a timestamp that would produce the following:

[    6.834073] Testing tracer function: [    7.136194] PASSED

I made the KERN_CONT ("<c>") use the facility as well to pass info to not print the timestamp. This fixes the abve issue to print:

[    1.291025] Testing tracer function: PASSED

---
 include/linux/printk.h |    8 ++++
 kernel/printk.c        |  104 ++++++++++++++++++++++++++++++++++++++++++-----
 2 files changed, 101 insertions(+), 11 deletions(-)

index 1bec2f7..b3317bf3 100644
@@ -111,6 +111,8 @@ asmlinkage int printk_emit(int facility, int level,
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 
+void printk_flush(void);
+
 /*
  * Special printk facility for scheduler use only, _DO_NOT_USE_ !
  */

@@ -158,6 +160,10 @@ static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies,
 	return false;
 }
 
+static inline void printk_flush(void)
+{
+}
+
 static inline void log_buf_kexec_setup(void)
 {
 }

@@ -190,6 +196,8 @@ extern void dump_stack(void) __cold;
 	printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)
+#define pr_flush() \
+	printk_flush()
 
 /* pr_devel() should produce zero code unless DEBUG is defined */
 #ifdef DEBUG

1.7.3.4

Maybe also add the actual usage sites, to demonstrate how it's going to be used?

Thanks,

Ingo

Here's the places that I added (and tested) the pr_flush().

I even added 'set_current_task(TASK_UNINTERRUPTIBLE); schedule_timeout(5*HZ);' to see if it does flush, and it worked fine.

-- Steve

index 49249c2..f7f2cd0 100644
@@ -825,6 +825,7 @@ int register_tracer(struct tracer *type)
 
 		/* the test is responsible for initializing and enabling */
 		pr_info("Testing tracer %s: ", type->name);
+		pr_flush();
 		ret = type->selftest(type, tr);
 		/* the test is responsible for resetting too */
 		current_trace = saved_tracer;

index 29111da..84b674e 100644
@@ -1606,6 +1606,7 @@ static __init void event_trace_self_tests(void)
 #endif
 
 		pr_info("Testing event %s: ", call->name);
+		pr_flush();
 
 		/*
 		 * If an event is already enabled, someone is using

@@ -1635,6 +1636,7 @@ static __init void event_trace_self_tests(void)
 			continue;
 
 		pr_info("Testing event system %s: ", system->name);
+		pr_flush();
 
 		ret = __ftrace_set_clr_event(NULL, system->name, NULL, 1);
 		if (WARN_ON_ONCE(ret)) {

@@ -1657,6 +1659,7 @@ static __init void event_trace_self_tests(void)
 
 	pr_info("Running tests on all trace events:\n");
 	pr_info("Testing all events: ");
+	pr_flush();
 
 	ret = __ftrace_set_clr_event(NULL, NULL, NULL, 1);
 	if (WARN_ON_ONCE(ret)) {

index 288541f..9638639 100644
@@ -161,6 +161,7 @@ static void print_counts(void)
 	       trace_selftest_test_probe3_cnt,
 	       trace_selftest_test_global_cnt,
 	       trace_selftest_test_dyn_cnt);
+	pr_flush();
 }
 
 static void reset_counts(void)

@@ -184,6 +185,7 @@ static int trace_selftest_ops(int cnt)
 
 	printk(KERN_CONT "PASSED\n");
 	pr_info("Testing dynamic ftrace ops #%d: ", cnt);
+	pr_flush();
 
 	ftrace_enabled = 1;
 	reset_counts();

@@ -315,6 +317,7 @@ int trace_selftest_startup_dynamic_tracing(struct tracer *trace,
 	/* The ftrace test PASSED */
 	printk(KERN_CONT "PASSED\n");
 	pr_info("Testing dynamic ftrace: ");
+	pr_flush();
 
 	/* enable tracing, and record the filter function */
 	ftrace_enabled = 1;

[]

It'd have been nicer if you'd have cc'd me.

What I submitted is far simpler and it allows a knob to control the printk buffering on a global basis.

Did you try it? It seems to work here, but I don't have your other patches to rcu-torture with inserted printk_flush patches to verify it. Can I have a copy of those please.

I didn't mean to be rude. I had pulled in my original patch which kept the Cc list, and did a git --amend after making my changes and testing. I just did a cut and paste to put back the Cc list.

But it did not handle the \n nor the timestamp prefix.

No, because it did not do what I needed.

I just posted the places that I add it. There may be more places coming too.

-- Steve

uh, how about we fix that? The old behaviour was good, the new behaviour is noxious.

Please idenfity these "new printk() changes". Was the new noxiousness an unavoidable effect of them?

See commit 7ff9554bb578 ("printk: convert byte-buffer to variable-length record buffer") and related commits.

But that said, there may be a way that I can make it still always flush and not add a new API. We can flush on partial writes, and keep track of the current task (as it already does). If a new task comes in, we can then force a newline before printing the content of the old task (if there wasn't a newline printed before).

This is basically what it does now, except that it buffers the data. If a new task were to do a print in between the two partial writes, it flushes what was buffered and adds a newline before printing the new text.

I think I may be able to implement the same behavior, except that it wont buffer. It would just keep track of the state of the last write.

-- Steve

If a driver does

	printk("testing the frobnozzle ...");
	do_test();
	printk(" OK\n");

and do_test() hangs up, we really really want the user to know that there was a frobnozzle testing problem. Please tell me this isn't broken.

OK, then I wont tell you :-) But this is exactly what happened to me. There was a config that caused the function tracer self test to triple fault the machine. The test does exactly what you just described:

	printk("Testing trace %s: ", tracer->name);
	ret = run_tests(tracer);
	if (ret == 0)
		printk("PASSED!\n");
	else
		printk("FAILED!\n");

But because of this new buffering, that didn't print. And unfortunately, the previous printk was the start of the rcu torture test. Thus when Fengguang saw that the last thing printed before his machine crashed was the rcu torture tests starting, he obviously (but incorrectly) blamed it on the rcu torture test.

Yes, I think this is broken by design. But I have an idea for a fix. I'll work on it on Monday, and it wont require adding a pr_flush() like I did in this patch set.

-- Steve

Absolutely.

pr_flush() really seems to be a workaround.

Fundamentally:

e2ae715d66bf kmsg - kmsg_dump() use iterator to receive log buffer content c313af145b9b printk() - isolate KERN_CONT users from ordinary complete lines 3ce9a7c0ac28 printk() - restore prefix/timestamp printing for multi-newline strings 649e6ee33f73 printk() - restore timestamp printing at console output 5c5d5ca51abd printk() - do not merge continuation lines of different threads 7f3a781d6fd8 printk - fix compilation for CONFIG_PRINTK=n
5fc3249068c1 kmsg: use do_div() to divide 64bit integer
e11fea92e13f kmsg: export printk records to the /dev/kmsg interface 7ff9554bb578 printk: convert byte-buffer to variable-length record buffer

Should we revert them or can they be fixed sanely? Kay seems to be busy with other things so I guess a revert is the best we can do. Greg, Kay?

Thanks,

Ingo

I think the new behavior an overall improvement.
It helps avoid multiple thread interleaving.

I suggested a fix to enable a printk buffered/non-buffered mechanism with an optional printk_flush/pr_flush.

https://lkml.org/lkml/2012/6/21/305

Ugh, so you suggest a global toggle to turn buffering on/off?

That approach really misses thole whole *point* of printk() and debug logging in particular. In most cases when users are triggering and reporting problems they don't go around toggling various rarely used switches to see whether they make a difference. They and kernel developers just take printk output at face value and trust it.

Even if people are aware of this global toggle there are frequent cases where a hang is probabilistic and occurs only very rarely. If a once a year bug triggers then it's obviously useful to have good debug output on the screen or in the serial log and not wait another year with the debug option turned on
...

If I cannot trust printk output anymore and would have to toggle global switches to make it work then printk() has lost value for debugging kernel problems and that would be sad.

So NAK on your patch, really. We should either fix this regression in behavior, or, as a second best alternative we should at least give a deterministic way to flush the printk output, which works all the time.

Thanks,

Ingo

<shrug>

Rather than adding a bunch of printk_flush() calls around the possibly many sites per file that need them, I'd rather see a code block surrounded by buffer(false)/buffer(true).

I'd actually rather see the existing partial line uses like:

	printk("doing test_func: ");
	printk("%s\n", test_func(foo) ? "successful", "failed");

and

	printk("step 1")
	bar();
	printk(" - step 2");
	baz();
	printk("completed\n");

changed to whole lines rather than adding a bunch of printk_flush() sites or the printk_buffering(on|off) blocks.

Anyway, I suggested it shouldn't be merged awhile ago.

https://lkml.org/lkml/2012/5/22/439

Making systemic printk changes is a slow business.

I just don't have a better idea than Joe or Steven.

The conversion from the unreliable byte-buffer to records changes the behavior a little in some areas. We are atomic at the line level now and not at an sometimes unpredictable byte stream position which can just be moved forward by adding another few bytes.

The usual continuation line user should all be buffered to make things generally more reliable and less racy. And we really had these problems in the past, and substantially improved the common use-cases now.

But yes, it seems to come into our way with the current output format of the kernel self-tests, and we need to do something about it. But I don't think it should be going back to the much-too-simple and unreliable byte-stream buffer.

We need make some sort of a compromise for the self-tests here, I guess. I think the trade of using one of these options for the self-tests to cope with the new model is justified:
- flush explicitly when it is needed, by a global flag or with a message prefix
- printing a second full line that says: test foo OK, instead of appending the OK to the former line
- printing one full line, and suppress the later OK entirely. The OK might not be needed at all; we will find out that the machine has not crashed at that point and a message in case of an error could be sufficient in most cases.

Reverting the changes now would remove:
- proper device identifiers attached to a message, which allows tools for the first time to know the contexts of the kernel messages
- 100% message integrity of structured messages, and single line prints, and if only one continuation line user prints at a time. We never mix continuation users with full line users, like the old buffer did.
- very reliable continuation line prints, because of the buffering. The only race that can still happen is several cont users racing against each other, which is not too likely
- 100% granularity at line level during userspace buffer access, crash dumping; we never copy around half or overwritten lines, like the old buffer
- the ring buffer prunes only entire messages not just the half of a line like the old byte buffer
- sequence numbers allow us to track the state of the read and write position in the buffer, so we never copy in-the-meantime already overwritten messages around
- sequence numbers which allow userspace to reconnect to the old reading position and process only new messages, and find if messages got overwritten
- support for multiple concurrent readers with live update of the kernel log stream

This seems like a trade of a rather cosmetic output-format issue for kernel self-tests, against general reliability, integrity and usefulness of the rest of the kernel message users.

The record buffer is a huge step forward for the system logging, and it allows us for the first time to make the kernel log useful to consumers other than humans, and is key part of providing important information to the system management.

An explicit flush for the self-test like users is unfortunate, and inconvenient, and surely not nice, but I think it's still the better overall deal.

Thanks,
Kay

That looks neat and feasible. We not only get less output, but also eliminate the problem of flushing:

        [   16.309109] Testing tracer irqsoff: PASSED
        [   17.184240] Testing tracer wakeup: PASSED
        [   18.060218] Testing tracer wakeup_rt: PASSED
        [   18.729222] Testing tracer function_graph: PASSED
        ...thousands more lines
=>
        [   16.309109] Testing tracer irqsoff
        [   17.184240] Testing tracer wakeup
        [   18.060218] Testing tracer wakeup_rt
        [   18.729222] Testing tracer function_graph
        ...thousands more lines

However these two special lines will have to be broken up into more lines:

        [   14.947553] Testing dynamic ftrace ops #1: (1 0 1 1 0) (1 1 2 1 0) (2 1 3 1 26) (2 2 4 1 43) PASSED
        [   15.740993] Testing dynamic ftrace ops #2: (1 0 1 26 0) (1 1 2 43 0) (2 1 3 1 15) (2 2 4 18 32) PASSED

Thanks,
Fengguang

On Sat, 2012-06-23 at 13:47 +0200, Kay Sievers wrote:
[]

This is probably the easiest actual fix.

I think the added timing information useful.

I think this is not particularly true nor really useful at present and the [v]printk_emit parts should be removed until a the benefit of such a capability more proven.

I'm still concerned someone is going to say that the because you say these things, someone else is going to declare that the content of the [v]printk_emit bits is effectively an ABI (inviolate and immutable) like the seq_ functions. I think that'd make changing any of the logging much more difficult and should be avoided.

It's hard to say that it's not too likely. I think it depends on cpu count. More cpus, more likely.

Still, it's decidedly better than it was.

Good features list and it was well implemented too.

I think the uses of the direct emit model should simply be updated to full lines as you suggested. There are not too many files that need touching.

We track all 'interesting' devices in userspace. So you can ask the system management about a mountpoint or a network interface and it will show all messages that got emitted during that bootup from the underlying devices in that context. With it's udev integration we can also include all the userspace data about the devices and walk up the parent devices and include the parent device information into the output.

For example, you ask for the state of a mountpoint and the system will return you all messages that got emitted from the underlying block devices/disks, then you can broaden the match and include all messages from the storage host controller where the disks are connected, and so on.

Similarly you can efficiently retrieve the logged messages for a network interface, including the parent device, which is usually a PCI card.

That's just how stuff should work today, and the consumer side of it is almost ready to ship, it's just the reliable device identifier in the kernel log that is missing today, and which we wait for, to be generally available.

The idea is similar how you can ask today for "give me all log messages of a certain service (note, not a PID):
https://plus.google.com/108087225644395745666/posts/iuFEgBZT3co

The whole point of attaching the context, where a message was generated from, in a sane format, is to replace the former unparsable and unrecognizable prefixes like:
cdc_acm 2-1.4:1.1: ...
iwlwifi 0000:03:00.0: ...
usb usb2: ...

which now are:
SUBSYSTEM=usb
DEVICE=+usb:2-1.4:1.1

SUBSYSTEM=pci
DEVICE=+pci:0000:03:00.0

SUBSYSTEM=usb
DEVICE=c189:1

been intended to be possible, but which have just been insufficiently implemented for dev_printk().

Nothing should really change to what we do already today, dev_printk() was supposed to be recognizable, it just wasn't good enough, it wasn't intentionally insufficiently implemented.

We do not give the messages texts any more meaning than they already carry, we can just properly *filter* for them. The importance or not of the actual text stays pretty much the same. People today already run magic regexes on the kernel log to guess what's happened in there, and the attached context to allow reliable filtering and identification does not change it.

What we did in the old logging was to throw away all of the context the kernel has at logging time, log the pure text with a pretty much unrecognizable prefix, and later start guessing games to restore the context again. That's really a pretty amateurish way of doing software. Tools in "the stuff mostly works, or otherwise humans can probably make sense of it" category might be fine or even unavoidable in some areas of software development, but it is surely not how the basic building blocks of an operating system should work today. :)

Kay

Then pick the fix you see as the best solution, post it and push the fix to Linus, don't just sit there passive-aggressively leaving a regression you introduced unresolved ...

I think Steve's fix would be OK as a workaround, if no-one can think of anything better.

The thing is, this bug, despite being reported early on, has been left unresolved for weeks and it's -rc4 time now. Time is running out and frankly, I've been watching this thread, and the only reason you appear to be taking this bug somewhat seriously now is because Andrew and me complained. That is sad.

Kernel policy is that kernel bugs introduced during the merge window are fixed by those who introduced them, or the changes get reverted. The kernel project uses a very user-friendly process to resolve regressions and in the worst case you as a developer have to suffer your changes reverted. Obviously timely fixes are preferred over invasive reverts.

It is not *Steve's* job to fix this bug. That he actually posted a fix is nice from him, it makes your life easier (and you can still write some other fix) but *you* should be driving the resolution here, not Steve, me or Andrew.

Below is a (very crude and totally untested) roll-up revert of all the buffering changes to printk - it's obviously not what I want to see happen, but it's obviously *possible*.

Thanks,

Ingo

----------------->
Subject: printk: Revert the buffered-printk() changes for now
From: Ingo Molnar <[email protected]>
Date: Mon Jun 25 10:50:44 CEST 2012

They are not yet cooked and fixes have not arrived in time. We can re-try them in v3.6.

---
 drivers/base/core.c    |   51 -
 drivers/char/mem.c     |   42 +
 include/linux/printk.h |   12 
 kernel/printk.c        | 1599 +++++++++++++------------------------------------
 4 files changed, 484 insertions(+), 1220 deletions(-)

Index: linux/drivers/base/core.c
===================================================================
@@ -1844,60 +1844,15 @@ void device_shutdown(void)
  */
 
 #ifdef CONFIG_PRINTK
+
 int __dev_printk(const char *level, const struct device *dev,
 		 struct va_format *vaf)
 {
-	char dict[128];
-	size_t dictlen = 0;
-	const char *subsys;
-
 	if (!dev)
 		return printk("%s(NULL device *): %pV", level, vaf);
 
-	if (dev->class)
-		subsys = dev->class->name;
-	else if (dev->bus)
-		subsys = dev->bus->name;
-	else
-		goto skip;
-
-	dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
-			    "SUBSYSTEM=%s", subsys);
-
-	/*
-	 * Add device identifier DEVICE=:
-	 *   b12:8         block dev_t
-	 *   c127:3        char dev_t
-	 *   n8            netdev ifindex
-	 *   +sound:card0  subsystem:devname
-	 */
-	if (MAJOR(dev->devt)) {
-		char c;
-
-		if (strcmp(subsys, "block") == 0)
-			c = 'b';
-		else
-			c = 'c';
-		dictlen++;
-		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
-				   "DEVICE=%c%u:%u",
-				   c, MAJOR(dev->devt), MINOR(dev->devt));
-	} else if (strcmp(subsys, "net") == 0) {
-		struct net_device *net = to_net_dev(dev);
-
-		dictlen++;
-		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
-				    "DEVICE=n%u", net->ifindex);
-	} else {
-		dictlen++;
-		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
-				    "DEVICE=+%s:%s", subsys, dev_name(dev));
-	}
-skip:
-	return printk_emit(0, level[1] - '0',
-			   dictlen ? dict : NULL, dictlen,
-			   "%s %s: %pV",
-			   dev_driver_string(dev), dev_name(dev), vaf);
+	return printk("%s%s %s: %pV",
+		      level, dev_driver_string(dev), dev_name(dev), vaf);
 }
 EXPORT_SYMBOL(__dev_printk);
 

Index: linux/include/linux/printk.h
===================================================================
@@ -95,19 +95,9 @@ extern int printk_needs_cpu(int cpu);
 extern void printk_tick(void);
 
 #ifdef CONFIG_PRINTK
-asmlinkage __printf(5, 0)
-int vprintk_emit(int facility, int level,
-		 const char *dict, size_t dictlen,
-		 const char *fmt, va_list args);
-
 asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);
 
-asmlinkage __printf(5, 6) __cold
-asmlinkage int printk_emit(int facility, int level,
-			   const char *dict, size_t dictlen,
-			   const char *fmt, ...);
-
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 

@@ -300,8 +290,6 @@ extern void dump_stack(void) __cold;
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
-extern const struct file_operations kmsg_fops;
-
 enum {
 	DUMP_PREFIX_NONE,
 	DUMP_PREFIX_ADDRESS,

Yeah, sometimes we can't have everything at the same time, and we fixed serious reliability and integrity bugs for the cost of changing the behaviour of: debug-printk + continuation line + crash the box. If the box does not crash, the output does not change at all from before.

Steven said he would try something else on Monday, that's why I'm waiting. I'm not happy with any of the current optimize-continuation-lines-for-kernel-crashes patches, so I wanted to see what he has in mind.

That's true. this change is a trade, and the kernel self-tests print-continuation-line-and-let-the-kernel-crash is currently affected by the hugely improved integrity and reliability of all the "normal" users.

Let's see what other idea Steven has, he wrote "But I have an idea for a fix. I'll work on it on Monday, and it wont require adding a pr_flush() like I did in this patch set." before pointing fingers here please.

If we find a way to solve that cleanly, I'm all for it. But honestly, just letting these very special-case users print fully terminated lines instead of continuation lines seems like an option to me too. We really should not optimize for cosmetics (full lines work reliably, they are not buffered) of self-tests, for the price of the reliability and integrity of all other users.

The self-test users would need to be changed anyway to use "flush", why don't we just print a full line, omit the "PASSED" in case all went well, and only print in case of an error? I really do not see the need for continuation lines for the crash-sensitive self-tests; people will find out (without PASSED on the same line), that we passed the test when the box is still alive.

Kay

But if the box crashes, then we get lies about where it crashed. That's an important part.

I just posted it. You may not like it either, but it removes the needed printk_flush(), and doesn't touch any of your 'facility' work. Besides adding its own 0x1ffc tag.

I'm hoping that my last patch can satisfy both users.

It's out, please continue to point ;-)

The thing is, you made a fundamental change to the way printk() has worked from day one. This will give lots of developers a "surprise", that will last for a long time.

Well, it was a way my scripts would check if the test passed or not.

-- Steve

Sigh, which part of the "no regressions" policy did you not understand?

Even if we ignored regressions (which we don't), you'd *STILL* be wrong: using printk to debug crashes (and to develop code in general) is one of its earliest and I'd say most important role.

And when do we need printk() output? Most of the time only when there's a problem with the system - such as a crash.

System logging is an arguably secondary role, and it should not degrade printk()s primary role.

Your flippant attitude towards printk quality is really sad.

Thanks,

Ingo

I would argue that printk() should not play the role of normal system logging. It's main role should be for boot up and crashes. If devices need to log information to userspace, it should really use some other means. What was /sys made for anyway?

-- Steve

Specifically not for logging. See the very old discussions of this a long time ago (back in the 2.5 days), if you are curious.

printk() is the best thing we have for logging as everyone uses it and the information in it is exactly what userspace wants to know about. Because of that, why wouldn't we use it?

Anyway, your "never buffer printk data" patch looks like the right solution here, I'm guessing you are going to respin it based on the feedback so far, right?

thanks,

greg k-h

I agree with Greg's point there: the reality is that we have over 50,000 printk() sites in the kernel, which is a heck of a good source of system logging information, which we are not going to change over to some other facility, even if we had some marginal reasons to do it.

Just consider the life time of printk() call sites: in most cases it gets added as a debugging printout, as a: "Hey, I just finished reading Linux Device Drivers, 3rd Edition, and this best ever Linux driver is now ALIVE!!" tag of success.

Then it gets extended with a few more printouts of unexpected
behavior: "So, if you got here the hardware must be buggy or you must be doing something stupid, as the driver code sure as heck is perfect".

Most of the printk()s get removed during productization, but some actually make sense and remain (and some don't make sense but just never trigger).

Very few people add printk()s as "inform the system logging daemon about an event". The prevailing mindset is that perfect code does not need any logging, so what is left are over 50,000 call sites of bragging and debugging code, occasionally massaged to be somewhat user friendly.

System logging and tracing in particular can hook off this mechanism, but we probably aren't going to change the social role of printk()s overnight (or ever).

Thanks,

Ingo

Bragging. Silly. A _very_ small percent of printks are "look at me" messages so I think that's a ridiculously poor argument.

Most of the printks are announcement and error
logging notifications.

As I said, 'bragging and debugging code'.

Thanks,

Ingo