Issue
I am making a Linux kernel module on Ubuntu 4.14.12.
My understanding of printk() is that it is guaranteed to output to console immediately before the next line of code is run, rather than having its output placed on a buffer that is eventually flushed at some point. Is this correct?
I was getting a crash that occurred several hundred lines after multiple printk calls whose output did not appear in dmesg using the -wH command or in dmesg sent through tee to a file which I read after rebooting.
Is there lag between the time a printk is sent to console and it shows up in dmesg that would allow my system to freeze up before I saw the output? Or is there something else occurring?
dmesg shows the printks in question after fixing the problematic line of code. The console log level was set higher than the console log level of the printks in question.
Solution
There are many layers between your module calls printk(...) and the output showing up on the console.
My understanding of printk() is that it is guaranteed to output to console immediately before the next line of code is run, rather than having its output placed on a buffer that is eventually flushed at some point. Is this correct?
No, this is not correct. There is no "console" in printk() implementation and there shouldn't be any. There's always a buffer, many layers of buffers. The line 1705 in printk.c answers your question. The printk_emit() function uses a statically allocated buffer static char textbuf[LOG_LINE_MAX]; and calls vscnprintf(textbuf, sizeof(textbuf), ...) on it to parse arguments. So it uses a buffer. I don't think it is possible to write a printf function without using an internal buffer, at least it's harder. And the __log_buf variable is a statically allocated buffer, an array of characters, and it is the kernel log buffer.
Is there lag between the time a printk is sent to console and it shows up in dmesg that would allow my system to freeze up before I saw the output?
Yes? There's always a lag. I don't know how to define a "lag" (one milisecond? A second? One nanosecond?) but the assembly instructions behind printk function has to execute, then all the layers up until they are placed in __log_buf static variable. Then dmesg which awaits on read() syscall is woken up I guess somewhere inside console_unlock. After the wakeup dmesg will finally call devkmsg_read() function which will return the buffer. Then dmesg() will call write() syscall on stdout after it has received the data. Then write() kernel syscall will try to write something onto your screen - so the data has to go all the way through console drivers and display drivers and graphics drivers. There's always a lag. But it should be minimal.
dmesg shows the printks in question after fixing the problematic line of code
Which just says that dmesg didn't get the output from kernel log. There is probably something else occurring. The simplest is dmesg process does not get cpu time, is blocked on reading syslog, your module executes inside with irq disabled, and so on.
Answered By - KamilCuk Answer Checked By - David Goodson (WPSolving Volunteer)