리눅스 strace 명령어를 통해, "hello world"를 출력하는 코드가 어떤 시스템 콜을 호출하는 지 알아보려 합니다.
hello world!
프로그래밍에 입문한 사람이라면 가장 처음 보는 문장입니다.
"컴퓨터의 세계에 온 것을 환영한다"는 의미입니다.
컴퓨터 엔지니어가 되고싶은 사람이라면
위 문장을 화면에 출력해줄 여러 함수를 조합해가며
첫 프로그램 파일을 작성했을 것입니다.
이런 출력 코드 작성은
프로그래밍 언어의 문법, 문맥을 잘 살펴볼 수 있는 좋은 예시이기도 합니다.
간단한 코드 작성으로 내가 원하는 문장을 출력해보는 경험을 할 수 있으니까요.
음... 그런데 저는 OS를 공부하던 중 문득 이런 생각이 들었어요.
진짜 간단할까?
아래와 같은 python 스크립트를 작성해 실행시켰다고 생각해볼까요?
먼저 아래와 같은 파이썬 파일을 하나 작성해줍니다.
hello.py
#python 3
print("hello world!")
그리고 아래 명령어를 통해 해당 파이썬 파일을 실행시켜요.
CLI 환경에서 작동하는 명령어지만, visual studio code 같은 곳에서 Ctrl+Shift+F5 와 같은 단축키를 통해 실행시키는 과정과 별반 다를게 없습니다.
어쨋든 파이썬 스크립트를 실행시키는 과정이라는 게 중요해요.
$ python3 hello.py
그러면 해당 스크립트를 실행시킨 터미널에서 아래와 같은 문자열이 나올거에요.
hello world!
참 간단하죠?
사실 간단하게 보이도록 추상화가 되어있을 뿐,
간단하지 않습니다.
파이썬 스크립트를 실행시키면
하나의 파이썬 프로세스가 되고
이 프로세스를 실행시키기 위해
OS가 CPU, Memory와 같은 자원을 할당하고,
관련 메타 데이터를 읽어와 수많은 준비작업을 진행합니다.
print 한 문장을 실행시키기 위해, 정말 많은 시스템콜이 사용됩니다.
사용자 프로그램(python 스크립트) 계층의 명령어(print 함수)는
여러 시스템 콜의 조합으로 변환되고,
이를 커널 계층(OS, 운영체제)이 받아
사용자 프로그램을 프로세스화해서 실행시킬 수 있도록
관리하게 됩니다.
여기서 중요한건,
이렇게 복잡한 과정도 결국엔
전부 코드로 이뤄져 있다는 점입니다.
그리고 시스템콜은 그리 많지 않은 종류로 구성되어있기도 하고요.
아래 챕터에서 더 자세히 알아봅시다.
Ubuntu Linux 에서 strace 명령어로 더 자세히 알아보기
리눅스 환경에서 위와 같이, hello world를 출력하는 python 스크립트를 하나 작성합니다.
그리고 OS에 아래 패키지를 설치해줍니다.
$ apt-get install strace
strace 명령어는 프로세스가 어떤 시스템 콜을 호출하는지
확인할 수 있게 해줍니다.
아래 명령어를 bash에 입력해봅시다.
strace 출력 결과는 -o 옵션을 통해
파일로 저장 가능합니다.
$ strace -o hello.py.log python3 ./hello.py
hello world
이전과 똑같은 출력 결과가 나오고 프로그램이 종료되었습니다.
그러면 strace 출력 결과가 저장된 hello.py.log 내용을 살펴볼게요.
$cat hello.py.log
...
write(1, "hello world!\n", 13) = 13
...
strace는 각각의 출력 줄이 사용된 시스템 콜 1개를 나타냅니다.
처음에 엄청난 준비를 하다가,
결국 마지막 즈음에 write 시스템콜을 호출하네요.
stdout, 표준출력, 즉 사용자 디스플레이를 의미하는 1번 파일 디스크립터에
13바이트 크기의 문자열을 출력하라는 명령어입니다.
문장 한 줄을 띄워주는 이스케이프 문자 \n을 포함해서
"hello world!\n" 은 총 13바이트 입니다.
마지막 = 연산자 이후의 값은
해당 시스템 콜이 반환하는 return value 입니다.
보통 0 및 0 이상의 숫자는 정상 작동을 의미하고,
return value -1는 오류를 의미합니다.
음..
보면 알 수 있듯, 전부다 코드로 이뤄져 있네요.
더 자세히 살펴볼까요?
더 자세히
system call : execve
strace 로그의 첫 줄부터 볼까요?
execve("/usr/bin/python3", ["python3", "./hello.py"], 0x000000000000 /* 30 vars */) = 0
execve는, 새로운 프로그램을 실행하기 위한 시스템 콜이에요.
execve를 통해, 현재 프로세스를 python3 인터프리터로 대체해 hello.py 파이썬 프로그램을 시작하게 됩니다.
(파이썬은 스크립트 언어여서, 코드 자체로 이미 프로그램이에요)
첫 번째 인자로 프로그램의 경로,
두 번째 인자는 프로그램에 전달할 인자 배열(argument array),
세 번째 인자는 프로그램에 전달할 환경 변수 배열를 의미합니다.
위 시스템콜에서 세 번째 인자인 환경 변수 배열은,
인자 배열처럼 직접 값으로 주어진게 아니라
환경 변수 배열이 존재하는 메모리 값이 주어졌습니다.
(위 예시에서는 보안상 제 메모리 주소를 0x0000.. 으로 표현했습니다.)
주석에 30 vars 라 써져있는데, 해당 메모리 주소에 실제로 30개의 환경변수 {key: value} 쌍이 존재합니다.
execve는 현재 프로세스를 다른 프로그램을 호출해 대체한다고 했잖아요?
그럼 어떤 프로세스를 대체하는걸까요?
보통 bash와 같은 쉘에 명령어를 입력해 실행시켰으니까,
bash를 대체하는 걸까요?
접근은 맞으나 조금 다릅니다.
bash에 명령어를 입력하면,
clone 시스템 콜 호출을 통해 새로운 프로세스를 하나 생성한 뒤
execve로 현재 프로세스를 특정 프로그램으로 대체하게 됩니다.
(그러나 strace 결과 log에 프로세스 생성 및 분기 시스템 콜(clone)이 보이지 않는 이유는
"clone으로 프로세스 분기를 한 결과부터 새로운 프로세스로 관리"하기 때문에,
clone 호출 이후에 프로세스가 호출한 시스템 콜 부터 기록하는 것 같아요)
그럼 bash에서 python 프로그램을 실행하면, 해당 프로세스의 부모 프로세스는 bash가 되겠네요?
확인해봅시다.
부모 프로세스의 정보를 확인하기 위해 아래 라이브러리를 추가로 설치해줍시다.
$ pip install psutil
그리고 다음 check_parent_process_name.py 스크립트를 작성해봐요.
# check_parent_process_name.py
import os
import psutil
def main():
# 현재 프로세스의 PID
current_pid = os.getpid()
# 현재 프로세스의 부모 프로세스 PID
parent_pid = os.getppid()
# 부모 프로세스 객체 생성
parent_process = psutil.Process(parent_pid)
# 부모 프로세스의 이름
parent_process_name = parent_process.name()
print(f"현재 프로세스 PID: {current_pid}")
print(f"부모 프로세스 PID: {parent_pid}")
print(f"부모 프로세스 이름: {parent_process_name}")
if __name__ == "__main__":
main()
실행해봅시다.
$ python3 check_parent_process_name.py
위처럼 bash에서 특정 파일을 실행하면, 부모 프로세스가 bash가 되는 걸 확인할 수 있네요!!
신기합니다.
진짜 bash의 process id가 95967이 맞을까요??
확인해봅시다.
$ ps
bash의 pid는 95967이 맞네요!!
다음 주요한 시스템 콜을 살펴봅시다.
OS가 한 프로세스를 실행시키기 위해
어떤 작업을 하는지 떠올리면 이해하기 쉬울거에요.
execve("/usr/bin/python3", ["python3", "./hello.py"], 0x7ffc1bd22008 /* 30 vars */) = 0 <0.000197>
brk(NULL) = 0x12eb000 <0.000007>
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffdea4511c0) = -1 EINVAL (Invalid argument) <0.000007>
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000010>
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000012>
fstat(3, {st_mode=S_IFREG|0644, st_size=34910, ...}) = 0 <0.000009>
mmap(NULL, 34910, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5e1d57c000 <0.000009>
close(3) = 0 <0.000007>
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000013>
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300A\2\0\0\0\0\0"..., 832) = 832 <0.000008>
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.000008>
pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32, 848) = 32 <0.000007>
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\7\2C\n\357_\243\335\2449\206V>\237\374\304"..., 68, 880) = 68 <0.000007>
...
python 프로세스의 시스템 콜 전체 호출을 기록한 파일 내용입니다.
각 문장 맨 마지막에 적혀있는 소수점 6자리 시간은
각 시스템 콜에 소요된 시간을 기록한 정보에요.
strace 명령어에 -T 옵션을 주면 출력해줍니다.
전체 기록을 더 자세히 볼까요?
우선 OS가 유지할 프로세스 정보를 만들어주고 (execve),
프로그램이 사용할 여러 라이브러리를 가져오고(openat),
프로세스가 존재할 메모리를 매핑하고 보호(mmap, mprotect)하는 과정을 거쳐
프로세스가 실행될 준비를 마쳐줍니다.
이후 hello.py가 실행하려던 함수 print에 맞는 시스템콜
write을 호출해 사용자 디스플레이에 "hello world!"를 출력하게 됩니다.
이러한 과정 속에서, 기존에 정의된 linux의 표준 스펙(페이지 크기 등)을 지키기 위해
여러 명세를 읽어들이고(read)
여러 파일 포지션을 유지(lseek)하는 등
다양한 시스템 콜이 사용됩니다.
위 그림을 보면 알 수 있듯, 하나의 함수 print("hello world!") 를 실행하기 위해
들어가는 노력이 장난 아니네요.
파이썬은 스크립트 언어이고,
사용자가 사용하기 더욱 편하게 추상화 되어있으니(C++, go와 같은 언어에 비해)
당연히 많은 사전 작업을 동반할 수 밖에 없는 걸까요?
Go 언어를 이용한 "hello world!" 출력 분석과 비교해봅시다.
Go로 출력하는 "hello world!" 분석
아래처럼 "hello world!"를 출력하는 go 파일을 작성합니다.
// hello.go
package main
import(
"fmt"
)
func main(){
fmt.Println("hello world!")
}
go는 컴파일 언어이기 때문에,
아래처럼 빌드하는 과정이 필요합니다!
$ go build ./hello.go
컴파일을 완료하면, hello라는 실행가능한 파일이 생기고,
다음처럼 터미널에 hello를 입력하면 파일이 실행됩니다.
./hello
strace를 통해 go 실행파일이 실행하는 시스템 콜 목록을 확인해볼까요?
strace -o hello.log ./hello이전과 동일하게, -o 옵션을 통해 시스템 콜 목록을 hello.log에 저장합니다.
execve("./hello", ["./hello"], 0x* /* 30 vars */) = 0
arch_prctl(ARCH_SET_FS, 0x*) = 0
sched_getaffinity(0, 8192, [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31]) = 8
openat(AT_FDCWD, "/sys/kernel/mm/transparent_hugepage/hpage_pmd_size", O_RDONLY) = 3
read(3, "2097152\n", 20) = 8
close(3) = 0
mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x*
mmap(0x*, 67108864, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x*
mmap(0x*, 67108864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xc000000000
mmap(NULL, 33554432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x*
mmap(NULL, 2164736, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x*
mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x*
mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x*
rt_sigprocmask(SIG_SETMASK, NULL, [], 8) = 0
sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
sigaltstack({ss_sp=0x*, ss_flags=0, ss_size=32768}, NULL) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
gettid() = 328411
rt_sigaction(SIGHUP, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGHUP, {sa_handler=0x*, sa_mask=~[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_RESTART|SA_SIGINFO, sa_restorer=0x455310}, NULL, 8) = 0
rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGINT, {sa_handler=0x*, sa_mask=~[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_RESTART|SA_SIGINFO, sa_restorer=0x455310}, NULL, 8) = 0
rt_sigaction(SIGQUIT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGQUIT, {sa_handler=0x*, sa_mask=~[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_RESTART|SA_SIGINFO, sa_restorer=0x455310}, NULL, 8) = 0
...위와 같은 결과를 볼 수 있습니다.
python 프로세스에 대해 strace를 실행한 것처럼,
Go 파일을 실행한 Go 프로세스도 맨 처음 호출하는 시스템 콜이 execve입니다.
그 다음 arch_prctl 시스템콜로 프로그램의 아키텍처와 관련된 설정을 합니다.
이후 mmap을 통해 메모리 매핑을 계속 진행합니다.
이후 대부분의 코드는 sigaction 시스템 콜을 통해
여러 시그널에 대한 handler를 지정해줍니다.
이후 약 150번째 라인에서
write 시스템콜을 통해 stdout에 "hello world!\n"를 출력하도록 합니다.
파이썬에 비하면 약 5배정도 적은 시스템 콜 수행량을 가지고 있습니다.
Go와 Python 수행속도 비교
"hello world!" 를 출력하는 비교적 간단한 작업임에도 불구하고,
Go 언어는 Python 보다 호출하는 시스템 콜이 약 5배 가량 적습니다.
Go 같은 컴파일 언어는 일반적으로 Python같은 스크립트 언어보다
빠른 수행 속도를 가지고 있다고 알려져있습니다.
그 이유 중 하나가 이렇듯 함수 실행 전 사전작업에 들이는 system call의 적고 많음에 있는 것 아닐까요?
한 번 각 프로세스의 수행 시간을 비교해봅시다.
리눅스 명령어 중 time(1)을 사용해 프로그램의 실행 시간을 측정할 수 있습니다.
time 뒤에 (1)을 붙인 이유는, (1)은 time(2)와 다른 쉘 명령어를 의미하기 때문입니다.
( time(2)는 unix timestamp를 반환하는 시스템 콜입니다. )
Go 프로세스가 "hello world!"를 출력하는데 걸린 시간
$ time strace -o trace.log -T -tt ./hello
Python 프로세스가 "hello world!"를 출력하는데 걸린 시간
$ time strace -o trace.log -T -tt python3 ./hello.py
보시면 알 수 있듯, system call 개수랑 비슷하게
시스템 콜 전체 호출에 소요된 시간이 대략 5배가량 차이가 납니다.
(실행 환경 혹은 명령어를 실행할 때마다 편차가 존재할 수 있습니다.)
전체 실행 시간인 real time은 세 배 정도 차이나는 것을 볼 수 있네요.
(언어별 실행 속도를 일반화 하고자 하는 것이 아닙니다.
단지 실행 환경 구성을 위해 얼마나 많은 시간을 쏟는지 언어별 비교를 하기 위함입니다.)
왜 파이썬이 실행 속도가 더 느릴까요?
저희가 지금까지 strace를 통해 본 시스템 콜 호출 목록은
런타임 실행 시의 목록입니다.
Go는 컴파일 언어이면서
기본적으로 라이브러리를 정적 링크하는 언어입니다.
따라서 컴파일 단계에서 필요한 모든 종속성(라이브러리)를 포함합니다.
그렇기 때문에 런타임 단계에서 라이브러리를 가져올 필요가 없어
빠른 런타임 속도를 가지고 있습니다.
그러나 파이썬은 인터프리터 기반 언어이기 때문에,
런타임 시에 openat 시스템 콜을 통해 필요한 공유 라이브러리를 동적으로 로드합니다.
동적으로 로드한다는 것은
프로세스가 실행중인 런타임 시간에 라이브러리를 로드한다는 것과 동일한 말입니다.
런타임에서 이 과정을 무려 63번이나 합니다.
라이브러리를 동적으로 로드하는 전체 과정에 걸린 시간은 무려 0.00659s 나 됩니다.
$ grep 'openat' hello.py.log | sed 's/[<>]//g' | awk '{sum += $NF} END {printf "%.6f\n", sum}'
0.000659(strace log 중 라이브러리 로드 시스템 콜 'openat'이 존재하는 line을 보고,
파이프연산자로 다음 명령어에 넘긴다.
다음 명령어 sed를 통해 한 문장 속 수행한 시간 부분을 감싸고 있는 '<', '>' 문자를 제거한 후 결과를 다음 명령어 awk에 넘긴다.
이후 awk 명령어는 해당 문장의 맨 마지막 필드에서 시간 값을 더해, 그 결과를 출력한다. => 전체 수행 시간 중 라이브러리 로드 시스템 콜 openat에 걸린 시간 출력)
이러한 주요 차이점에 의해 실행 속도에 차이가 나게 됩니다.
마지막으로,
"앗, 근데 그럼 Go를 컴파일 할 때 걸린 시간과 시스템 콜 호출 목록도 고려해봐야 하는 것 아닐까요?"
라고 생각하셨나요?
좋습니다. 같이 알아봐요.
$ time strace -o go_compile.log -T -tt go build ./hello.go
Go는 기본적으로 동적 링킹을 하지 않고 정적으로 라이브러리를 링크하기 때문에
컴파일 단계에 걸리는 시간이 무지막지하다는 걸 알 수 있었습니다.
호출한 시스템 콜 개수도 무려 2400개가 넘어갑니다.
런타임에서의 빠른 실행을 위해, 준비과정이 정말 길게 든다는 걸 알 수 있었네요.
아래 명령어 입력 이후, go_complie.log 파일을 읽어봅시다.
$ strace -o go_compile.log go build ./hello.go
대부분의 작업이 라이브러리 로드로 구성되어있는 걸 알 수 있습니다.
끝!
Ref.
'OS > Linux' 카테고리의 다른 글
| Linux scheduler의 time slice 가시화 ( + nice value) (2) | 2024.10.18 |
|---|