作者：彭东林
开发板：tiny4412ADK+S700 4GB Flash
主机：Wind7 64位
虚拟机：Vmware+Ubuntu12_04
u-boot：U-Boot 2010.12
Linux内核版本：linux-3.0.31
Android版本：android-4.1.2
源码：kernel/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)
{
int printed_len = 0;
int current_log_level = default_message_loglevel;
/*
在include/linux/printk.h中：
#define default_message_loglevel (console_printk[1])
在kernel/printk.c中：
int console_printk[4] = {
DEFAULT_CONSOLE_LOGLEVEL, // console_loglevel
DEFAULT_MESSAGE_LOGLEVEL, // default_message_loglevel
MINIMUM_CONSOLE_LOGLEVEL, // minimum_console_loglevel
DEFAULT_CONSOLE_LOGLEVEL, // default_console_loglevel
};
#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL
在.config中：
#define CONFIG_DEFAULT_MESSAGE_LOGLEVEL 4
*/
unsigned long flags;
int this_cpu;
char *p;
size_t plen;
char special;
/*
由于没有定义宏CONFIG_BOOT_PRINTK_DELAY，所以boot_delay_msec是空函数
*/
boot_delay_msec();
/*
printk_delay这个函数中判断变量printk_delay_msec的值，它的初始值是0
static inline void printk_delay(void)
{
if (unlikely(printk_delay_msec)) {
int m = printk_delay_msec;
while (m--) {
mdelay(1);
touch_nmi_watchdog();
}
}
}
那么在什么地方设置这个值呢？通过分析代码发现，是通过写文件/proc/sys/kernel/printk_delay实现的，可以执行如echo “44” > /proc/sys/kernel/printk_delay 来改变这个变量的值
在文件kernel/sysctl.c中：
static struct ctl_table kern_table[] = {
……
{
.procname = "printk_delay",
.data = &printk_delay_msec,
.maxlen = sizeof(int),
.mode = 0644,
.proc_handler = proc_dointvec_minmax,
.extra1 = &zero,
.extra2 = &ten_thousand,
},
……
}
当向文件/proc/sys/kernel/printk_delay中写入数据，函数proc_dointvec_minmax会调用，然后将这个数字赋值给printk_delay_msec
static struct ctl_table root_table[] = {
{
.procname = "kernel",
.mode = 0555,
.child = kern_table,
},
……
}
内核在启动时会同一处理root_table，然后再/proc下生成相应的文件，方便内核调试
*/
printk_delay();
preempt_disable(); // 关抢占
/* This stops the holder of console_sem just where we want him */
raw_local_irq_save(flags);
this_cpu = smp_processor_id(); //读取当前cpu核的id号
/*
* Ouch, printk recursed into itself! 处理printk中再次调用printk的情况
*/
if (unlikely(printk_cpu == this_cpu)) {
/*
* If a crash is occurring during printk() on this CPU,
* then try to get the crash message out but make sure
* we can't deadlock. Otherwise just return to avoid the
* recursion and return - but flag the recursion so that
* it can be printed at the next appropriate moment:
*/
if (!oops_in_progress) {
recursion_bug = 1;
goto out_restore_irqs;
}
zap_locks();
}
lockdep_off();
spin_lock(&logbuf_lock);
printk_cpu = this_cpu;
if (recursion_bug) {
recursion_bug = 0;
/*
static const char recursion_bug_msg [] =
KERN_CRIT "BUG: recent printk recursion!
";
如果在printk中继续调用printk，上面这句就会不断出现，可以试试
*/
strcpy(printk_buf, recursion_bug_msg); // 缓存入printk_buf，待下面处理
printed_len = strlen(recursion_bug_msg);
}
/* Emit the output into the temporary buffer
先将要打印的字符串缓存入printk_buf中
*/
printed_len += vscnprintf(printk_buf + printed_len,
sizeof(printk_buf) - printed_len, fmt, args);
/*
如果配置和宏CONFIG_DEBUG_LL的话，
这个以后分析，printascii是一个用汇编实现的函数，在文件arch/arm/kernel/debug.S中
他会直接将传入的printk_buf参数中的内容打印出来
*/
#ifdef CONFIG_DEBUG_LL
printascii(printk_buf);
#endif
p = printk_buf; // 将临时缓冲区的首地址赋给指针p
/*
Read log level and handle special printk prefix
这个函数会解析printk_buf的前三个字符，因为一般我们在驱动中使用printk的时候会加一个前缀如 printk(KERN_DEBUG “hello world
”); 其中KERN_DEBUG宏展开后就是 “<7>”
这个函数的目的就是解析这里的 ”<7>”，会把解析出来的数字7赋值给current_log_level
如果是”<c>”或者”<d>”，这把字符c或者d赋值给special
上面两种情况下，返回值是3，也就是字符串”<x>”的长度，赋值返回0，同时也不给current_log_level和special赋值
*/
plen = log_prefix(p, ¤t_log_level, &special);
if (plen) { // 如果是类似printk(“hello world”);则plen是0，这个if条件不成立
p += plen; // 跳过printk_buf开头的 “<x>”
switch (special) { // 一般不会是 ‘c’ 或者 ‘d’
case 'c': /* Strip <c> KERN_CONT, continue line */
plen = 0;
break;
case 'd': /* Strip <d> KERN_DEFAULT, start new line */
plen = 0;
default:
if (!new_text_line) { // 这个变量初始值是1
emit_log_char('
');
/*
#define CONFIG_LOG_BUF_SHIFT 17 在make menuconfig的时候可以修改
#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
static char __log_buf[__LOG_BUF_LEN] __nosavedata; // 定义了128KB的log缓冲区
static int log_buf_len = __LOG_BUF_LEN; // 128K
static char *log_buf = __log_buf;
#define LOG_BUF_MASK (log_buf_len-1)
#define LOG_BUF(idx) (log_buf[(idx) & LOG_BUF_MASK]) // 获得log_buf中第idx个字符，这个技巧保证了log_buf中的内容可以以环形缓冲区的形式存放，不至于溢出
static void emit_log_char(char c) // 将c表示的字符存入log_buf中，并调整相关索引值
{
LOG_BUF(log_end) = c; // 存入 log_buf[log_end&(128k-1)]
log_end++;
if (log_end - log_start > log_buf_len)
log_start = log_end - log_buf_len;
if (log_end - con_start > log_buf_len)
con_start = log_end - log_buf_len;
if (logged_chars < log_buf_len)
logged_chars++;
}
*/
new_text_line = 1;
}
}
}
/*
* Copy the output into log_buf. If the caller didn't provide
* the appropriate log prefix, we insert them here
*/
for (; *p; p++) {
if (new_text_line) {
/*
这个if语句是根据用户配置在每条内核log前面加上优先级、时间戳以及cpu_id
*/
new_text_line = 0;
/*
从下面这个if判断可以看出，如果使用的是类似printk(“Hello world
”);，
在处理时自动加入前缀，使用的等级是current_log_level的初始值，也就是4
*/
if (plen) {
/* Copy original log prefix */
int i;
for (i = 0; i < plen; i++)
emit_log_char(printk_buf[i]);
printed_len += plen;
} else {
/* Add log prefix */
emit_log_char('<');
emit_log_char(current_log_level + '0');
emit_log_char('>');
printed_len += 3;
}
if (printk_time) { //判断是否在每条log的前面加上时间戳
/* Add the current time stamp */
char tbuf[50], *tp;
unsigned tlen;
unsigned long long t;
unsigned long nanosec_rem;
t = cpu_clock(printk_cpu);
nanosec_rem = do_div(t, 1000000000);
tlen = sprintf(tbuf, "[%5lu.%06lu] ",
(unsigned long) t,
nanosec_rem / 1000);
for (tp = tbuf; tp < tbuf + tlen; tp++)
emit_log_char(*tp);
printed_len += tlen;
}
if (printk_cpu_id) { // 判断是否加入打印这条log的cpu_id
/* Add the cpu id */
char tbuf[10], *tp;
unsigned tlen;
tlen = sprintf(tbuf, "c%u ", printk_cpu);
for (tp = tbuf; tp < tbuf + tlen; tp++)
emit_log_char(*tp);
printed_len += tlen;
}
if (printk_pid) { // 判断是否加入当前进程的pid
/* Add the current process id */
char tbuf[10], *tp;
unsigned tlen;
tlen = sprintf(tbuf, "%6u ", current->pid);
for (tp = tbuf; tp < tbuf + tlen; tp++)
emit_log_char(*tp);
printed_len += tlen;
}
if (!*p)
break;
}
emit_log_char(*p);
if (*p == '
') // 当是’
’时，表示下一条log的开始，上面的if条件又成立了
new_text_line = 1;
}
/*
* Try to acquire and then immediately release the
* console semaphore. The release will do all the
* actual magic (print out buffers, wake up klogd,
* etc).
*
* The console_trylock_for_printk() function
* will release 'logbuf_lock' regardless of whether it
* actually gets the semaphore or not.
*/
if (console_trylock_for_printk(this_cpu))
console_unlock();
lockdep_on();
out_restore_irqs:
raw_local_irq_restore(flags);
preempt_enable(); // 开抢占
return printed_len; // 返回出入的字符串的长度
}
console_unlock()
void console_unlock(void)
{
unsigned long flags;
unsigned _con_start, _log_end;
unsigned wake_klogd = 0;
if (console_suspended) {
up(&console_sem);
return;
}
console_may_schedule = 0;
for ( ; ; ) {
spin_lock_irqsave(&logbuf_lock, flags);
wake_klogd |= log_start - log_end; // 控制判断是否唤醒syslogd的标志位
if (con_start == log_end) // 没有要打印的东西
break; /* Nothing to print */
_con_start = con_start; // 这几句是计算本次log_buf中打印输出索引的范围
_log_end = log_end;
con_start = log_end; /* Flush 就是下一次log_buf输出的起始点*/
spin_unlock(&logbuf_lock);
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(_con_start, _log_end); // 将log_buf中从_con_start到_log_end之间的内容输出
start_critical_timings();
local_irq_restore(flags);
}
console_locked = 0;
/* Release the exclusive_console once it is used */
if (unlikely(exclusive_console))
exclusive_console = NULL;
up(&console_sem);
spin_unlock_irqrestore(&logbuf_lock, flags);
if (wake_klogd)
wake_up_klogd(); // 唤醒sys_logd进程
}
我们先看一下wake_up_klogd干了什么：
void wake_up_klogd(void)
{
if (waitqueue_active(&log_wait))
this_cpu_write(printk_pending, 1);
}
然后，在printk_tick函数中会读取printk_pending，如果是1则唤醒log_wait等待队列：
void printk_tick(void)
{
if (__this_cpu_read(printk_pending)) {
__this_cpu_write(printk_pending, 0);
wake_up_interruptible(&log_wait);
}
}
那么谁会在这个log_wait等待队列上睡眠呢？系统调用sys_syslog
int do_syslog(int type, char __user *buf, int len, bool from_file)
{
unsigned i, j, limit, count;
int do_clear = 0;
char c;
int error;
error = check_syslog_permissions(type, from_file);
if (error)
goto out;
error = security_syslog(type);
if (error)
return error;
switch (type) {
…
case SYSLOG_ACTION_READ: /* Read from log */
error = -EINVAL;
if (!buf || len < 0)
goto out;
error = 0;
if (!len)
goto out;
if (!access_ok(VERIFY_WRITE, buf, len)) {
error = -EFAULT;
goto out;
}
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);
log_start++;
spin_unlock_irq(&logbuf_lock);
error = __put_user(c,buf); // 读取log内容到用户空间
buf++;
i++;
cond_resched();
spin_lock_irq(&logbuf_lock);
}
spin_unlock_irq(&logbuf_lock);
if (!error)
error = i;
break;
……
}
out:
return error;
}
SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
{
return do_syslog(type, buf, len, SYSLOG_FROM_CALL);
}
也就是，当执行 cat /proc/kmsg 时会调用这个函数do_syslog
关于/proc/kmsg的生成，请分析fs/proc/kmsg.c，这个文件会在/proc/下生成kmsg文件，已经跟这个kmsg相关的操作函数。
关于dmesg的实现是通过调用glibc的函数klogctl获取log_buf的，最终也会调用内核中的do_syslog
那么printk_tick在什么时候调用呢？是在每次发生系统嘀嗒时调用
exynos4_mct_comp_isr 这个函数是tiny4412 注册的系统时钟中断处理函数
------ tick_handle_periodic 从这里开始，下面的都是内核通用的
------ tick_periodic
------ update_process_times
------- printk_tick
那系统嘀嗒中断发生时为什么会调用exynos4_mct_comp_isr呢？
start_kernel ----- init/main.c
------ tick_init ------ kernel/time/tick-common.c
/*
void __init tick_init(void)
{
clockevents_register_notifier(&tick_notifier);
}
static struct notifier_block tick_notifier = {
.notifier_call = tick_notify,
};
static int tick_notify(struct notifier_block *nb, unsigned long reason,
void *dev)
{
switch (reason) {
......
case CLOCK_EVT_NOTIFY_ADD:
return tick_check_new_device(dev);
......
}
return NOTIFY_OK;
}
*/
tick_check_new_device
---- tick_setup_device
---- tick_setup_periodic
---- tick_set_periodic_handler
--- dev->event_handler = tick_handle_periodic
系统时钟初始化在kernel启动过程中：
start_kernel
--- time_init （arch/arm/kernel/time.c）
void __init time_init(void)
{
system_timer = machine_desc->timer;
system_timer->init();
}
在mach-tiny4412.c中
MACHINE_START(TINY4412, "TINY4412")
/* Maintainer: FriendlyARM (www.arm9.net) */
.boot_params = S5P_PA_SDRAM + 0x100,
.init_irq = exynos4_init_irq,
.map_io = smdk4x12_map_io,
.init_machine = smdk4x12_machine_init,
.timer = &exynos4_timer,
.reserve = &exynos4_reserve,
MACHINE_END
tiny4412的系统时钟初始化是在arch/arm/mach-exynos/mct.c:
struct sys_timer exynos4_timer = {
.init = exynos4_timer_init,
};
static void __init exynos4_timer_init(void)
{
…
exynos4_timer_resources(); // 获得时钟源的时钟频率 24MHz
exynos4_clocksource_init(); // 注册时钟源
exynos4_clockevent_init(); // 注册中断
}
static void exynos4_clockevent_init(void)
{
clk_cnt_per_tick = clk_rate / HZ;
…
clockevents_register_device(&mct_comp_device);
setup_irq(IRQ_MCT_G0, &mct_comp_event_irq);
}
先看一下函数clockevents_register_device的实现
void clockevents_register_device(struct clock_event_device *dev)
{
…
clockevents_do_notify(CLOCK_EVT_NOTIFY_ADD, dev);
…
}
此时上面的tick_notify会获得执行，最终mct_comp_device的event_handler会被赋值为tick_handle_periodic。
setup_irq会注册向IRQ_MCT_G0中断线注册中断mct_comp_event_irq
#define IRQ_MCT_G0 IRQ_SPI(57)
57是Exynos4412的G0_IRQ的中断号，关于这部分可以阅读Exynos4412芯片手册的;
第9章 Interrupt Controller
第25章 Multi Core Timer (MCT)
此外：
static struct irqaction mct_comp_event_irq = {
.name = "mct_comp_irq",
.flags = IRQF_TIMER | IRQF_IRQPOLL,
.handler = exynos4_mct_comp_isr, // 这个就是中断处理函数
.dev_id = &mct_comp_device,
};
在这个中断处理函数中的dev_id就是上面结构体中的mct_comp_device
static irqreturn_t exynos4_mct_comp_isr(int irq, void *dev_id)
{
struct clock_event_device *evt = dev_id;
exynos4_mct_write(0x1, EXYNOS4_MCT_G_INT_CSTAT);
evt->event_handler(evt);
return IRQ_HANDLED;
}
好了，接着上面的console_unlock分析
call_console_drivers(_con_start, _log_end);
// 将log_buf中从_con_start到_log_end之间的内容输出
static void call_console_drivers(unsigned start, unsigned end)
{
unsigned cur_index, start_print;
static int msg_level = -1;
BUG_ON(((int)(start - end)) > 0);
cur_index = start;
start_print = start;
while (cur_index != end) {
if (msg_level < 0 && ((end - cur_index) > 2)) {
/* strip log prefix */
/*
上面已经分析过log_prefix的作用，请参考上面的分析，此外，对于不规范的printk（如: printk(“Hello world
”);），上面也进行了处理，加上了默认的等级4
这里的目的是：过滤掉字符串”<x>”，不输出到终端上
*/
cur_index += log_prefix(&LOG_BUF(cur_index), &msg_level, NULL);
start_print = cur_index;
}
while (cur_index != end) {
char c = LOG_BUF(cur_index);
// 获得log_buf中索引号为((cur_index) & LOG_BUF_MASK)的元素
cur_index++;
if (c == '
') { // 表示本条log结束
if (msg_level < 0) {
/*
* printk() has already given us loglevel tags in
* the buffer. This code is here in case the
* log buffer has wrapped right round and scribbled
* on those tags
*/
msg_level = default_message_loglevel;
}
// 获得本条log在log_buf中的索引范围，从start_print到cur_index
_call_console_drivers(start_print, cur_index, msg_level);
msg_level = -1;
start_print = cur_index;
break;
}
}
}
_call_console_drivers(start_print, end, msg_level);
}
static void _call_console_drivers(unsigned start,
unsigned end, int msg_log_level)
{
// 这里的console_loglevel是个宏，也就是console_printk[0]，为7
if ((msg_log_level < console_loglevel || ignore_loglevel) &&
console_drivers && start != end) {
// 由于对log_buf当成一个环形缓冲区处理，所以这个需判断是否发生了wrapped
if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
/* wrapped write */
__call_console_drivers(start & LOG_BUF_MASK,
log_buf_len);
__call_console_drivers(0, end & LOG_BUF_MASK);
} else {
__call_console_drivers(start, end);
}
}
}
// 输出log_buf中索引号从start到end范围内容
static void __call_console_drivers(unsigned start, unsigned end)
{
struct console *con;
for_each_console(con) {
if (exclusive_console && con != exclusive_console)
continue;
if ((con->flags & CON_ENABLED) && con->write &&
(cpu_online(smp_processor_id()) ||
(con->flags & CON_ANYTIME)))
con->write(con, &LOG_BUF(start), end - start);
}
}
这里就会调用最终驱动中的硬件接口，通过uart打印到终端上。
其中在include/linux/console.h中：
#define for_each_console(con)
for (con = console_drivers; con != NULL; con = con->next)
其中console_drivers是一个全局变量，会在register_console中设置，所以就要看是谁调用了register_console。