Re: [PATCH] printk: Add printk_flush() to force buffered text to console

[Steven Rostedt <rostedt@goodmis.org>]

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