printf 함수 실행 분석하기

[0]

C에서 printf 함수가 호출되면, 어떤 과정을 걸쳐 콘솔에 프린트되는지 알아보자. 우선 printf는 stdio.h의 함수임을 상기할 필요가 있다. 이 라이브러리는 대부분의 운영체제에 C runtime이라는 이름으로 대부분 포함되어 있다. 이러한 라이브러리 코드들은 링커가 연결을 시켜주게 된다.(물론 이전에 컴파일되어 오브젝트 파일이 생성되는 게 먼저이다.) 여기에서는 링킹이나 컴파일 등은 제쳐두고, 순수하게 printf 함수 호출 시 실행되는 코드 플로우를 따라가 보도록 하자. 하드웨어 dependent한 부분은 최대한 제외하고, general한 부분만을 간략히 다루도록 하겠다.

 

[1]

printf가 호출되면 다음의 복잡한 매크로와 함께 _vfprintf_l()이 호출된다. 다음의 코드는 x86 windows 10의 C runtime stdio.h의 코드이다.

    _Check_return_opt_
    _CRT_STDIO_INLINE int __CRTDECL printf(
        _In_z_ _Printf_format_string_ char const* const _Format,
        ...)
    #if defined _NO_CRT_STDIO_INLINE
    ;
    #else
    {
        int _Result;
        va_list _ArgList;
        __crt_va_start(_ArgList, _Format);
        _Result = _vfprintf_l(stdout, _Format, NULL, _ArgList);
        __crt_va_end(_ArgList);
        return _Result;
    }
    #endif

vfprintf_l()이 호출됨을 알 수 있다. 운영체제에서 기본으로 설치된 C runtime마다 다르겠지만 stdio.h에서 보통 몇 단계의 함수호출이 더 이루어지게 된다. 여기에서는 생략한다.

 

[2]

runtime 이후에는 운영체제에 따라 시스템콜이 호출된다. 시스템콜이 호출 시 보통 커널 컨텍스트로 스위칭이 이루어지고(이 부분은 운영체제 구현에 따라 상이할 수 있다.) 커널 코드가 실행된다. 여기에서는 x86 리눅스 커널을 기반으로 함수 호출 플로우를 따라가 보자. 우선 strace로 어떤 시스템콜이 호출되는지 알아보자.

#include <stdio.h>

int main(void){
    printf("hello\n");
}

$ strace ./a.out 
execve("./a.out", ["./a.out"], 0x7fffe5eeb5f0 /* 18 vars */) = 0
brk(NULL)                               = 0x7fffe7f2f000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=31764, ...}) = 0
mmap(NULL, 31764, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f8ba6816000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2030544, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8ba6810000
mmap(NULL, 4131552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8ba6000000
mprotect(0x7f8ba61e7000, 2097152, PROT_NONE) = 0
mmap(0x7f8ba63e7000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7f8ba63e7000
mmap(0x7f8ba63ed000, 15072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f8ba63ed000
close(3)                                = 0
arch_prctl(ARCH_SET_FS, 0x7f8ba68114c0) = 0
mprotect(0x7f8ba63e7000, 16384, PROT_READ) = 0
mprotect(0x7f8ba6c00000, 4096, PROT_READ) = 0
mprotect(0x7f8ba6627000, 4096, PROT_READ) = 0
munmap(0x7f8ba6816000, 31764)           = 0
fstat(1, {st_mode=S_IFCHR|0660, st_rdev=makedev(4, 1), ...}) = 0
ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
brk(NULL)                               = 0x7fffe7f2f000
brk(0x7fffe7f50000)                     = 0x7fffe7f50000
write(1, "hello\n", 6hello
)                  = 6
exit_group(0)                           = ?
+++ exited with 0 +++

 

여러 시스템콜들이 호출되고 있지만, 가장 핵심인 "hello"를 출력하는 시스템콜은 write()임을 확인할 수 있다. 여기에서부터는 리눅스 커널에서 실행 흐름을 따라가 보도록 하자. 커널 버전은 5.7이다. 

 

[3]

SYSCALL_DEFINE3(write, unsigned int, fd, const char __user *, buf,
		size_t, count)
{
	return ksys_write(fd, buf, count);
}

우선 write 시스템 콜에서는 ksys_write()를 호출할 뿐 별다른 역할은 하지 않는다.

ssize_t ksys_write(unsigned int fd, const char __user *buf, size_t count)
{
	struct fd f = fdget_pos(fd);
	ssize_t ret = -EBADF;

	if (f.file) {
		loff_t pos, *ppos = file_ppos(f.file);
		if (ppos) {
			pos = *ppos;
			ppos = &pos;
		}
		ret = vfs_write(f.file, buf, count, ppos);
		if (ret >= 0 && ppos)
			f.file->f_pos = pos;
		fdput_pos(f);
	}

	return ret;
}

ksys_write()에서부터 중요한 동작들이 실행된다. 우선 fdget_pos()를 통해 파일 디스크립터 fd를 구조체의 형태로 가져온다.(fd구조체는 커널 코드 내에서만 사용되고, 유저 애플리케이션에는 integer 형태로 fd를 반환한다.) file_ppos() 함수를 호출하여 파일 포인터의 현 위치를 읽어오고, vfs_write()로 실제 write를 수행한 뒤에, 변경된 위치를 fdput_pos()로 저장한다. 다음으로 vfs_write()를 보자.

ssize_t vfs_write(struct file *file, const char __user *buf, size_t count, loff_t *pos)
{
	ssize_t ret;

	if (!(file->f_mode & FMODE_WRITE))
		return -EBADF;
	if (!(file->f_mode & FMODE_CAN_WRITE))
		return -EINVAL;
	if (unlikely(!access_ok(buf, count)))
		return -EFAULT;

	ret = rw_verify_area(WRITE, file, pos, count);
	if (!ret) {
		if (count > MAX_RW_COUNT)
			count =  MAX_RW_COUNT;
		file_start_write(file);
		ret = __vfs_write(file, buf, count, pos);
		if (ret > 0) {
			fsnotify_modify(file);
			add_wchar(current, ret);
		}
		inc_syscw(current);
		file_end_write(file);
	}

	return ret;
}

우선 f_mode를 체크하여 이 파일이 write 가능한 상태인지를 체크한다. rw_verify_area() 함수로 쓰기가 진행되는 영역이 안전한지 체크하고, __vfs_write()를 통해 write가 일어난다. 이때 __vfs_write() 전후로 file_start_write()와 file_end_write()를 통해 이 파일이 현재 write 작업 중임을 마킹하고 해제한다. 마지막으로 __vfs_write()를 보자.

static ssize_t __vfs_write(struct file *file, const char __user *p,
			   size_t count, loff_t *pos)
{
	if (file->f_op->write)
		return file->f_op->write(file, p, count, pos);
	else if (file->f_op->write_iter)
		return new_sync_write(file, p, count, pos);
	else
		return -EINVAL;
}

여기에선 단순하다. f_op에 등록된 각 디바이스의 write함수를 호출한다. 즉 여기서부터는 하드웨어 dependent한 구현의 코드가 들어가게 된다.

 

[참고]

https://www.maizure.org/projects/printf/

Tearing apart printf() – MaiZure's Projects

http://egloos.zum.com/rousalome/v/9993265

[리눅스커널][가상파일시스템] 파일 객체: write 연산 세부 동작 분석