한빛출판네트워크

제공: 한빛 네트워크
저자: 한동훈

커널 2.6.20에서 printk() 함수의 구현은 다음과 같습니다.

asmlinkage int printk(const char *fmt, ...)
{
  va_list args;
  int r;
  va_start(args, fmt);
  r = vprintk(fmt, args);
  va_end(args);
  return r;
}

printk()의 구현은 위와 같습니다. 함수 원형 선언에서 ...라고 쓰면 가변인자를 의미합니다. 즉, 인자의 개수가 정해지지 않은 것입니다. 내부적으로 배열을 사용합니다.

가변 인자 처리에 대해서는 인터넷이나 C 언어 참고서를 볼 것을 권하지만, 간단히 설명하자면 가변 인자는 va_list 배열로 전달됩니다. 정확히는 va_start() 함수를 호출해서 가변인자배열 va_list를 초기화합니다. 그 이후에는 va_arg()를 호출해서 전달된 인자를 순서대로 처리합니다. 처음 호출하면 va_list에서 첫번째 인자를 처리하고, 두번째 호출하면 두번째 인자를 처리하는 식입니다. va_end()는 va_list를 이용한 처리가 끝났음을 알리는 역할을 하지만, 실제로는 아무 처리도 하지 않지만, 이 동작 방식은 표준에서 정의된 바가 없고, C 언어 컴파일러마다 다르게 동작할 수 있으므로 va_start()와 함께 va_end()를 사용하는 습관을 갖는 것이 좋습니다. C 언어에서 이들을 사용하려면 stdarg.h 헤더 파일을 선언해야 합니다.

최근의 커널을 보면 printk를 printf로 선언하고 있기 때문에 printk() 대신에 printf()를 쓰는 것도 됩니다.(최근 커널의 경우이며 그렇지 않은 경우에는 모듈을 설치할 때 puts() 함수를 찾을 수 없다는 오류를 내보냅니다. 그러니, 커널에서 뭔가를 출력할 때는 printk() 함수를 사용하는 것이 좋습니다)

그리고, 실제 출력 루틴은 vprintk() 함수입니다.

커널 컴파일 옵션에 보면 Kernel Hacking 메뉴에 Show timing information on printks 항목이 있습니다. 이 옵션은 printk로 출력할 때마다 해당 시간을 자동으로 출력하게 합니다. 그러니까, 실행되는 시간정보가 자동으로 출력되는 형태입니다. printk()로 출력하면 앞에 [00123.222356]과 같이 시간 정보가 출력됩니다.

       t = printk_clock();
        nanosec_rem = do_div(t, 1000000000);
        tlen = sprintf(tbuf,
            "<%c>[%5lu.%06lu] ",
            loglev_char,
            (unsigned long)t,
            nanosec_rem/1000);

시간 처리 출력 부분입니다. printk_clock()은 실제로 sched_clock() 함수를 호출하는 역할만 합니다.

unsigned long long sched_clock(void)
{
        return (unsigned long long)jiffies * (1000000000 / HZ);
}

sched_clock() 함수의 구현은 단순히 이렇게 나누는 것에 불과합니다.

do_div( n, base )는 나눗셈을 해서 나머지를 반환합니다.

printk()에서 재미있는 것은 preempt_disable()을 호출해서 커널 선점을 중단하는 점과 SMP 환경에서 해당 CPU가 몇번째 CPU인지 찾아낸다는 점.

printk_cpu = smp_processor_id();

이런 부분이죠.

그리고, 콘솔에 대한 것도 console_sem이라는 콘솔 세마포어를 사용해서 락을 얻고, 그 다음에 출력을 하고, 그 이후에 세마포어를 해제합니다.

실제 printk()에 따라 포맷을 맞추고, 문자열을 만들어내는 과정은 한 문장으로 끝납니다.

printed_len = vscnprintf(printk_buf, sizeof(printk_buf), fmt, args);

vscnprintf() 함수는 포맷 문자열에 전달된 문자가 %c, %d, %l, %s 같은 형식 문자에 따른 switch … case 문으로 구현되어 있습니다. 형식문자가 다양한 만큼 해당 코드 역시 약간 지저분해 보이지만 이해하기는 쉽습니다.

나머지 처리는 앞에 커널 컴파일 옵션에 따라 시간 정보를 출력하느냐하는 것과 printk_buf에 만들어진 결과를 출력하기 위해 커널 선점을 금지하고, 현재 CPU 번호를 얻어오고, 적절한 콘솔 락과 세마포어를 얻어와서 출력하는 과정들이 더 복잡한 셈입니다.

printk() 함수를 사용할 때 보면 printk( KERN_INFO, "string" ); 이런 형태가 가능합니다. 앞에 쓰인 것은 로그 레벨을 나타내죠.

보통은 printk( "string" );과 같이 사용하는데 이 경우에는 기본 로그 레벨이 사용됩니다. 이에 대한 것은 여깁니다.

 if (log_level_unknown)

이 부분들에서 처리를 합니다.

        if (p[0] == "<" && p[1] >="0" &&
           p[1] <= "7" && p[2] == ">") {
          loglev_char = p[1];
          p += 3;
          printed_len -= 3;
        } else {
          loglev_char = default_message_loglevel
            + "0";
        }

문자열이 "<0>"과 같은 형태니까 p[0], p[1], p[2]와 같이 사용해서 적절한 로그레벨인가를 찾습니다.

일단, 지정하지 않은 경우에는 default_message_loglevel이 사용됩니다. 이는 로그 레벨 4를 나타내며, <4>와 같이 표현됩니다.

기본 레벨은 KERN_WARNING 상수로 지정됩니다. KERN_LEVEL이 상수로 4입니다.

다음은 로그 레벨을 지정한 경우에 실행되는 부분입니다.

     else {
        if (p[0] != "<" || p[1] < "0" ||
           p[1] > "7" || p[2] != ">") {
          emit_log_char("<");
          emit_log_char(default_message_loglevel
            + "0");
          emit_log_char(">");
          printed_len += 3;
        }
      }
      log_level_unknown = 0;
      if (!*p)
        break;

로그 레벨로 지정된 숫자는 0 ~ 7입니다. 자세한 것은 [vi -t KERN_INFO]로 입력해보면 선언된 상수 목록이 모두 보일겁니다.

콘솔 화면에서는 단순히 메시지만 보이지만, /var/log/messages 파일을 살펴보면 출력결과가 "<1> hello" 이렇게 찍히는 것을 볼 수 있죠. 로그 레벨이 찍혀나오는데, 그 부분이 emit_lot_char() 때문입니다.

          emit_log_char(default_message_loglevel
            + "0");

이렇게 중간에 0을 더하는 형태가 보이네요.

문자 "0"을 더하는 것이니까 아스키 코드로 48을 더하는 겁니다. 그래야, 문자로 출력했을 때 제대로 0이라는 값이 찍힐겁니다. 숫자 4를 문자로 찍어버리면 아스키 코드표에서 4번째 것이 찍히겠죠. 그러니까, 저렇게 살짝 더해줘서 아스키 코드표에 있는 문자 0, 1, 2, 3, 4...가 찍히게 하는 겁니다.

emit_log_char()가 출력하는 것은 %d가 아니라 %c라고 생각하면 되겠죠.

그리고, 로그 레벨을 찾았으므로 log_level_unknown을 0으로 설정합니다.

문자열을 전부 출력하면 *p는 NULL이 되므로 break 문을 통해 종료하게 됩니다. 루프의 시작 조건이 다음과 같기 때문입니다.

  for (p = printk_buf; *p; p++) {
    if (log_level_unknown) {
     }....
    else {
       emit_log_char(*p);
    }

한 문자씩 처리하게 되어 있습니다.

루프 전체 안에 <0>과 같은 로그 레벨 판별이 들어가 있는데 일단 판별이 끝나고 나면 항상 else문이 실행되는 구조로 되어 있습니다. 그러니, 꼭 비효율적이다라고 할 것 까진 아니죠.

마음 같아서는 로그 레벨 판별하는 것을 별도로 빼고 싶긴 합니다. 왜냐면 로그 레벨 판별이 끝난 후에도 항상 if 문을 검사한 다음에 else로 넘어가야하는데, 이런 판별 구조를 모두 제거해보는 거죠.

이런 것을 구현해서 패치를 제공할 수도 있을 겁니다. "얼마나 성능 향상이 있겠어? printk()가 커널 전체에서 얼마나 자주 쓰인다고 그런 일을 해?" 라고 생각할 수도 있지만요.

이상의 코드는 커널 2.6.20에서 가져온 것입니다.

커널 2.4는 printk()가 조금 다르게 되어 있습니다. SMP 환경 지원에 맞게 구현된 것 같지도 않고, 프로세서별 자료 구조도 전혀 없죠.

전역 변수로 선언된 phandle stdout;이 있고,

write( stdout, ~~~) 이런식으로 직접적으로 써버립니다.

2.4는 커널 선점이 없죠. 개인적으로는 커널 2.6대를 좋아합니다. 소스도 정리되어 있고, 깨끗한 부분들이 많습니다.

어쨌거나, printk()를 약간 개선해서 패치를 만들어서 http://lkml.org에 올려보세요. 노력을 들인만큼 커널 해커로 잘 알려진 분들이 코드를 검토하고, 의견을 줄겁니다.

전 세계 최고의 해커들과 대화할 수 있는 기회죠.