作者：彭東林
開發板：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!\n"; 如果在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\n”); 其中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('\n'); /* #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\n”);， 在處理時自動加入前綴，使用的等級是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 == '\n') // 當是’\n’時，表示下一條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\n”);），上面也進行了處理，加上了默認的等級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 == '\n') { // 表示本條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。