실험
프로세스가 사용자 모드와 커널 모드 중 어느 쪽에서 실행되고 있는지의 비율은 sar 명령어를 통해 알 수 있다. 각 CPU 코어가 어떤 종류의 처리를 실행하고 있는지를 1초 단위로 측정한다.
sar -P ALL 1 을 통해 확인이 가능하다. Ctrl c를 누르면 데이터 평균치를 출력하고 sar을 종료한다.
CPU 코어에서 실행되고 있던 처리의 종류는 각 줄의 %user 부터 %idle까지 필드에 표시된다. 한 줄의 필드값을 전부 더하면 100이 된다. 이를 통해 한 줄에 1개의 CPU 코어가 대응하고 있으므로 이 시스템에 탑재된 8개의 CPU 코어 각각에 대해 정보가 출력되고 있음을 알 수 있다.
사용자 모드에서 프로세스 실행하고 있는 시간의 비율은 %user와 %nice의 합계로 얻을 수 있다. CPU 코어가 커널 모드에서 시스템 콜 등의 처리를 실행하고 있는 시간의 비율은 %system으로 얻을 수 있다.
코드로 실험
시스템 콜을 호출하지 않고 계속 무한루프를 도는 프로그램을 실행하여 sar로 확인한다.
loop.c
int main(void)
{
for(;;)
;
}shell
gcc -o loop loop.c
./loop &위 코드를 실행 후 sar -P ALL 1 1을 통해 CPU 코어 0에서는 유저 프로세스, 즉 loop 프로그램이 계속해서 동작하고 있었던 것을 알 수 있다.
loop 프로그램의 동작
측정이 끝난다면 kill 13093 통해 프로그램을 종료할 수 있다.
단순히 부모 프로세스의 프로세스 ID를 얻는 getppid() 시스템 콜을 무한루프 하는 프로그램을 실행해서 측정한다.
ppidloop.c
#include <sys/types.h>
#include <unistd.h>
int main(void)
{
for(;;)
getppid();
}shell
gcc -o ppidloop ppidloop.c
./ppidloop &
sar -P ALL 1 1실행 결과를 보면 통계 정보를 측정하고 있던 1초 동안 한 일을 알 수 있다.
- CPU 1 내에서는 ppidloop 프로그램을 28%의 비율로 실행하고 있다
- ppidloop 프로그램의 요청에 대응하여 이 프로그램의 부모 프로세스를 얻는 커널의 처리를 72% 비율로 실행하고 있다.
대체로 %system의 수치가 크면 시스템 콜이 너무 많이 호출되고 있거나 시스템에 과부하가 걸려 있는 등의 좋지 않은 상태를 의미한다.
시스템 콜의 소요시간
strace에 -T 옵션을 붙여 각종 시스템 콜 처리에 컬린 시간을 마이크로초 단위로 정밀하게 측정할 수 있다. %system의 점유율이 높을 때 구체적으로 어떤 시스템 콜에 시간이 걸리고 있는지를 확인할 경우 이 기능을 사용하면 편리하다. hello 프로그램에 strace -T를 실행한 결과이다
strace -T -o t_hello.log ./hello
t_hello.log
execve("./hello", ["./hello"], 0x7ffeefd27878 /* 70 vars */) = 0 <0.000138>
brk(NULL) = 0x5560b39b2000 <0.000003>
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc7d3f5f40) = -1 EINVAL (Invalid argument) <0.000003>
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f06f8c12000 <0.000004>
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000006>
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000005>
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=57679, ...}, AT_EMPTY_PATH) = 0 <0.000004>
mmap(NULL, 57679, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f06f8c03000 <0.000004>
close(3) = 0 <0.000003>
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000005>
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\237\2\0\0\0\0\0"..., 832) = 832 <0.000004>
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784 <0.000004>
pread64(3, "\4\0\0\0 \0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0"..., 48, 848) = 48 <0.000004>
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0i8\235HZ\227\223\333\350s\360\352,\223\340."..., 68, 896) = 68 <0.000003>
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=2216304, ...}, AT_EMPTY_PATH) = 0 <0.000004>
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784 <0.000003>
mmap(NULL, 2260560, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f06f89db000 <0.000006>
mmap(0x7f06f8a03000, 1658880, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28000) = 0x7f06f8a03000 <0.000010>
mmap(0x7f06f8b98000, 360448, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bd000) = 0x7f06f8b98000 <0.000007>
mmap(0x7f06f8bf0000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x214000) = 0x7f06f8bf0000 <0.000006>
mmap(0x7f06f8bf6000, 52816, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f06f8bf6000 <0.000005>
close(3) = 0 <0.000003>
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f06f89d8000 <0.000004>
arch_prctl(ARCH_SET_FS, 0x7f06f89d8740) = 0 <0.000003>
set_tid_address(0x7f06f89d8a10) = 8292 <0.000003>
set_robust_list(0x7f06f89d8a20, 24) = 0 <0.000003>
rseq(0x7f06f89d90e0, 0x20, 0, 0x53053053) = 0 <0.000003>
mprotect(0x7f06f8bf0000, 16384, PROT_READ) = 0 <0.000006>
mprotect(0x5560b2073000, 4096, PROT_READ) = 0 <0.000005>
mprotect(0x7f06f8c4c000, 8192, PROT_READ) = 0 <0.000006>
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0 <0.000004>
munmap(0x7f06f8c03000, 57679) = 0 <0.000008>
newfstatat(1, "", {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}, AT_EMPTY_PATH) = 0 <0.000005>
getrandom("\xbf\xb6\xd6\xe3\x51\xc1\x06\x77", 8, GRND_NONBLOCK) = 8 <0.000004>
brk(NULL) = 0x5560b39b2000 <0.000003>
brk(0x5560b39d3000) = 0x5560b39d3000 <0.000004>
write(1, "hello world\n", 12) = 12 <0.000009>
exit_group(0) = ?
+++ exited with 0 +++이것을 통해 hello world\n을 처리하는 데 14마이크로초가 걸렸던 것을 알 수 있다.
-tt을 통해 마이크로초 단위로 표시할 수 있다.
