프로그램이 커널에 무엇을 부탁하는지 센다
이 실습은 VM 에서 돕니다
우분투 24.04 VM 한 대입니다. root 이고 커널 권한이 있어서 strace 가 다른
프로세스에 붙을 수 있습니다. 실습 파드에서는 ptrace 권한이 없어 이 실습이
불가능합니다. 처음 뜨는 데 1분 남짓 걸립니다.
목표
프로그램이 사용자 공간에서 커널로 넘어가는 자리, 곧 시스템 콜을 직접 세고
읽습니다. 숨겨진 설정 파일과 열린 로그 파일을 시스콜 기록과 /proc 에서 찾아내고,
date 가 시간을 읽는데도 시스템 콜이 보이지 않는 이유(vDSO)를 확인합니다.
마지막으로 strace 가 프로그램을 얼마나 느리게 만드는지 재서, 운영 서버에서
왜 다른 도구가 필요한지 숫자로 봅니다.
왜 중요한가
장애 대응에서 가장 흔한 질문은 "이 프로그램이 지금 무엇을 하고 있나" 입니다. 로그가 없거나 거짓말을 할 때도 시스템 콜은 거짓말을 하지 않습니다. 파일을 열든, 소켓에 쓰든, 잠을 자든 커널에 부탁해야 하기 때문입니다. 설정 파일을 어디서 읽는지, 어떤 경로를 헛짚는지, 왜 느린지가 그 기록에 다 들어 있습니다.
그런데 strace 는 ptrace 로 매 시스템 콜마다 프로세스를 멈춥니다. 그래서 바쁜
서버에서 함부로 붙이면 장애를 키웁니다. 이 실습의 마지막 두 단계가 그 비용을
직접 재는 자리이고, 이 코스 뒤쪽의 eBPF 가 바로 그 비용을 없애려고 나온 기술입니다.
단계
ls -la /etc의 시스템 콜을 종류별로 세어 요약표를/root/kx/sys/01-count.txt에 저장하세요.kx-report가 몰래 읽는 설정 파일을 추적해, 추적 기록을/root/kx/sys/02-trace.txt에, 찾은 경로를/root/kx/sys/02-conf.txt에 적으세요.- 서비스
kx-daemon이 열어 둔 로그 파일을/proc에서 찾아/root/kx/sys/03-fd.txt에pid=·fd=·path=세 줄로 적으세요. date가 시간을 시스템 콜 없이 읽는다는 증거를/root/kx/sys/04-date.txt와/root/kx/sys/04-vdso.txt에 남기세요.- vDSO 가 대신해 주지 않는 시계를 읽으면 시스템 콜이 보인다는 것을
/root/kx/sys/05-cputime.txt에 남기세요. python3 -c 'import json'이 실패한 openat 만 골라/root/kx/sys/06-failed.txt에 저장하세요.strace가 붙었을 때와 아닐 때의 실행 시간을 재서/root/kx/sys/07-overhead.txt에 적으세요.- 배운 것을
/root/kx/sys/08-report.md에 정리하세요.
참고
strace -c는 요약표를,-o 파일은 기록을 파일로,-f는 자식 프로세스까지,-e trace=openat은 한 종류만 고릅니다.-f를 주면 기록 각 줄 앞에 PID 가 붙습니다. 자식이 한 일은 그 PID 로 구별합니다.- 서비스의 PID 는
systemctl show -p MainPID --value <서비스>로, 열린 파일은ls -l /proc/<pid>/fd로 봅니다. - 흔한 실수:
-f없이 셸 스크립트를 추적하는 것. 스크립트가 부른 명령(자식)이 한 일은 하나도 안 보입니다.
시스템 콜을 종류별로 센다
ls -la /etc 를 strace -c 로 실행해 시스템 콜 요약표를 /root/kx/sys/01-count.txt 에 저장하세요. 표의 마지막 total 줄까지 들어 있어야 합니다.
strace -c 는 프로그램이 끝날 때 표를 표준 오류로 냅니다. 표만 파일로 받으려면 -o 파일 을 쓰고, ls 의 출력은 /dev/null 로 보내면 됩니다. 디렉터리를 읽는 시스템 콜이 표에 보이는지 확인하세요.
숨겨진 설정 파일을 찾는다
kx-report 를 실행하며 openat 만 추적해 기록을 /root/kx/sys/02-trace.txt 에 저장하고, 기록에서 찾은 설정 파일의 절대 경로 하나를 /root/kx/sys/02-conf.txt 의 첫 줄에 적으세요. 이 VM 의 경로는 다른 VM 과 다릅니다.
kx-report 는 셸 스크립트이고 설정 파일은 스크립트가 부른 다른 명령이 엽니다. 부모만 추적하면 그 줄이 보이지 않습니다. 자식 프로세스까지 따라가는 옵션을 켜고, 기록에서 .conf 로 끝나는 경로를 찾으세요. /etc/nsswitch.conf 처럼 C 라이브러리가 스스로 여는 시스템 설정도 섞여 나오니 구별하세요.
열려 있는 파일을 /proc 에서 찾는다
서비스 kx-daemon 의 PID 를 찾고, 그 프로세스가 fd 3 으로 열어 둔 로그 파일의 절대 경로를 /proc 에서 읽어 /root/kx/sys/03-fd.txt 에 pid=·fd=·path= 세 줄로 적으세요.
systemd 가 관리하는 서비스의 PID 는 systemctl show 의 MainPID 속성에 있습니다. /proc/<pid>/fd/ 아래의 항목은 심볼릭 링크라서 링크가 가리키는 곳이 곧 열린 파일입니다. 서비스가 다시 떴다면 PID 가 바뀌니 새로 확인하세요.
시간을 읽는데 시스템 콜이 없다
strace -e trace=clock_gettime,gettimeofday 로 date 를 실행한 기록을 /root/kx/sys/04-date.txt 에 저장하고, 셸 자신의 메모리 지도에서 [vdso] 줄을 골라 /root/kx/sys/04-vdso.txt 에 저장하세요.
date 는 분명 시간을 읽는데 기록에는 그 시스템 콜이 없습니다. 커널이 프로세스마다 넣어 주는 작은 공유 라이브러리가 그 일을 대신하기 때문입니다. 그 라이브러리가 어디에 올라가 있는지는 /proc/self/maps 에 이름표와 함께 나옵니다.
vDSO 가 대신해 주지 않는 시계
python3 -c 'import time; time.clock_gettime(time.CLOCK_PROCESS_CPUTIME_ID)' 를 strace -e trace=clock_gettime 로 실행한 기록을 /root/kx/sys/05-cputime.txt 에 저장하세요. 이번에는 기록에 clock_gettime(CLOCK_PROCESS_CPUTIME_ID 줄이 있어야 합니다.
vDSO 는 벽시계와 단조 시계처럼 커널이 공유 페이지에 미리 적어 둘 수 있는 시계만 대신 답합니다. 프로세스가 쓴 CPU 시간은 커널이 그 순간 계산해야 하므로 진짜 시스템 콜이 납니다. 같은 실험을 CLOCK_MONOTONIC 으로 바꿔 비교해 보세요.
실패한 시스템 콜만 고른다
python3 -c 'import json' 을 자식까지 추적하면서 실패한 openat 만 남긴 기록을 /root/kx/sys/06-failed.txt 에 저장하세요. 성공한 openat 줄이 섞여 있으면 안 됩니다.
strace 에는 결과가 실패인 시스템 콜만 남기는 옵션이 있습니다(man strace 에서 failed 를 찾아보세요). 파이썬이 모듈을 찾으려고 여러 경로를 헛짚는 모습이 그대로 보입니다. 실패가 곧 오류는 아니라는 것도 여기서 확인할 수 있습니다.
strace 의 값을 잰다
dd if=/dev/zero of=/dev/null bs=1 count=200000 status=none 를 그냥 실행한 시간과 strace -c -o /dev/null 을 붙여 실행한 시간을 밀리초로 재서 /root/kx/sys/07-overhead.txt 에 plain_ms= 와 strace_ms= 두 줄로 적으세요.
date +%s%N 은 나노초를 줍니다. 앞뒤로 재서 빼고 1000000 으로 나누면 밀리초입니다. bs=1 이라 이 명령은 시스템 콜을 40만 번 부르고, strace 는 그 하나하나에서 프로세스를 멈춥니다. 차이가 몇 배인지 보세요.
경계에서 본 것을 정리한다
/root/kx/sys/08-report.md 에 ## 경계를 넘는 일·## vDSO·## 운영에서 strace 를 쓸 때 세 절을 쓰세요. 본문에 ptrace 와 vDSO 가 나와야 하고, 7단계에서 잰 두 숫자를 그대로 인용해야 합니다.
첫 절에는 시스템 콜이 무엇을 위해 있는지와 2·3단계에서 무엇을 찾았는지를, 둘째 절에는 4·5단계의 차이를, 셋째 절에는 7단계의 숫자와 그 숫자가 운영에서 뜻하는 것을 적습니다.