The story behind printf 2편

*본 글은 https://www.programering.com/a/MjMycDMwATQ.html의 포스팅을 번역 한 뒤 직접 실험하여 부가설명을 제가 붙였습니다. 이상한 부분은 지적 부탁드리겠습니다.

printf함수 호출 과정 추적하기

우리는 위의 과정들을 통해 printf(“Hello World\n”)가 puts 함수로 변환됐음을 알 수 있습니다. 또 우린 puts가 libc.a 에 포함되어 있음을 알 수 있었습니다. 그리고 elf 파일인 ioputs.o에  puts와 _IO_puts 가 저장됨을 알 수 있었습니다. 그럼 printf 의 call trace를 할 수 있을까요? 다시말해 printf 함수는 순서대로 어떻게 작동할까요? 마지막으로 리눅스에선 커널의 int 0x80번지(커널모드를 진입하기 위한 주소로써 예전 리눅스 방식.)를 이용하여 soft인터럽트 시스템 콜을 호출할까요?

만일 우리가 터미널로 문자열 정보를 출력하려 한다면 우린 대게 시스템콜인 write()를 이용합니다. 그런다음 printf가 Hello World를 출력할 것입니다. 이를 확인하기 위해 GDB를 이용하여 호출 과정을 추적해봅시다. 만일 디버깅에 심볼 테이블을 이용하기 위해 컴파일 과정의 소스파일을 이용하려 한다면 -g 션을 이용해야 합니다.

$/usr/lib/gcc/i686-linux-gnu/4.7/cc1 -fpreprocessed -quiet -g main.i -o main.s

우선 GDB를 이용하여 실행파일을 디버깅합니다.

$gdb ./main

(gdb)break main

(gdb)run

(gdb)stepi

우린 Hello World를 보기위해 stepi 명령어를통해 메인함수에 중단점을 걸어야합니다.

(nexti명령어는 수행후 다음 줄로 넘어가는 반면 stepi는 수행줄의 함수등의 스택으로 넘어 갑니다.

하지만 stepi를 이용하여도  Hello World를 출력하고 넘어가 버립니다. 이러한 이유로 우리는 printf가 아닌 puts를 호출하여 확인해야합니다.

(gdb)

0xb7fff419 in __kernel_vsyscall ()

(gdb)

Hello World!

0xb7fff424 in __kernel_vsyscall ()

(gdb)

0xb7fff425 in __kernel_vsyscall ()

디버깅 과정에서 드디어 Hello World를 발견하였습니다. 그 위치는 보는바와 같이 주소 0xb7fff424로써 실행코드에서 출력되고 있습니다. 이를 분명히 하기 위해 0xb7fff424 주소에 중단점을 새로 걸고 진행합니다. 그러면 코드는 __kernel_vsyscall 함수에서 중지되고 disassemble 명령어를 통해 어셈블리 코드를 확인합니다.

(gdb)disassemble

Dump of assembler code for function __kernel_vsyscall:

 0xb7fff414 <+0>: push  %ecx

 0xb7fff415 <+1>: push  %edx

 0xb7fff416 <+2>: push  %ebp

 0xb7fff417 <+3>: mov   %esp,%ebp

=> 0xb7fff419 <+5>: sysenter

 0xb7fff41b <+7>: nop

 0xb7fff41c <+8>: nop

 0xb7fff41d <+9>: nop

 0xb7fff41e <+10>: nop

 0xb7fff41f <+11>: nop

 0xb7fff420 <+12>: nop

 0xb7fff421 <+13>: nop

 0xb7fff422 <+14>: int   $0x80

 0xb7fff424 <+16>: pop   %ebp

 0xb7fff425 <+17>: pop   %edx

 0xb7fff426 <+18>: pop   %ecx

 0xb7fff427 <+19>: ret  

End of assembler dump.

이 과정에서 우린 놀라운 점을 발견할 수 있습니다. PC 포인터가 sysenter에 직접 위치한 점을 말입니다. 이는 시스템콜 진입점인데 왜 int 0x80명령어가 아닌지 궁금하다면 리누즈 토발즈의 Article Intel P6 vs P7 system call performance 관한 메일링 리스트 중  Linux 2.6 support for new CPU fast system calls" 기고문에서 이유를 확인할 수 있습니다.

시스템 콜 위치는 printf 함수를 호출하는 과정의 맨 마지막에 위치하며 backtrace 명령어를 통해 현재까지의 stack frame을 볼 수 있습니다.

(gdb)backtrace

#0 0xb7fff419 in __kernel_vsyscall ()

#1 0x08058784 in __fxstat64 ()

#2 0x0806fad2 in _IO_file_stat ()

#3 0x080abcd4 in _IO_file_doallocate ()

#4 0x0804a890 in _IO_doallocbuf ()

#5 0x08070b58 in _IO_new_file_overflow ()

#6 0x080705b0 in _IO_new_file_xsputn ()

#7 0x080499a5 in puts ()

결과적으로 시스템콜은 __fxstat64를 호출하게 되었습니다.

*  __fxstat64 : https://refspecs.linuxfoundation.org/LSB_1.3.0/gLSB/gLSB/baselib-xstat64-1.html

printf 함수 소스 읽기

다음으로 printf 함수 소스를 읽어야합니다.Hello World가 출력되는걸 추적하여 출력됨을 확인하긴 하였으나 아직 소스코드를 직접 본것은 아닙니다. 어셈블리를 통해 읽으려는건 좋은 방법이 아닙니다. 제일 좋은 방법은 소스코드 그 자체를 확인하는것 입니다. 우린 웹사이트들을 통하여 소스를 직접 확인 할 수 있습니다.

* linux github : https://github.com/torvalds/linux/blob/master/arch/x86/boot/printf.c

1. puts 함수의 _IO_new_file_xsputn 호출

_IO_new_file_xsputn 심볼은 다음과 같은 연관이 있습니다.

_IO_sputn => _IO_XSPUTN => __xsputn => _IO_file_xsputn => _IO_new_file_xsputn

$cat ./libio/ioputs.c

int

_IO_puts (str)

const char *str;

{

int result = EOF;

_IO_size_t len = strlen (str);

_IO_acquire_lock (_IO_stdout);

if ((_IO_vtable_offset (_IO_stdout) != 0

  || _IO_fwide (_IO_stdout, -1) == -1)

  && _IO_sputn (_IO_stdout, str, len) == len

  && _IO_putc_unlocked ('\n', _IO_stdout) != EOF)

  result = MIN (INT_MAX, len + 1);

_IO_release_lock (_IO_stdout);

return result;

}

#ifdef weak_alias

weak_alias (_IO_puts, puts)

#endif

( weak_alias에 관한 설명 : https://en.wikipedia.org/wiki/Weak_symbol )

주목할점은 weak_alias 매크로 정의입니다. 이 매크로가 ifdef에 의해 사용가능하다면 weak type인   puts 함수는 _IO_puts로 바인드 됩니다. 이러한 점은 puts 심볼이 _IO_puts로 파싱된다는 점을 알 수 있습니다.

2._IO_new_file_xsputn 의  _IO_new_file_overflow 호출

1번 과정에서 맨 마지막으로 호출되는 _IO_new_file_xsputn는 다시 다음과 같은 순서로 연관되어집니다.

_IO_OVERFLOW => __overflow => _IO_new_file_overflow

$cat ./libio/fileops.c

_IO_size_t

_IO_new_file_xsputn (f, data, n)

_IO_FILE *f;

const void *data;

_IO_size_t n;

{

...

if (to_do + must_flush > 0)

  {

_IO_size_t block_size, do_write;

/* Next flush the (full) buffer. */

if (_IO_OVERFLOW (f, EOF) == EOF)

  /* If nothing else has to be written or nothing has been written, we

 must not signal the caller that the call was even partially

 successful. */

  return (to_do == 0 || to_do == n) ? EOF : n - to_do;

...

3._IO_new_file_overflow 의  _IO_doallocbuf 호출

4._IO_doallocbuf 의 _IO_file_doallocate 호출

_IO_doallocbuf은 다시 다음으로 연관되어 집니다.

_IO_doallocbuf => _IO_file_doallocate

$cat ./libio/fileops.c

int

_IO_new_file_overflow (f, ch)

_IO_FILE *f;

int ch;

{

...

/* If currently reading or no buffer allocated. */

if ((f->_flags & _IO_CURRENTLY_PUTTING) == 0 || f->_IO_write_base == NULL)

  {

/* Allocate a buffer if needed. */

if (f->_IO_write_base == NULL)

  {

   _IO_doallocbuf (f);

_IO_setg (f, f->_IO_buf_base, f->_IO_buf_base, f->_IO_buf_base);

  }

...

5.__IO_file_doallocate Call _IO_file_stat

_IO_file_stat은 다시 다음으로 연관되어 집니다.

_IO_SYSSTAT => __stat => _IO_file_stat

$cat ./libio/filedoalloc.c

int

_IO_file_doallocate (fp)

_IO_FILE *fp;

{

...

size = _IO_BUFSIZ;

if (fp->_fileno >= 0 && __builtin_expect (_IO_SYSSTAT (fp, &st), 0) >= 0)

  …

6.__IO_file_stat Call __fxstat64

마지막으로 _IO_file_stat는 위에서 보았던 스택프레임의 맨 아래에 존재하던 __fxstat64로 연관되어 집니다.

$cat ./libio/filedoalloc.c

int

_IO_file_stat (fp, st)

_IO_FILE *fp;

void *st;

{

return __fxstat64 (_STAT_VER, fp->_fileno, (struct stat64 *) st);

}

7.fstat64 A call to linux-gate.so:: __kernel_vsyscall

주목할점은 linux-gate.so은 디스크에 존재하지 않는 점입니다. 이 링크파일은 커널과 텀파일러에 의해 커널 이미지의 특정 페이지에 위치합니다.  더 자세한 정보를 얻고싶다면 linux-gate.so를 직접 살펴보어야 합니다.

끝 마치며.

이 기고문은 printf의 이해를 위함이였으며 컴파일러 과정에 따른 printf 함수의 수행과정을 발견하였습니다. 다음으로 gdb를 이용하여 printf함수에 따른 호출들을 역으로 추적해보았으며 최종적으로 glibc 소스코드를 통해 상세한 호출과정을 알 수 있었습니다. 이러한 printf 함수의 호출과정들을 규명함으로 printf 함수를 더욱 분명히 이해하며 computer의 메카니즘을 더욱 깊게 이해하게 하리라 믿습니다.

많은 도움이 되었길 바랍니다.