Kernel module programming (6): debug of printk-printf

This article contains "Linux Device Drivers", that is, the fourth chapter of LDD3: One of the Reading Notes of Debugging Techniques, but we are not limited to this content. I saw the English version of LDD3 on the Internet: http://www.deansys.com/doc/ldd3/

I have read it. It is best to read it with the original version.

In the debugging of our program, whether it is JAVA, C (kernel module or user application), print is a very important means. In my previous projects, I will have a log file that divides logs into several levels based on project requirements. Through setlogLevel, I can set the levels of debug that can be enabled or disabled, each log line consists of three parts: [time] [log-level] [log Content. You can decide whether to write logs to a file or simply display the logs on terminal. In a JAVA project, logs can be output to the console client, and a TCP link is used between them. If TCP is blocked, the output will be discarded until TCP is restored. In C, we can simply add-DMY_DEBUG_LEVEL to the compilation parameters. In a sense, DEBUG is also a learning.

I have a painful lesson in writing files. Write the original CDR Billing Data Sheet. Each business has three detailed records, two callleg records, and one business record. Our big traffic test, at least 48 hours, usually takes a longer time. The number of services exceeds 10 million. Therefore, a large amount of data needs to be written. There is no problem in the usual test, but in a formal test, the disk is full and cannot be written. Although this can be pushed to the Integration personnel, it is often not considerate to us. If we write files, including log files, for long-running systems, we must consider disk space issues. After this lesson, I wrote a background applet that compresses or deletes the initial file based on the time, capacity, and number of files. It will be executed regularly tomorrow. The performance of the stress test is also shown below, and the partner's test client logs are full of disks. This is a problem that is easily ignored during development, but it may cause serious problems in actual operation.

[Programming ideology 1: Pay attention to disk overflow]

In fact, debug is very important for development. It can not only track our program for diagnosis, but also track our business logic and find performance bottlenecks (gdb is not competent for performance bottlenecks, because the breakpoint makes the system performance difficult ). The same is true in kernel module programming. The program we developed should not be divided into the beta version and the official version. Their source code is the same, but there is no debugging information in the official version. The following describes how to use printk.

Some important macros

Printk and printf are very similar, but they are not the same. The following is an example:

Printk (KERN_DEBUG "wei mark here: % s: % d at % s ()/n ",_ FILE __

,_ LINE __

,_ FUNCTION __

);

Where_ FILE __

Indicates the source code file, which appears in an absolute path,_ LINE __

The number of rows allowed by the printk in the source code file. This can also be used in user programs._ DATE __

And_ TIME __

Is very common. But sometimes we need to use msec. In this case, we have to write it by ourselves. These four macros are often used in debug. In addition_ STDC __

, Usually 1, expressed as standard ansi c. Another common feature is_ FUNCTION __

It indicates that the function is also a good method for locating. These macros can be used in user programs and are very helpful for debugging.

KERN_DEBUG is a string, that is, "<7>", which is the lowest among the eight debug levels defined by the kernel. From 0 to 7: KERN_EMERG, KERN_ALERT, KERN_CRIT, KERN_ERR, KERN_WARING, KERN_NOTICE, KERN_INFO, KERN_DEBUG. Corresponding to <0>, <1>, <2> ....... Because he is a character, there is no comma after him.

In fc10, I checked dmesg and/var/log/messages, and found that the "<7>" represented by KERN_DEBUG is not displayed, but the moblin running KVM is used, this "<7>" is displayed. I did an experiment and directly used "<7>" to replace KERN_DEBUG. For example, in the above example, I wrote "<7> wei... ", in fc10, it is also not displayed <7>, which is related to the OSV integrated system.

Use printk | printf

A good programming habit is to add the DEBUG level to each printk, which makes the program easier to understand. In the scull example, A scull_debug.c file is added to ensure source code consistency and whether the debug information is displayed can be determined by compilation.

# Ifndef WEI_SCULL_DEBUG_H

# Undef PDEBUG

# Ifdef SCULL_DEBUG

# Ifdef _ KERNEL __

# Define PDEBUG (fmt, args...) printk (KERN_DEBUG "scull:" fmt, # args)

# Else

# Define PDEBUG (fmt, args...) printf (fmt, # args)

# Endif

# Else

# Define PDEBUG (fmt, args ...)

# Endif

# Undef PDEBUGG

# Define PDEBUGG (fmt, args ...)

# Endif

In the above example, the PDEBUG macro is defined. If needed, we can also define the actual content of PDEBUGG. If SCULL_DEBUG is defined and the DEBUG mode is enabled, PDEBUG decides whether to use printk or printf based on whether or not to program the kernel. That is to say, this header file can also be used in user programs. The following is the modification to the Makefile. The simple processing is in the gcc line. If you need debug and add the parameter-DSCULL_DEBUG, you can. You do not need to delete this definition. The following is a simple and easy-to-understand method. I will add-DSCULL_DEBUG directly in the settings of EXTRA_CFLAGS, and comment on it to describe the meaning of the parameter, without making a bunch of scripts. The following is an example of LDD3, in which CFLAGS is changed to EXTRA_CFLAGS. Another note is that a space must be added after ifeq; otherwise, an error is reported.

DEBUG = y

Ifeq ($ (DEBUG), y)

DEBFLAGS =-O-g-DSCULL_DEBUG

Else

DEBFLAGS =-O2

Endif

EXTRA_CFLAGS

+ =$ (DEBFLAGS)

OBJ-M: = scull. o

Module-objs: =

PWD: = $ (shell PWD)

Kdir: =/lib/modules/$ (shell uname-R)/build

ALL:

Make-C $ (kdir) M = $ (PWD) Modules

Clean:

Make-C $ (kdir) M = $ (PWD) clean

In fc10, we still hope to see the debug level. On the other hand, we are not familiar with the meaning of 0-7. We only know that the higher the number, the more important the information is. We rewrite scull_debug.c to the following:

# Ifndef wei_scull_debug_h

# Ifdef _ KERNEL __

# Define wei_kern_ermer 0

# Define wei_kern_alert 1

# Define wei_kern_crit 2

# Define wei_kern_err 3

# Define wei_kern_warning 4

# Define wei_kern_notice 5

# Define wei_kern_info 6

# Define wei_kern_debug 7

Static char * log_level [] = {

"Kern_emerg ",

"Kern_alert ",

"Kern_crit ",

"Kern_err ",

"Kern_warning ",

"Kern_notice ",

"Kern_info ",

"Kern_debug"

};

# Endif

# UNDEF pdebug

# Ifdef scull_debug

# Ifdef _ KERNEL __

# Define pdebug (FMT, argS...) printk (kern_debug "scull:" FMT, # ARGs)

# Ifdef wei_debug_level

# Define wdebug (Level, FMT, argS ...)/

If (level <= wei_debug_level) printk ("% S % s scull [% s]:" FMT,_ DATE __

,_ TIME __

, Log_level [level], # ARGs)

# Else

# Define wdebug (Level, FMT, argS ...) printk ("% s scull [% s]:" FMT ,__ time _, log_level [level], # ARGs)

# Endif
# Else

# Define pdebug (FMT, argS...) printf (FMT, # ARGs)

# Define wdebug (Level, FMT, argS ...)

# Endif

# Else

# Define pdebug (FMT, argS ...)

# Endif

# UNDEF pdebugg

# Define pdebugg (FMT, argS ...)

# Endif

We can select the debug level to use a string for the debug level. It may be of little significance for simple programs. We can also set our own level. Rewrite the Makefile as follows:

DEBUG = y

Debuglevel = 6

Ifeq ($ (Debug), Y)

DEBFLAGS =-O-g-DSCULL_DEBUG-DWEI_DEBUG_LEVEL = $ (DEBUGLEVEL)

Else

DEBFLAGS =-O2

Endif

EXTRA_CFLAGS + = $ (DEBFLAGS)

Obj-m: = scull. o

Module-objs: =

PWD: = $ (shell pwd)

KDIR: =/lib/modules/$ (shell uname-r)/build

All:

Make-C $ (KDIR) M = $ (PWD) modules

Clean:

Make-C $ (KDIR) M = $ (PWD) clean

 

In the scull example, we can obtain the following information from dmesg through load and unload:

Sep 9 2009 14:18:14 scull [KERN_NOTICE]: Scull module init enter

Sep 9 2009 14:18:18 scull [KERN_NOTICE]: Scull module exit

Avoid blocking of printk

For some reason, frequent loop call of a printk statement may cause CPU congestion. If the input terminal is slow, congestion may occur, it is impossible for us to read any valid information from this crazy screen, which is basically invisible. Kernel programming provides a protection mechanism. The following is an example of a test:

For (I = 0; I <1000; I ++ ){

If (printk_ratelimit ()){

Printk (KERN_DEBUG "Test for ratelimte I = % d j = % d/n", I, ++ j );

}

}

Printk (KERN_NOTICE "After Test I = % d j = % d/n", I, j );

Printk_ratelimit () determines whether to print the debug information based on the value returned by the printing frequency. The returned value depends on two factors:/proc/sys/kernel/printk_ratelimit and/proc/sys/kernel/printk_ratelimit_burst. The former indicates how many seconds after the value is set to 0 and then returns to 1, that is, the waiting time (seconds) for re-printing. The latter may be related to the length of the cache queue, it indicates the number of printk entries before the value is 0. The default values are 5 and 10, that is, two outputs can be output per second under the control of printk_ratelimit. In the above example, we can see that the output is 10 times.The processing mechanism I imagine is that the system sets a queue length based on the value of printk_ratelimit_burst. If the queue is full, the value of printk_ratelimit () is 0, and new messages are prohibited from joining the queue, wait for the seconds specified by printk_ratelimit

Printk_ratelimit () is set to 1, which allows new messages to be added to the queue. This method was used to process business requests and set the frequency at which requests can be accepted to avoid the emergence of burst. I guess the mechanism here is similar. In any case, this is an effective method.

[Programming philosophy 2: Control Input/Output and control business volume]

Related links:

My articles related to the kernel module

My articles related to programming ideas