Historical

Lets look back on how the printing was handled in a pre-history kernel.

SMP (Symmetric Multi Processing) SoCs became common in the late 1990s. Before that, everything was easy and everyone was happy. No NMIs. No races between multiple cores. Simple locking. No Facebook.

As a response to SMP systems, Linux v2.1.80 introduced a spin_lock to printk to avoid race conditions between multiple cores. The solution we came up with was to serialize all prints to the console. If two CPUs called printk() at the same time, the second core has to wait for the first core to finish.

This does not scale well. In fact, it does not scale at all. What about a modern system with 100+ CPUs that all calls printk at the same time? Depending on the console, the printing may take milliseconds and you will surely end up with an unresponsive system.

Nowdays

Now we are doing things differently. The first core that grabs the console_lock is responsible to print all messages in the __log_buf. If another core is calling printk() in meanwhile, it puts its data into __log_buf , tries to grab the lock which is busy, and then simple returns.

As __log_buf continues getting new data, the unlucky core that grabbed the console_lock may end up doing nothing but printing.

The good thing is that we only locks up a single core instead of all cores. The bad thing is that we locks up a single core.

printk()

printk() is defined in kernel/printk/printk.c and does not look much to the world :

 1    asmlinkage __visible int printk(const char *fmt, ...)
 2    {
 3        va_list args;
 4        int r;
 5
 6        va_start(args, fmt);
 7        r = vprintk_func(fmt, args);
 8        va_end(args);
 9
10        return r;
11    }

It simple calls vprintk_function with its own arguments.

vprintk_func()

vprintk_func() is a function that forward the arguments to different print-functions depending on the current context :

 1    
 2    __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
 3    {
 4        if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
 5            return vprintk_nmi(fmt, args);
 6
 7        if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK)
 8            return vprintk_safe(fmt, args);
 9
10        if (this_cpu_read(printk_context) & PRINTK_NMI_DEFERRED_CONTEXT_MASK)
11            return vprintk_deferred(fmt, args);
12
13        return vprintk_default(fmt, args);
14    }

The different contexts we have to consider are:

vprintk_emit()

vprintk_emit() is responsible to write to __log_buf, (but not the only function, cont_flush() also write to __log_buf) and print out the content to all consoles. :

 1    
 2    asmlinkage int vprintk_emit(int facility, int level,
 3                    const char *dict, size_t dictlen,
 4                    const char *fmt, va_list args)
 5    {
 6
 7        ...
 8
 9        <<<<< Strip kernel syslog prefix >>>>>
10
11        ...
12
13        <<<<< log_output() does the actual printing to __log_buf >>>>>
14        printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
15
16        ...
17
18        if (!in_sched) {
19            /*
20             * Try to acquire and then immediately release the console
21             * semaphore.  The release will print out buffers and wake up
22             * /dev/kmsg and syslog() users.
23             */
24            if (console_trylock())
25                console_unlock();
26        }
27
28        return printed_len;
29    }

The function is quite straight forward. The only thing that looks a little bit strange is :

1    
2        if (console_trylock())
3            console_unlock();

Really? Grab the console_lock and immediately unlock it? The thing is that all magic happens in console_unlock().

console_unlock()

The CPU that is grabbing the console_lock is responsible to print to all registered consoles until all new data in __log_buf is printed. This regardless if other CPUs keeps filling the buffer with new data.

In the worst case, this CPU is doing nothing but printing and will never leave this function. :

 1    void console_unlock(void)
 2    {
 3        ...
 4
 5
 6        <<<<< Endless loop? >>>>>
 7        for (;;) {
 8
 9            <<<<< Go through all new messages >>>>>
10
11            ...
12
13            <<<<< Print to all consoles >>>><
14            call_console_drivers(ext_text, ext_len, text, len);
15
16            ...
17        }
18
19        ...
20
21        <<<<<  Release the exclusive_console once it's used >>>>>
22        console_locked = 0;
23
24        ...
25
26        <<<<< Wake up klogd >>>>>
27        if (wake_klogd)
28            wake_up_klogd();
29    }

The function is looping until all new messages is printed. For each new message, a call to call_console_drivers() is made. The last thing that we do is waking up the klogd kernel thread that will signal to all userspace application that is waiting on klogctl(2).

call_console_drivers()

call_console_drivers() is asking all registered consoles to print out a message. The console_lock must be held when calling this function.

 1    
 2    static void call_console_drivers(const char *ext_text, size_t ext_len,
 3                     const char *text, size_t len)
 4    {
 5        struct console *con;
 6
 7        trace_console_rcuidle(text, len);
 8
 9        if (!console_drivers)
10            return;
11
12        for_each_console(con) {
13            if (exclusive_console && con != exclusive_console)
14                continue;
15            if (!(con->flags & CON_ENABLED))
16                continue;
17            if (!con->write)
18                continue;
19            if (!cpu_online(smp_processor_id()) &&
20                !(con->flags & CON_ANYTIME))
21                continue;
22            if (con->flags & CON_EXTENDED)
23                con->write(con, ext_text, ext_len);
24            else
25                con->write(con, text, len);
26        }
27    }

__log_buf

The kernel log buffer is exported as a global symbol called __log_buf. If you have an systems that deadlocks without any output on the console and you may reboot the system without resetting RAM, then you may print the content of __log_buf from the bootloader.

Determine the physical address of __log_buf:

1    [09:59:31]marcus@little:~/git/linux$ grep __log_buf System.map 
2    c14cfba8 b __log_buf

The 0xc14cfba8 is the virtual address of __log_buf. This kernel is compiled for a 32bit ARM with the CONFIG_VMSPLIT_3G set, so the kernel virtual address space start at 0xc0000000. To get the physical address out of the virtual, subtract the offset (0xc14cfba8 - 0xc0000000) and you will end up with 0x014cfba8. Dump this address from your bootloader and you will see your kernel log.

sizeof(__log_buf)

The size of __log_buf is set at compile-time with CONFIG_LOG_BUF_SHIFT. The value defines the size as a power of 2 and is usually set to 16 (64K).

There is also a CONFIG_PRINTK_SAFE_LOG_BUF_SHIFT that is the per-CPU buffer where messages printed from unsafe context are temporary stored. Examples on unsafe context would be NMI and printk recursions. The messages are copied to the main log buffer in a safe context to avoid a deadlock.

This buffer is rarely used but has to be there to avoid the nasty deadlocks. The CONFIG_PRINTK_SAFE_LOG_BUF_SHIFT was introduced in v4.11 and is also expressed as a power of 2.