FS4412 Embedded system based porting (8) Linux kernel debug PRINTK

The following is mainly excerpted from the Linux security system analysis and programming

1. Basic Principles

(1) Set CONSOLE=TTYSAC0 or console=tty1 in Uboot
Here is the set control terminal, TYSAC0 represents the serial port, Tty1 represents the LCD
(2) The kernel is printed with PRINTK

The kernel will be based on command line parameters to find the corresponding hardware operation function, and the information through the corresponding hardware terminal print out!

2. Log level of PRINTK and console
The function printk is used in a similar way to printf for kernel-printed messages. PRINTK messages are categorized according to the log level (loglevel).
Similar in Android, there is the use of the log function to print debugging information.
The log level is defined by a macro, and the log-level macro expands to a string that, when compiled, is stitched together by the preprocessor and the message text into a single string, so there can be no comma between the log level macro and the format string in the PRINTK function.


Here are two examples of PRINTK, one for printing debugging information and the other for printing critical condition information.

PRINTK (kern_debug "Here I am:%s:%i/n", _ _file_ _, _ _line_ _);p rintk (kern_crit "I ' m trashed; Giving up on%p/n ", PTR);

The log levels for PRINTK are defined as follows (in linux2.6 and 3.14/include/linux/kernel.h):

#defineKERN_EMERG "<0>"/* emergency message, before the system crashes, indicates that the system is not available */#defineKERN_ALERT "<1>"/* Report a message that the action must be taken immediately */# Definekern_crit "<2>"/* critical condition, usually involving severe hardware or software operation failure */#defineKERN_ERR "<3>"/* error condition, driver common Kern_err to report hardware errors */# Definekern_warning "<4>"/* warning condition, warning for possible problems */#defineKERN_NOTICE "<5>"/* normal but important conditions for reminders. Commonly used for security-related messages */#defineKERN_INFO <6> */* Prompt information, such as when the driver starts, print hardware information */#defineKERN_DEBUG "<7>"/* Debug-level message */extern int console_printk[]; #define CONSOLE_LOGLEVEL (console_printk[0]) #define DEFAULT_MESSAGE_LOGLEVEL (console_printk[1 ]) #define MINIMUM_CONSOLE_LOGLEVEL (console_printk[2]) #define DEFAULT_CONSOLE_LOGLEVEL (Console_printk[3])

The log level range is 0~7, and the PRINTK statement that does not specify a log level is Default_ Message_loglevel by default, and its definition is listed as follows (in Linux2.6/kernel/printk.c, in linux3.14/ In kernel/printk/printk.c):

/* Do not define log level PRINTK use the following default level */#define DEFAULT_MESSAGE_LOGLEVEL 4/* kern_warning WARNING condition */

The kernel can print messages to the current console, specifying the console as a character-mode terminal or printer, and so on. By default, the console is the current virtual terminal.
To better control the different levels of information displayed on the console, the kernel sets the console's log level console_loglevel. The purpose of the PRINTK log level is to print a certain level of messages, similar to which the console displays only a certain level of messages.
Messages can be displayed when the log level is less than console_loglevel. The corresponding log level for the console is defined as follows:

/* Displays a message that is more severe than this level */#define MINIMUM_CONSOLE_LOGLEVEL 1/* The minimum log level that can be used */#define DEFAULT_CONSOLE_LOGLEVEL 7/* is more than kern_debug Important messages are printed */int console_printk[4] = {default_console_loglevel,/* console log level, messages with precedence above this value will be displayed *//* the default message log level in the console. PRINTK the priority is not defined, print the message above the priority level */default_message_loglevel,/* the minimum console log level, the minimum value (highest priority) that can be set for the console log level */minimum_console_ loglevel,default_console_loglevel,/* default Console log level */};

If the system runs KLOGD and SYSLOGD, the kernel messages are appended to/var/log/messages regardless of the console_loglevel value. If KLOGD is not running, the message is not delivered to the user space and can only be viewed/proc/kmsg.


The initial value of the variable console_loglevel is default_console_loglevel and can be modified by Sys_syslog system calls. You can modify this variable by specifying the-C switch option when calling Klogd. If you want to modify its current value, you must first kill KLOGD, and then add the-C option to restart it.
The log level of the console can be read and modified by reading and writing to the/PROC/SYS/KERNEL/PRINTK file. Here's how to view this file:

#cat/proc/sys/kernel/printk7   4  1   7

The 4 data shown above correspond to the console log level, the default message log level, the lowest console log level, and the default console log level.

Use the following command to set the current log level:

# echo "4 4 1 7" >/PROC/SYS/KERNEL/PRINTK

here is a question to say, in some of the development boards provided by the kernel source code PRINTK default print level is unmodified, such as the core of the Development Board of the Infineon, in the actual use of some drivers will output some debugging information, in the actual use of this information will affect the normal user use, For example, the Infineon Development Board connected to the network cable after the serial terminal will be timed output the following content:

Eth0:link down Eth0:link up, 100Mbps, Full-duplex, LPA 0x4de1

The above information is not a mistake, just print debugging information, the network is normal connection, but this will interfere with the serial input, so when compiling the kernel, modify the debug level in the PRINTK.C as follows to solve the problem:

int console_printk[4] = {default_message_loglevel,/* console log level, messages with precedence above this value will be displayed *//* the default message log level in the console, PRINTK does not define a priority level. Print this priority above the message */default_message_loglevel,/* minimum console log level, the minimum value that the console log level can be set (highest priority) */minimum_console_loglevel,default_ console_loglevel,/* default Console log level */};

3. PRINTK Printing message mechanism


In the kernel, the function PRINTK prints the message to the ring buffer __log_buf and transmits the message to the console for display. The console driver displays log messages based on the log level of the console.
The application manages the ring buffer __log_buf through system call Sys_syslog, which can read data, clear buffers, set log levels, open/close consoles, and so on.
When the system calls Sys_syslog to read data from the ring buffer __log_buf, if the buffer does not have data, the system calls Sys_syslog the process is joined to wait for the queue log_wait. When PRINTK prints the data to the buffer, it wakes the system call Sys_syslog the process from which the data is read from the buffer. The wait queue log_wait is defined as follows:
Declare_wait_queue_head (log_wait);//Waiting for queue log_wait

The ring buffer __log_buf is defined as a global variable before it is used, with a buffer length of 1 << config_log_ Buf_shift. The variable config_log_buf_shift is defined by the configuration file at kernel compile time, and for the i386 platform, its value is defined as follows (in Linux2.6/arch/i386/defconfig):

Config_log_buf_shift=18

When the kernel compiles, the compiler generates the following macro definitions based on the configuration file settings:
#define Config_log_buf_shift 18

The ring buffer __log_buf is defined as follows (in Linux2.6/kernel/printk.c, in linux3.14/kernel/printk/printk.c):

#define __log_buf_len (1 << config_log_buf_shift)//define the length of the ring buffer, i386 platform is static char __log_buf[__log_buf_len]; PRINTK ring buffer static char *log_buf = __log_buf;static int log_buf_len = __log_buf_len;/* Mutex logbuf_lock protection Log_buf, Log_ Start, Log_end, Con_start and Logged_chars */static define_spinlock (logbuf_lock);

The LOG_BUF is defined by a macro, and the buffer __log_buf has the operation behavior of the ring buffer. The macro definition Log_buf gets the character of the buffer specified position ordinal, the position ordinal exceeds the buffer length, through the logic and operation with the length mask log_buf_mask, the position ordinal loops back to the position in the ring buffer.

The definition of the macro definition Log_buf and the position ordinal mask Log_buf_mask is listed below:
#define LOG_BUF_MASK (log_buf_len-1)
#define LOG_BUF (IDX) (log_buf[(IDX) & Log_buf_mask])

To indicate the __LOG_BUF character read position of the ring buffer, the following positional variables are defined:

Static unsigned long log_start;/* system calls the next character read by Syslog */
Static unsigned long con_start;/* to the next character in the console */
Static unsigned long log_end;/* the most recent uppercase character ordinal plus 1 */
static unsigned long logged_chars; /* The number of characters produced since the last read+clear operation */

Kernel calls from anywhere can call functions PRINTK print debugging, security, prompting, and error messages. The function PRINTK attempts to get the console semaphore (Console_sem), and if so, outputs the information to the ring buffer __log_buf, and then the function Release_console_sem () sends the message in the ring buffer to the console before releasing the semaphore. The console driver is called to display the printed information. If the semaphore is not received, only the information is output to the ring buffer and returned.

The function PRINTK is listed below (in Linux2.6/kernel/printk.c, in linux3.14/kernel/printk/printk.c):

asmlinkage int PRINTK (const char *FMT, ...)    {va_list args;    int R;    Va_start (args, FMT);    R = VPRINTK (FMT, args);    Va_end (args); return r;}    asmlinkage int VPRINTK (const char *fmt, va_list args) {unsigned long flags;    int Printed_len;    Char *p;    static Char printk_buf[1024];    static int log_level_unknown = 1;　Preempt_disable ();    Turn off kernel preemption if (unlikely (oops_in_progress) && printk_cpu = = smp_processor_id ())/* If this CPU crashes while running in PRINTK,    Be sure not to deadlock, 10 seconds 1 times to initialize the lock Logbuf_lock and Console_sem, leave time for the console to print the full oops information */zap_locks ();  Local_irq_save (flags);    Store local Interrupt ID lockdep_off ();    Spin_lock (&logbuf_lock);　    PRINTK_CPU = smp_processor_id ();    /* Send output information to temporary buffer printk_buf */Printed_len = vscnprintf (printk_buf, sizeof (PRINTK_BUF), FMT, args);            /* Copy the PRINTK_BUF data to the loop buffer if the caller does not provide the appropriate log level, insert the default value */for (p = printk_buf; *p; p++) {if (Log_level_unknown) { /* Log_level_unknown signals the start of a new line */if (printk_Time) {int loglev_char;                Char tbuf[50], *TP;                unsigned tlen;                unsigned long long t;                unsigned long nanosec_rem; /* Force output log level before time output */if (p[0] = = ' < ' && p[1] >= ' 0 ' && p[1] <                    = ' 7 ' && p[2] = = ' > ') {Loglev_char = p[1];//Get log level character p + = 3;                Printed_len-= 3;                } else {Loglev_char = Default_message_loglevel + ' 0 ';                } t = Printk_clock ();//returns the current clock, in ns Nanosec_rem = Do_div (t, 1000000000); Tlen = sprintf (Tbuf, "<%c>[%5lu.%0                               6lu] ", Loglev_char, (unsigned long) T, nanosec_rem/1000);//write the formatted log level and time for (TP = TBUF; TP < TBUF +Tlen　 tp++) Emit_log_char (*TP);            Output log level and time character to the loop buffer Printed_len + = Tlen;                        } else {if (p[0]! = ' < ' | | p[1] < ' 0 ' | | P[1] > ' 7 ' | |                    P[2]! = ' > ') {emit_log_char (' < ');　 Emit_log_char (Default_message_loglevel + ' 0 ');                    Output character to loop buffer Emit_log_char (' > ');                Printed_len + = 3;            }} log_level_unknown = 0;        if (!*p) break;    } Emit_log_char (*p);//output other PRINTK_BUF data to the loop buffer if (*p = = '/n ') Log_level_unknown = 1; if (!down_trylock (&console_sem)) {/* has a console driver, lowers Spinlock and lets Release_console_sem () print characters */Console_loc        ked = 1;        PRINTK_CPU = Uint_max;        Spin_unlock (&logbuf_lock); /* If the CPU is ready, the console will output characters. The function Cpu_online detects if the CPU is online, and the function have_callable_console () detects if a registered console can be startedUse */if (Cpu_online (smp_processor_id ()) | | | have_callable_console ()) {console_may_schedule = 0;        Release_console_sem ();            } else {/* release lock avoids flushing buffer */console_locked = 0;        Up (&console_sem);        } lockdep_on (); Local_irq_restore (flags);        Restore local Interrupt ID} else {/* If other processes have this driver, this thread reduces spinlock, allowing the semaphore holder to run and invoke the console driver output character */printk_cpu = Uint_max;        Spin_unlock (&logbuf_lock);        Lockdep_on (); Local_irq_restore (flags);  Restore local Interrupt Identity} preempt_enable (); Open preemption mechanism return printed_len;}

The function Release_console_sem () unlocks the console system, releasing the amount of semaphores held by the console system and the driver caller. When a semaphore is held, the PRINTK indicates that the data is already stored in the buffer. The function Release_console_sem () sends this data to the console display before releasing the semaphore. If the background process klogd the data in the waiting ring buffer, it wakes up the KLOGD process.

The function Release_console_sem is listed below (in Linux2.6/kernel/printk.c, in linux3.14/kernel/printk/printk.c):

void Release_console_sem (void) {unsigned long flags;        unsigned long _con_start, _log_end;                unsigned long wake_klogd = 0; for (;;)                {Spin_lock_irqsave (&logbuf_lock, flags);                Wake_klogd |= Log_start-log_end;                if (Con_start = = log_end) break;/* no data to print */_con_start = Con_start;                _log_end = Log_end;                Con_start = log_end;/* Flush */Spin_unlock_irqrestore (&logbuf_lock, flags);            Call the console driver write function to the console call_console_drivers (_con_start, _log_end);        } console_locked = 0;        Console_may_schedule = 0;        Up (&console_sem);        Spin_unlock_irqrestore (&logbuf_lock, flags); if (wake_klogd &&!oops_in_progress && waitqueue_active (&log_wait)) Wake_up_interruptib Le (&log_wait);//Wake up the process on the waiting queue}

The function _call_console_drivers displays the data from start to end-1 in the buffer to the console. Before outputting data to the console, it checks the log level of the message. Only messages that have a log level smaller than the console log level console_loglevel can be presented to the console driver.
The function _call_console_drivers is listed as follows:

static void _call_console_drivers (unsigned long start,                                                                    unsigned long end, int msg_log_level) {        // The log level is less than the console log level message to output to the console        if ((Msg_log_level < Console_loglevel | | ignore_loglevel) &&                        Console_ Drivers && start = end) {                if ((Start & Log_buf_mask) > (end & Log_buf_mask)) {/                        * Call Console driver write function *                        /__call_console_drivers (Start & Log_buf_mask,  log_buf_len);                        __call_console_drivers (0, End & Log_buf_mask);                    } else {                        __call_console_drivers (start, end);}}}    

The function __call_console_drivers calls the console driver's write function to display the message. It is listed as follows:

static void __call_console_drivers (unsigned long start, unsigned long end) {        struct console *con;                for (con = console_drivers; con; con = con->next) {                if (Con->flags & con_enabled) && Con->write &&                                (Cpu_online (smp_processor_id ()) | |                                  (Con->flags & Con_anytime)))                        Con->write (Con, &log_buf (start), End-start); Call the driver's write function            }    }

4. Sys_syslog system Call

The system calls Sys_syslog to perform the corresponding operation according to the command of the parameter type. The commands defined by the parameter type are listed below:

0--Close the log, not currently implemented.
1--Open the log, not currently implemented.
2-Reads the log message from the ring buffer.
3-Reads all messages that remain in the ring buffer.
4-Reads and clears all messages that remain in the ring buffer.
5--Clears the ring buffer.
6--Turn off PRINTK to the console for printing.
7--Turn on PRINTK to the console for printing.
8--Sets the log level of messages that are printed to the console.
9--Returns the number of characters not read in the log buffer.
10--Returns the size of the log buffer.

The Sys_syslog function is listed below (in Linux2.6/kernel/printk.c, in linux3.14/kernel/printk/printk.c):

Asmlinkage long sys_syslog (int type, char __user * buf, int len) {return Do_syslog (type, buf, Len);        }int do_syslog (int type, char __user *buf, int len) {unsigned long I, j, limit, count;        int do_clear = 0;        char c;                int error = 0;  Error = Security_syslog (type);                Check if the permission to call this function if (error) return error;            Switch (type) {case 0:/* closed log */break;            Case 1:/* Open log */break;                Case 2:/* Read log information */error =-einval;                if (!buf | | Len < 0) goto out;                Error = 0;                if (!len) goto out;                        if (!ACCESS_OK (Verify_write, buf, Len)) {//Verify that there is a write permission error =-efault;                    Goto out;                           }//When Log_start-log_end is 0 o'clock, it indicates that the ring buffer is not readable and puts the current process into the waiting queue log_wait     Error = Wait_event_interruptible (log_wait, (log_start-log_end));                if (error) goto out;                i = 0;                SPIN_LOCK_IRQ (&logbuf_lock); while (!error && (log_start! = log_end) && i < len) {c = log_buf (Log_start);//                        Get the read position from the ring buffer Log_start log_start++;                        SPIN_UNLOCK_IRQ (&logbuf_lock);　Error = __put_user (C,BUF);                        The character of C address is passed to the buf of user space buf++;                        i++;  Cond_resched ();                    Conditional scheduling, allowing other processes to have run time Spin_lock_irq (&logbuf_lock);                } SPIN_UNLOCK_IRQ (&logbuf_lock);                if (!error) error = i;            Break                Case 4:/* read/clear last kernel message */do_clear = 1; /* FALL THRU */Case 3:/* read last kernel message */error =-einval;                if (!buf | | Len < 0) goto out;                Error = 0;                if (!len)//Read length is 0 goto out;                        if (!ACCESS_OK (Verify_write, buf, Len)) {//verify Write access error =-efault;                    Goto out;                } count = Len;                if (Count > Log_buf_len) count = Log_buf_len;                SPIN_LOCK_IRQ (&logbuf_lock);                if (Count > Logged_chars)//Logged_chars is the number of log characters generated since the last read/purge count = Logged_chars;                if (do_clear) logged_chars = 0;　                Limit = Log_end;                /* __put_user () can sleep, when __put_user sleep, PRINTK () may overwrite messages being copied to the user space, so these messages are copied in the opposite direction, overwriting the data in the BUF overlay to the beginning of the BUF */                        for (i = 0; I < count &&!error; i++) {//Read count characters j = limit-1-i; if (j+ Log_buf_len < log_end) break; c = Log_buf (j);                        The reading position of J Spin_unlock_irq (&logbuf_lock) is obtained from the ring buffer.                         The C position character is passed to the buf of the user space, and if an error occurs, the wrong C position will be given error error = __put_user (C,&buf[count-1-i]);                        Cond_resched ();                    SPIN_LOCK_IRQ (&logbuf_lock);                                } SPIN_UNLOCK_IRQ (&logbuf_lock);                if (error) break;                Error = i;                        if (i! = count) {//represents __put_user no copy completed int offset = Count-error; /* buffer overflow during copy, correct user space buffer */for (i = 0; i < error; i++) {if (__get_                                                User (C,&buf[i+offset]) | |       __put_user (C,&buf[i])) {//overwrite the overwritten data to the starting position of the BUF                                                             Error =-efault;                                    Break                            } cond_resched ();            }} break;                Case 5:/* Clear the ring buffer */logged_chars = 0;            Break                Case 6:/* closes the output message to the console */console_loglevel = Minimum_console_loglevel;            Break                Case 7:/* turns on output message to console */console_loglevel = Default_console_loglevel;            Break                Case 8:/* Set the log level to print to the console */error =-einval;                if (Len < 1 | | len > 8) goto out;                if (Len < minimum_console_loglevel) len = minimum_console_loglevel;                Console_loglevel = Len;                Error = 0;            Break Case 9:/* Gets the size of the buffer that the log message occupies */error =Log_end-log_start;            Break                Case 10:/* Returns the size of the ring buffer */error = Log_buf_len;            Break                Default:error =-einval;            Break    } Out:return error; }

FS4412 Embedded system based porting (8) Linux kernel debug PRINTK