tiny 4412シリアルポート駆動分析二---printkの実現

40224 ワード
print
作者:彭東林
メールアドレス:[email protected]
 
開発ボード:tiny 4412 ADK+S 700 4 GB Flash
ホスト:Wind 7 64ビット
VM:Vmware+Ubuntu 12_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, &current_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); } }

では誰がこのロゴに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この関数はtiny 4412に登録されたシステムクロック割り込み処理関数です
 ------ tick_handle_periodicはここから始まり、次はカーネル共通です
                ------ tick_periodic
                          ------  update_process_times
                                     -------   printk_tick
 
システムがバタバタと中断したときになぜexynos 4が呼び出されたのか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-tiny 4412.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

tiny 4412のシステムクロックの初期化は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_デバイスの実装
void clockevents_register_device(struct clock_event_device *dev) { … clockevents_do_notify(CLOCK_EVT_NOTIFY_ADD, dev); … }

このとき上のtick_notifyは実行され、最終mct_comp_デバイスのevent_handlerはtick_に割り当てられますhandle_periodic.
setup_IRqはIRQ_に登録されますMCT_G 0中断線登録中断mct_comp_event_irq
#define IRQ_MCT_G0               IRQ_SPI(57)
57はExynos 4412のG 0_IRQの割り込み番号は、この部分についてExynos 4412チップマニュアルを読むことができます.
第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_コンソールで設定するので、誰がregisterを呼び出したかによって決まります.console.
いくつかの数の加算を求めます例えば:2+22+222+..
Spring boot構成SqlSessionFactory