Messages in this thread | | | Subject | Re: [PATCH] printk: Add printk_flush() to force buffered text to console | From | Steven Rostedt <> | Date | Mon, 18 Jun 2012 21:28:46 -0400 |
| |
On Mon, 2012-06-18 at 16:03 -0700, Greg Kroah-Hartman wrote:
> > Actually, I think that patch really should go mainline, and give others > > some of the luxury that us -rt folks enjoy. > > That would be good.
Maybe I'll package that up if Ingo has no objections.
> > If other printks were interleaved and it didn't crash, we wouldn't care > > (or even notice). But if it did crash, I'll even argue seeing the > > interleaved printks would provide a hint to why it crashed. > > Ok, so what do you want to do here? Fix up your RFC patch to not have > the printk stamps? Or something like the above rt patch? >
I'm fine with adding a printk_flush() or even as Joe suggested, making a pr_flush(), or printk(KERN_FLUSH "..." that will just do it. Maybe make that default with a switch.
As to get rid of the time stamp issue, that may take a bit, as the code goes through layers where this information needs to be passed down. I ran 'trace-cmd record -p function_graph -g printk' to see how the flow works, mounted an NFS filesystem (to force a printk) and this is what I got:
printk() { vprintk_emit() { _raw_spin_lock(); log_store(); console_trylock() { down_trylock() { _raw_spin_lock_irqsave(); _raw_spin_unlock_irqrestore(); } } console_unlock() { _raw_spin_lock_irqsave(); log_from_idx(); msg_print_text() { print_prefix(); print_prefix(); } log_next(); serial8250_console_write() {
What's missing (as are all lib/ functions are from function tracing) is the first call to vscnprintf() to get the string and all its args together.
Then the '\n' is checked as well as the '<X>' notations. The prefix is set for everything but '<c>' which makes sense, as you don't want to add a prefix to a KERN_CONT line. But this 'prefix' variable just changes the logic, it doesn't really prevent the prefix from appearing as we will see.
Now things are a bit different if there's a newline or not. In this trace, the newline was there, but first lets look at what happens when there's no newline.
It checks this static variable called 'cont_len' which is set if we buffered the last line. cont_task is set to the task it buffered too. If cont_len is set but cont_task does not equal the current task, we call this log_store() thingy. Which is the next thing that would have happened if we did have a newline.
Now if cont_len is zero, it updates the current cont_level and cont_task. Now it copies the printk into the cont_buf, which too is static.
Finally, console_trylock() followed by console_unlock() which is done regardless if there was a newline or not.
The console_unlock() is where the magic happens. Remember that log_store() thingy, that's what is going to be printed. But remember, it only was called if we had a newline, or we had buffered data and the current task is different. But the current printk line is still located in that cont_buf variable which happens to be static for vprintk_emit() and not available elsewhere.
Once data is sent to the log_store() it always prints this prefix. This is why my printk_flush() caused the next (<c>) line to have a timestamp too. Because when that got flushed out, it got a timestamp on it, as all data that goes to the console gets a timestamp. The only reason it doesn't in the current method, is that it buffers it locally in the cont_buf[] array, before it sends it out to the console. When it does send it out to the console, it sends the entire buffer.
I forgot to mention what happens when the line has a newline, and there's content in cont_buf[]. If the cont_task is the same as current, it appends the cont_buf to the new data that is about to be printed, and then sends that out to the log_store() which will get a timestamp at the beginning of the line before the buffered data.
Oh, and one more thing. The vprintk_emit() strips the newline from the text even if it had one. The msg_print_text() called by console_unlock() and a bunch of syslog callers, adds the '\n' back. This is to all text going out. My patch added a msg flag to say "don't do that!" We also need a flag to skip adding the timestamp, but that looks even more complex, as the timestamp is added by print_prefix() also called by msg_print_text() (three callers) and there's no comments to what the frick it's doing or why. We need a way to stop that from happening.
-- Steve
| |