ex) DBMS의 flush 관련 설정을 건드렸더니 disk resource에 문제가 생긴 시나리오, 악의적인 shellcode로 인해 네트워크 쪽에 문제가 생긴 시나리오, 메모리 capacity를 줄였더니 특정 앱의 latency가 증가한 시나리오

등등 적당히 challenging 하고 1~2주 내에 검증해볼 정도의 시나리오면 좋을것 같은데 이런거 고려안하고 일단 최대한 많이 생각해주세요!

Assignees: 정동호, 이치윤

제가 요새 보안쪽 공부하고 있어서 그쪽 관련해서 시나리오 생각나는대로 바로바로올릴게요

리눅스 top 명령어를 이용한 실시간 cpu, 메모리 사용률 체크 리눅스를 사용하는 디바이스의 성능이나 리눅스 서버의 성능을 체크할 때 매우 유용하며 어떤 process가 cpu를 과다하게 잡고 있는지 분석 가능

scenario 1: short-lived process with top

아래와 같이 짧은 시간동안 cpu resource를 잡아먹고 꺼지는 short-lived process가 주기적으로 실행된다고 해보자.

systemd에 등록된 서비스가 잘못 설정되어 계속 재시도 되는 경우 서비스 외부에 문제가 있는 상황에서 계속 실패 후 retry하는 경우) 를 가정함

#!/bin/bash

trap 'kill $(cat /tmp/dd_pid); exit' INT

while :
do
    (dd if=/dev/urandom & echo $! >&3) 3>/tmp/dd_pid | bzip2 -9 >> /dev/null &
    sleep 0.9

    kill $(cat /tmp/dd_pid)
    sleep 2
done

interval-sampling 도구인 top(1)에서는 샘플링 주기에 따라 이런 프로세스들이 보이지 않을 수 있다.

아래 top(1)의 결과를 보면 un-niced user의 프로세스들이 전체 CPU 시간의 32%를 잡아먹고 있다고 나오지만 막상 프로세스 목록을 보면 CPU를 점유하고 있는 프로세스가 보이지 않는다.

top - 02:30:59 up 4 days, 15:29,  3 users,  load average: 0.55, 0.24, 0.09
Tasks: 106 total,   1 running, 105 sleeping,   0 stopped,   0 zombie
%Cpu(s): 32.0 us,  1.7 sy,  0.0 ni, 66.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :    978.6 total,    151.4 free,    245.1 used,    582.1 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.    568.7 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                
   5764 mongodb   20   0 1501184  75352  11832 S   0.3   7.5  20:47.32 mongod                                                                                                                 
      1 root      20   0  169072  10892   6296 S   0.0   1.1   0:18.71 systemd                                                                                                                
      2 root      20   0       0      0      0 S   0.0   0.0   0:00.00 kthreadd                                                                                                               
      3 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_gp                                                                                                                 
      4 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_par_gp                                                                                                             
      6 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/0:0H-

이를 위해 atop(1)을 사용해 볼 수도 있지만 atop(1)의 결과는 너무 장황해서 필요한 정보로 가공하는데 어려움이 있고 불필요한 정보들까지 같이 처리하여 비교적 오버헤드가 크다.

pidstat(1)도 atop(1)과 비슷한 목적으로 사용가능하지만 파싱하기 더 쉽게 출력된다.

처음부터 우리가 필요한 정보만 추출할 수 있으면 가공하기도 쉽고 오버헤드도 적을텐데 프로세스 생성을 모니터링하려면 어떻게 해야할까

위 그래프를 참고해 exec syscall을 모니터링 해보기로 했다.

exec는 execvp execv execvpe execle 등등 여러 family가 있는것처럼 보였는데 ausyscall(8)로 확인한 결과 현재 아키텍처에서는 execve만 존재하는걸로 보였다.

먼저 아래와 같이 어떤 exec에 대해 tracepoint가 있는지 확인했다. probe와 비교했을때 tracepoint가 인터페이스면에서 더 안정적이어서 tracepoint를 먼저 찾았다.

ubuntu@ip-172-31-46-92:~$ sudo bpftrace -lv 't:syscalls:*enter_exec*'
tracepoint:syscalls:sys_enter_execve
    int __syscall_nr;
    const char * filename;
    const char *const * argv;
    const char *const * envp;
...

보면 execve syscall이 호출될때(return될때는 exit_exec 사용) 호출되는 tracepoint:syscalls:sys_enter_execve 라는 tracepoint와 제공되는 파라미터들을 확인할 수 있었다.

그래서 아래와 같이 bpftrace로 작은 bpf 프로그램을 만들어 검증해볼 수 있었다. 이를 좀 더 고도화하면 bcc를 사용해 세부적인 정보들을 더 활용해 볼 수 있겠다.

ubuntu@ip-172-31-46-92:~$ sudo bpftrace -e 't:syscalls:sys_enter_execve { printf("[%d] ", pid); join(args->argv)}'
Attaching 1 probe...
[62130] sh gen-shortlived-jobs.sh
[62133] sleep 0.9
[62132] bzip2 -9
[62134] dd if=/dev/urandom
[62135] cat /tmp/dd_pid
[62136] sleep 2
[62139] sleep 0.9
[62138] bzip2 -9
[62140] dd if=/dev/urandom
[62141] cat /tmp/dd_pid
[62142] sleep 2
[62143] cat /tmp/dd_pid
...

distro마다 배포된 bcc 패키지가 다른데 ubuntu의 경우 bpfcc-tools라는 이름으로 배포되고 있다. 위의 기능을 python-bcc로 다시 짠 tool은 execsnoop-bpfcc 라는 이름으로 관리되고 있다.

cli에서 one-liner로 작성되는 대신 코드는 더 길지만 많은 작업을 할 수 있다.

ubuntu@ip-172-31-46-92:~$ sudo execsnoop-bpfcc -T
TIME     PCOMM            PID    PPID   RET ARGS
03:46:46 sh               62188  61635    0 /usr/bin/sh gen-shortlived-jobs.sh
03:46:46 sleep            62191  62188    0 /usr/bin/sleep 0.9
03:46:46 bzip2            62190  62188    0 /usr/bin/bzip2 -9
03:46:46 dd               62192  1        0 /usr/bin/dd if=/dev/urandom
03:46:47 cat              62193  62188    0 /usr/bin/cat /tmp/dd_pid
03:46:47 sleep            62194  62188    0 /usr/bin/sleep 2
03:46:49 sleep            62197  62188    0 /usr/bin/sleep 0.9
03:46:49 bzip2            62196  62188    0 /usr/bin/bzip2 -9
03:46:49 dd               62198  1        0 /usr/bin/dd if=/dev/urandom
03:46:50 cat              62199  62188    0 /usr/bin/cat /tmp/dd_pid

오픈소스므로 다른 정보가 더 필요하다면 직접 수정해도 되고 아니면 다른 도구들과 연계하여 더 깊게 분석해볼 수 있을것 같다.

여기서는 시나리오가 너무 단순해 pidstat과 ppid만 사용해도 될것 같았지만 이런식으로 bpf를 활용해볼수 있다는 것을 보여주고 싶었다.

scenario 2: httpd max clients

Apache HTTP Server라고도 불리는 httpd는 기본적으로 MaxClients 라는 파라미터가 256으로 튜닝되어있다. 모종의 이유로 해당 웹서버에 접속한 클라이언트가 MaxClients 값 이상이 되면 더이상 요청을 처리할 수 없는 것이다. 이렇게 queuing delay를 겪게되는 유저는 심각한 latency를 겪게 되고 서비스를 운용하는 관리자 입장에서는 빨리 해결하고 싶은 문제일 것이다.

이러한 문제가 발생하는 이유로는 DoS 공격이 가해졌거나 서버 자체의 설정이 잘못된 경우 또는 크리스마스나 블랙프라이데이처럼 특정한 이벤트로 인해 자연스레 유저들이 몰리게 되는 것들이 있을것이다.

매번 테스트시 마다 Apache HTTP Server 환경을 구축하는 것은 번거로우므로 이를 이미지로 만들고자 했다.

FROM httpd:2.4
COPY ./my-httpd.conf /usr/local/apache2/conf/httpd.conf
COPY ./32M /usr/local/apache2/htdocs/

httpd는 10억건 이상 pull될 정도로 많이 사용되는 이미지라 Docker Official Images로 관리되고 있다. 여기에 커스터마이징한 설정파일과 테스트용으로 사용할 리소스를 이미지에 같이 넣어준다.

커스텀한 설정으로는 아래와 같다:

<IfModule mpm_prefork_module>
    StartServers             1
    MinSpareServers          1
    MaxSpareServers          2
    MaxRequestWorkers        5
    MaxConnectionsPerChild   0
</IfModule>

기존에는 최대 250개의 요청을 처리할 수 있으나 과정을 단순화 하기 위해 임계치를 5개로 낮추었다. 이럼에도 불구하고 테스트 서버 -> 클라이언트 간 bandwidth가 약 84~93 Mbits/sec이라 32MB 사이즈의 리소스로도 의미 있는 emulating이 되지 않았고 더 큰 사이즈의 리소스를 요청하기보다는 트래픽 비용을 줄이면서 테스트를 할 방법이 필요했다.

iproute2 패키지에서 같이 제공되는 tc(8)은 리눅스 커널 패킷 스케줄러를 설정할 수 있게 해준다. 그래서 테스트 시에 sudo tc qdisc add dev eth0 root tbf rate 1mbit burst 32kbit latency 400ms 를 설정해 초당 1Mbit 정도의 속도로만 트래픽이 전송될 수 있도록 했다.

2번째 시나리오를 emulating하기 위한 스크립트는 아래처럼 작성된 run.sh이다:

#!/bin/bash -x

if [ "$EUID" -ne 0 ]
  then echo "Please run as root"
  exit
fi

# safety logic
trap 'tc qdisc del dev eth0 root; rm 32M; exit' INT

pushd test-httpd

# for generating high load
sh gen_dummy_data.sh 32M
docker build -t 2-httpd_max_clients .

# tc for emulating tcp congestion
tc qdisc add dev eth0 root tbf rate 1mbit burst 32kbit latency 400ms
docker run -it --rm --name 2-httpd_max_clients -p 5001:80 2-httpd_max_clients
tc qdisc del dev eth0 root
rm ./32M

tc(8)를 사용하기 위해 sudo 권한이 필요하다. 실행 시키면 동적으로 이미지가 빌드되고 컨테이너로 띄어지면서 아래와 같이 httpd daemon의 로그 화면이 보일것이다.

이제 클라이언트에서 서버로 요청을 날려볼 수 있다. 초당 트래픽을 1Mbit으로 제한을 걸어둔 상태이므로 32MB 크기의 리소스를 요청하면 MaxClients에 도달하기까지 충분한 시간을 확보할 수 있을것이다.

클라이언트에서 5건의 request를 동시에 보내자 서버에서 MaxRequestWorkers(MaxClients)에 도달했다고 경고하는 것을 볼 수 있다.

여기서 ss(8), lsof(8), netstat(8) 같은 명령어로 상황을 파악하려고 하면 잘 되지 않는다. 호스트 환경과 격리된 컨테이너의 네트워크 문제인것 같은데 이부분은 더 리서치가 필요해 다음 시나리오에서 다뤄야 할 것 같다.

iftop(8)에 -P 옵션을 줘서 보면 src ip와 port까진 나오는데 어떤 pid가 해당 요청을 처리하고 있는지까진 나오지 않는다. 여기서 bpf를 다음과 같이 활용해볼 수 있었다.

tcptop(8)는 커널의 tcp_sendmsg와 tcp_recvmsg에 kprobe를 붙여 작동한다. 하지만 이전 sys_enter_execve tracepoint와는 달리 이번에는 아래처럼 처리해야할 로직이 길기 때문에 bpftrace 대신 하위레벨의 bcc로 작성되었다.

...
int kprobe__tcp_sendmsg(struct pt_regs *ctx, struct sock *sk,
    struct msghdr *msg, size_t size)
{
    u32 pid = bpf_get_current_pid_tgid() >> 32;
    ...
    if (family == AF_INET) {
        struct ipv4_key_t ipv4_key = {.pid = pid};
        ipv4_key.saddr = sk->__sk_common.skc_rcv_saddr;
        ipv4_key.daddr = sk->__sk_common.skc_daddr;
        ipv4_key.lport = sk->__sk_common.skc_num;
        dport = sk->__sk_common.skc_dport;
        ipv4_key.dport = ntohs(dport);
        ipv4_send_bytes.increment(ipv4_key, size);

    } else if (family == AF_INET6) {
    ...

tcptop(8)의 결과를 보면 10초동안 80번 http 포트에서 xxx.xx.138.101 클라이언트 호스트로 5건의 tcp_sendmsg가 전송되었다는 사실과 누가(pid, comm) 요청을 처리하고 있었는지와 rx/tx 사이즈도 확인할 수 있었다.

이번에는 요청을 받을 수 있는 최대 5개를 넘어 6건의 요청을 날려봤다.

보면 뒤에온 요청은 아예 처리도 되지 않고 있다는것과 동시에 들어온 요청도 클라이언트마다 큰 차이가 있다는 것이다. 후자의 경우는 실험 환경이 열악해 부득이 호스트 한대에서 포트만 바꿔 여러곳에서 동시 접속하는것을 모방해서 그럴 수 있다고 쳐도 MaxClients 이후의 queuing delay를 겪는 유저의 경우 아예 아무런 응답조차 받고 있지 못하는 것은 큰 문제가 아닐 수 없다. 포트별로 전송속도에 차이가 있는거에 대해서도 실험을 해보고 싶었으나 테스트에 활용된 호스트가 Windows 호스트 안에 Linux VM으로 돌고 있어 이를 추적하기 어려웠다. vmware에서 가상 네트워크 관련 포트 포워딩 설정은 유료버전에서만 지원되기 때문이다.

이번 시나리오에서는 동시에 큰 자원을 여러번 요청해 서비스가 더이상 제대로 운용될 수 없도록 했기 때문에 모의 DoS 공격을 했다고 볼 수 있다. 이런경우 위에서 활용한 tcptop(8)으로 현재 어떤 ip에서 정상적이지 않은 요청을 하고 있는지 확인해보거나

아래와 같이 tcpstates(8)을 활용해 downtime 없이 임계치를 벗어나면 바로 차단해버릴수도 있을것이다.

tcptop(8)과 tcpstates(8) 모두 tracing의 범주의 들어간다. 각각 TCP send/receive event와 TCP set state event를 tracing 하므로 이 tool에 대한 오버헤드는 단위시간당 얼마나 많은 tcp_sendmsg/tcp_recvmsg가 호출되는지, 얼마나 많은 TCP 세션이 생성되는지에 따라 결정된다. 전자는 나중에 살펴볼 다른 bpf tool인 funccount로 직접 해당 커널 함수 호출을 카운팅해보거나 후자는 sar(8)로 sar -n DEV 1과 같이 측정해 볼 수 있을것이다.

미리 벤치마킹된 자료에 의하면 tcptop의 경우 초당 4k ~ 15k건의 이벤트가 발생하는 경우 0.5~2% CPU 오버헤드가 발생했고 1k 미만이라면 무시할만한 수준이라고 한다. tcpstates는 tracing으로 인한 오버헤드보다 결과를 출력하는데 걸리는 시간이 더 커서 고려하지 않아도 될것 같다.

### Checking connection performance using ss command ss 명령을 사용하여 연결 성능 확인가능하다. sockt 명령으로 netstat 보다 빠르고 더 많은 정보를 제공한다.

ss | less 위 명령어를 통해 udp, tcp, UNIX socket의 연결을 확인할 수 있다.

-ta (tcp), -ua (udp) socket 연결을 확인할 수 있다.

IPv4 프로토콜에서 tcp 연결이 설정된 것을 확인할 수 있다. ss -t4 state established

닫힌 tcp 연결 확인 ss -t4 state closed

특정 ip 주소와 port를 설정하여 연결확인 가능 ss dst XXX.XXX.XXX.XXX:22

scenario 3: read performance with page cache

원래 read performance with wiredTiger cache size여서 제목과 맞지않는 내용으로 시작된다. 처음에 MongoDB에서 데이터를 조회할때 디스크 아니면 MongoDB storage engine인 wiredTiger의 캐시만 활용하는줄 알았는데 실험이 진행될수록 캐시는 중간 중간 여러 단계에 있음을 알게되었다.

그래서 이번 시나리오에서는 그림의 Page cache와 읽기 성능에 대해 알아본다. 초반 내용은 page cache가 아닌 wiredTiger cache를 병목으로 가정하고 진행한 내용이지만 내용이 얼마 되지 않아 그냥 처음부터 읽어도 괜찮을것 같다. 아니면 8. Summary만 읽어도 좋을것 같다.

NoSQL DBMS로 유명한 MongoDB는 2014년 버전 3.2부터 WiredTiger라는 storage engine을 사용중이다. WiredTiger는 filesystem cache외에 내부적으로 cache를 하나 더 갖는데, 50% of (RAM - 1 GB) 또는 256 MB에서 큰 값을 고르게 된다.

이번 시나리오에서는 MongoDB를 운용하는 서버에서 다른 작업으로 인해 메모리가 부족해지고 덩달아 WiredTiger의 cache size도 줄어들면서 response time이 늘어난 문제를 다룬다 라고 하려 했으나 실험결과 WiredTiger의 cache size는 변함이 없어서 (4) performance degradation 확인 절부터는 주제를 Page cache로 변경하였다.

먼저 모의 테스트는 아래와 같이 진행했다:

1. Dockerfile 작성

FROM mongo:4.4.3

WORKDIR tmp

RUN apt update && apt install -y wget

RUN wget https://github.com/feliixx/mgodatagen/releases/download/v0.8.4/mgodatagen_linux_x86_64.tar.gz -O- | tar -xz

COPY ./dummy-data.json ./
COPY ./entrypoint.sh ./
RUN chmod +x ./entrypoint.sh

CMD ["/tmp/entrypoint.sh"]

base image는 공식 이미지 mongo:4.4.3을 활용했고 더미데이터 생성은 mgodatagen을 활용했다.

2. entrypoint.sh

mongod daemon을 fork하고 더미데이터 생성을 하는 역할만 하기 때문에 스크립트 내용은 생략한다.

3. run.sh

#!/bin/bash

pushd test-app

docker build -t 3-wt_cache_size .

docker run -it --rm -p 5001:27017 --name 3-wt_cache_size 3-wt_cache_size

위와 같이 생긴 run.sh을 통해 3-wt_cache_size라는 이미지를 빌드하고 컨테이너로 띄운다.

4. performance degradation 확인

실제로 메모리가 부족해지면 wiredTiger의 읽기 성능이 어떻게 변하는지 확인해보자. 현재 t2.micro instance는 1G의 메모리만 할당되어 있어서 최대 cache size는 256MB가 된다.

이 상태에선 cache size가 이미 256 MB 보다 작아서 호스트의 가용 메모리가 0에 가까워져도 변화가 없을것이다.

wiredTiger는 설정된 cache size의 80%를 유지한다고 한다. 현재 cache size와 더미데이터가 메모리에 올라왔을때를 확인해보면 201MB(256 * 80%), 357MB임을 확인할 수 있었다.

하지만 정말 호스트의 가용 메모리 크기가 성능에 영향을 미치지 않는지 확인하고 싶었다.

그래서 다음 스크립트들을 작성했다.

/tmp 아래 tmpfs 파일시스템을 마운트하고 호스트의 available memory가 100Mi 아래로 내려갈때까지 dd로 메모리를 잡아먹는 스크립트
(1)에서 생성된 파일을 지워 호스트의 메모리 사용량을 정상으로 복구하는 스크립트
더미데이터에 랜덤한 쿼리(캐시 도움이 없으면 I/O 비용이 많이 나갈만한)를 날리는 스크립트
(3)을 일정횟수만큼 반복하여 날리는동안 wiredTiger를 모니터링하는 스크립트

(1), (2)는 쉘 스크립트 / (3), (4)는 파이썬 스크립트로 작성되었으며 전체 내용은 3-wiredTiger_cache_size 경로 아래 코드들을 참고

반복해서 실험한 결과 해당 쿼리를 수행하는 평균 시간도 메모리가 줄어든 크기(1/2)에 반비례해 2배로 늘어났고 cache hit count도 절반가까이 떨어진것을 볼 수 있었다. 하지만 통계에서 잡히는'bytes currently in the cache'는 항상 256MB의 80%인 200MB였다. cache size는 변하지 않는데 왜 cache hit count는 절반으로 떨어진걸까 궁금했다. 하지만 너무 특정 application의 작동 방식에 대해 의존하고 싶지 않아 이 부분은 다음 실험으로 미루기로 했다.

방향을 바꿔 CPU의 Utilization으로 비교해보았다.

가용 메모리가 줄어들자 io에 병목이 생기는걸 볼 수 있었다. sar(1)에서 %iowait은 다음과 같은 의미를 갖고있다:

          %iowait
                Percentage of time that the CPU or CPUs were idle during which the system had an outstanding disk I/O request.

확실하게 퍼포먼스에 문제가 생겼음을 확인했고 io가 병목이란것도 알았다.

5. USE Method

(4)의 과정은 우리가 이슈의 원인을 알고 있는 경우를 가정하고 진행되었다. 이를 SantaBPF에서 어떻게 적용해볼 수 있을까? 먼저 모니터링 작업이 가장 먼저 수반될것이다. 이 단계는 어떤 tool을 써도 상관 없지만 sar(1)가 가장 범용적일것 같아 sar(1)를 가정하고 진행하겠다.

가장먼저 USE Method를 사용해볼 수 있을것이다.

CPU, Memory capacity, Network interface, Storage Device I/O 등등의 resource들에 대해 utilization, saturation, errors에 대한 metric을 모니터링한다. 이번 시나리오의 경우에는 CPU utilization, Memory capacity saturation, Storage Device I/O Utilization에 대한 metric이 변하게될것이다. 어떤 값이 baseline이고 어디까지가 threshold가 될지는 시스템마다 다를텐데 이 부분도 다음 리서치로 일단 넘기기로 했다. 일단 여기서는 지난 이력을 baseline으로 삼았다고 해보자.

여기서 지난 이력은 단순히 최근 5분 1시간 하루가 아니라 주기성을 고려하도록 한다. 이러한 주기성으로는 하루, 일주일, 1달, 1년등이 있다. 주기를 하루로 보면 업무시간인 9~18시에 부하가 몰릴것이고 일주일로 보면 주중인 월~금에 부하가 몰릴것이다.

지난 이력과 비교해 CPU utilization은 내려가고 Memory capacity saturation은 올라가고 Storage Device I/O Utilization이 올라가는 상황에서, 무엇을 의심해볼 수 있을까? 이미 앞에서 답을 알고 있는 상황이기에 "가용메모리 크기가 줄어들어 cache size가 줄어들고 cache miss가 늘어나 데이터를 처리하는 시간보다 디스크에서 읽고쓰는 시간이 늘어나는 경우"를 생각해볼 수 있다. 하지만 이런 결론은 아직 아는게 여기까지라 이것밖에 생각나지 않아서 내린 결론일 가능성이 아주 크다 생각한다. 그래서 USE Method 다음으로 어떻게 접근할 수 있을지 고민했다.

6. tracing with cachestat(8)

bcc에서는 어떻게 cache에 대한 퍼포먼스를 측정하고 있는지 보니 cachestat(8)이라는 tool을 이미 만들어둔것을 확인했다. 모든 bcc tool들은 open source라 내부구현을 확인할 수 있었는데 add_to_page_cache_lru mark_page_accessed account_page_dirtied mark_buffer_dirty 4개 kernel function에 대해 의존하고 있었다. tracepoint가 아닌 kprobe인 만큼 커널과 distro 버전에 민감할 것이다.

테스트로 돌려본 결과는 아래와 같았다.

확실히 hit ratio가 바닥을 기는것을 볼 수 있었다. 하지만 이 통계가 어떻게 집계되는지 모르고 쓴다면 결과를 잘못 해석할수도 있다. 먼저 hit ratio는 hit count / (hit count + miss count)로 계산된다. 이 count들은 어떻게 구해진걸까? cachestat(8)의 내부구현을 보면

total = mark_page_accessed - mark_buffer_dirty
misses = add_to_page_cache_lru - account_page_dirtied
hits = total - misses

로 되어있다.

이 커널 함수들이 무슨 의미인지 더 알아보려 했지만 그러지 못했다. 좀 더 공부해서 지식이 쌓이면 이해할 수 있을지도 모르겠다. 대신 동일한 방법으로 구현된 다른 버전의 cachestat(8) 문서를 찾아봤다. 위 버전은 bcc를 활용했고 ftrace를 활용한 cachestat도 있는데 ftrace 버전의 주석을 보면

# This is a proof of concept using Linux ftrace capabilities on older kernels, # and works by using function profiling for in-kernel counters. Specifically, # four kernel functions are traced: # # mark_page_accessed() for measuring cache accesses # mark_buffer_dirty() for measuring cache writes # add_to_page_cache_lru() for measuring page additions # account_page_dirtied() for measuring page dirties

라고 한다. 하지만 이건 linux 3.13에서 kprobe에 의존해 작성된 로직이니 다른 방법을 생각해보는것도 하나의 주제가 될 수 있겠다.

즉 cache access가 일어날때마다 mark_page_accessed() 함수 호출을 counting하고 그 중에 cache writes가 일어날때마다 counting된 mark_buffer_dirty() 함수 호출은 빼서 총 total(cache accesses)을 구한 뒤

add_to_page_cache_lru() 에서 account_page_dirtied()를 빼 misses를 구한다는데 이 부분을 잘 모르겠다. 코드에 주석도 없고 구글링 해도 잘 나오질 않아서 필요하다면 나중에 시간을 더 들여 봐야할것 같다.

hits를 구하는 건 위의 로직보다는 간단하다. 그냥 total에서 miss를 빼면되기 때문이다.

7. Pinpointing

CPU utilization은 내려가고 Memory capacity saturation은 올라가고 Storage Device I/O Utilization이 올라가는 상황

_mark_page_accessed, mark_buffer_dirty, add_to_page_cache_lru, account_pagedirtied kprobe로 보니 cache hit ratio가 바닥을 기는 상황

아래 kprobe를 쓰는 방법이 오버헤드가 더 크니 처음 모니터링은 위의 resource별 USE에 대해서만 수행하고 의심되는 anomaly가 발생한 경우에만 아래와 같은 profiling & tracing 를 수행한다.

아래까지 왔으면 현재 시스템이 캐시 문제로 I/O에 병목이 생겼음을 알 수 있다.

원래는 왜 캐시에 문제가 생겼는지 더 알아보자. 라고 하고 프로세스별로 page cache 점유율을 보려고 했는데 방법을 찾지 못했다. 직접 실험이라도 해보려고 sync; echo 3 | sudo tee > drop_caches도 해봤지만 어째선지 cache가 0으로 가지 않았다. 무언가 하한이 있는건가 싶은데 이부분은 아무리 리서치를 하고 질문을 올려도 답을 받지 못했다.

대신 fincore(1)를 찾았다. fincore(1)은 util-linux package에 포함되어 있는 명령어로, 어떤 파일이 메모리에 얼마나(몇 페이지에) 올라가 있는지 확인할 수 있다.

그리고 vfs의 __vfs_read()를 dynamic tracing 하여 어떤 파일이 현재 어떤 프로세스에게 얼마나 읽히고 있는지 확인해보는데 이 역시 bcc에서 filetop(8) 이라는 이름으로 구현되어 있다.

처음부터 page cache에 어떤 내용들이 올라가 있는지 알 수 있으면 이렇게 안하겠지만, 지금으로선 다음과 같이 접근해볼 수 있곘다.

현재 어떤 파일의 I/O가 가장 심한지 확인한다. (현재 이슈가 I/O에 있음을 위에서 확인했으므로)

그 파일이 메모리에 얼마나 올라가 있는지 확인한다.

(검증목적으로) 가용메모리가 줄어들었을때의 결과도 확인한다.

8. Summary

CPU Utilization 🡻 / Memory capacity saturation 🡹 / Storage Device I/O Utilization 🡹 인 상황이 인식됨
MongoDB의 response time도 2배 이상 느려진 상황
캐시 문제인지 확인하기 위해 cachestat(8)로 hit ratio 확인
hit ratio가 현저히 낮다면 filetop(8)으로 현재 어떤 파일이 I/O 작업에 있는지 확인
fincore(1)로 해당 파일 크기 대비 얼마나 메모리에 적재되어 있는지 확인
어떻게 하면 해당 파일을 디스크에서 읽지 않고 page cache에서 가지고 오게 할 수 있을지 솔루션 제시

NOTE 1

Since tmpfs lives completely in the page cache and on swap, all tmpfs pages will be shown as "Shmem" in /proc/meminfo and "Shared" in free(1). Notice that these counters also include shared memory (shmem, see ipcs(1)). The most reliable way to get the count is using df(1) and du(1).

TODO 1

flamegraph missing symbol issue

가용 메모리가 0에 가까워지는 경우 mongoDB의 성능이 급격히 나빠지는 구간의 code path 찾기. 이를 위해서 debugging symbol이 있는 버전으로 새로 빌드해야 하는데 현재 구축한 환경으로는 공간이 부족해서 (13GB<) 다음 실험으로 보류

TODO 2

mount -t tmpfs none -o size=1G /tmp/foo로 메모리에 임시 파일 시스템을 만들고 dd if=/dev/urandom of=/tmp/foo/1 oflag=append conv=notrunc bs=50M count=1; free -h로 남아있는 available memory size를 확인하면서 메모리를 잡아먹으면서 실험해보기. 너무 여유를 안주면 oom reaper가 mongod를 죽여버리는 문제가 있어 20Mi 정도는 남겨주어야 함. cold cache문제도 고려해 실험 결과는 5번 중 3번 이후만 집계함. 하지만 현재 더미 데이터 크기가 이미 250MB 아래고 또 최대 캐시 사이즈도 이미 250MB 아래라 이런식으로는 실험이 진행되지 않음. 따라서 이것도 다음 실험으로 보류함

TODO 3

특정 프로세스의 page cache size 구하기

TODO 4

filetop에서 vfs_read 말고 다른 tracing할 I/O 함수가 있는지 확인

TODO 5

drop_caches 이슈

SantaBPF / santabpf

1. 시나리오 작성 #3