[기술컬럼] Linux 게임 서버 성능 분석에 eBPF + BCC 활용하기

이 글에서는 흔히 사용하는 툴 체인 기반 성능 분석 방법의 문제를 설명하고, 이 대안으로 linux 의 eBPF + BCC 툴킷을 설명합니다.

툴 체인 기반 성능 분석 방법

다양한 툴체인을 이용해서 게임 서버의 성능을 분석해볼 수 있습니다.

  • 성능 측정 코드를 자동으로 삽입
  • 성능 측정 코드가 포함된 라이브러리를 링크하고, 이를 호출하는 코드 추가

하는 방식으로 동작합니다.

많은 툴체인은 개략적으로 아래와 같은 방법으로 동작합니다.

  1. 빌드 할 때 컴파일러 수준에서 성능 측정 코드를 삽입. 혹은 성능 측정 라이브러리를 링크.
  2. 실행 중 필요한 모든 순간, 혹은 그 중 일부를 샘플링해서 통계 데이터 생성
  3. (프로그램 종료 혹은 측정 종료 후) 통계 데이터 생성 마무리
  4. 시각화 툴에 맞게 추가 처리 혹은 변환

툴 체인 동작 예시

CPU 성능을 분석한다면 GCC의 -pg 플래그를 이용해서 성능 측정 코드를 빌드 시점에 추가합니다. 프로그램을 실행한 후에는 파일 형태로 성능 데이터를 쌓고, 이 데이터를 GProf 툴을 이용해서 분석합니다. 이 작업을 하면 아래처럼 특정 함수가 얼마나 시간을 쓰는지 확인할 수 있습니다.

% cumulative self self total
time seconds seconds calls ms/call ms/call name
14.29 0.03 0.03 207323 0.00 0.00 crow::json::escape
14.29 0.06 0.03 3059 0.01 0.02 crow::CrowApp::handle
9.52 0.08 0.02 2638 0.01 0.02 crow::json::dump_internal
4.76 0.09 0.01 307190 0.00 0.00 _Hashtable::insert_unique
4.76 0.10 0.01 208356 0.00 0.00 _Hashtable::_M_rehash
4.76 0.11 0.01 19129 0.00 0.00
                             vector::_M_emplace_back_aux
4.76 0.12 0.01 11961 0.00 0.00
    crow::Connection::cancel_deadline_timer

CPU 성능 분석 할 때는 오래 걸리는 함수를 찾게 되는데, 이 때 이 함수가 어떤 경로로 호출되는지 파악하기 위해서 콜 스택 정보가 꼭 필요합니다. 이 정보는 GProf 의 콜 그래프를 출력하면 이미지 파일로 확인할 수 있습니다.

gprof-cropped

첨언

툴 체인 기반으로 성능 평가를 하면 개발자가 코드를 관리하지 않아도 되어서 잠재적인 버그 위혐은 높지 않습니다. 다만 빌드 시점 혹은 실행 시점 직전에는 코드를 삽입하거나 추가 라이브러리를 로드해야해서, 이미 실행 중인 프로세스/서비스의 성능을 분석하기는 어렵습니다.

또한 성능 측정 할 때 어딘가에는 데이터를 쌓아야하기 때문에 성능 오버헤드도 큰 편입니다.

  • gprof: 30% – 300% 정도 속도 저하
  • valgrind: 바이너리 코드를 성능 평가/버그 분석용의 VM으로 실행. 400% – 4,000% 정도의 성능 저하

그리고 성능 측정 코드가 삽입되는 방식에 따라서 동적으로 로드하는 외부 라이브러리 (.dll, .so) 에 대한 측정이 안되는 경우가 많습니다. 비슷한 이유로, OS 내부에서 성능 문제가 생기는 경우에도 이를 파악하기는 어렵습니다.

마지막으로, 툴 체인이 직접 지원하지 않는 세부적인 필터링이 필요하다면 이를 적용하는 것은 굉장히 곤란한 일이 됩니다. 즉, 측정 대상을 한정하고 싶은 경우 — 예를 들어 디스크 I/O를 하는데 10ms 이상 걸린 순간의 콜 스택이 필요하다면 — 측정 시점에는 어렵고, 측정한 후에 사후 필터링하는 방법 정도 밖엔 없습니다.

성능 분석 툴에 원하는 것

툴 체인의 경우 이미 공개된 유/무료 툴을 활용하는 것이기에, 툴을 직접 고치기도 불가능하거나 쉽지 않습니다 — 대부분 코드 베이스가 커서 쉽지 않습니다.
그래서 편하게 성능을 분석하고 싶다면 좀 더 유연한 도구가 필요합니다.

  • 우선 앞서 말한 것처럼, 측정 대상을 쉽게 필터링할 수 있어야 합니다. 대량의 데이터가 쌓이는 경우 그 자체가 성능 문제가 될 수 있고,데이터가 적을 수록 분석은 용이합니다.
  • 성능 데이터는 어떤 취합값 (평균, 최소/최대값, 분산 같은 aggregation 값) 대신 분포를 파악할 수 있는 쪽이 더 바람직합니다.
  • 분석 도구는 성능 분석 대상과 분리되어 독립적으로 동작해야 합니다. 즉, 분석 도구를 수정하거나 옵션을 바꾼다고 분석 대상을 다시 빌드하거나 재실행해야 한다면 쉽게 적용하기 어렵습니다.
  • 분석 도구의 버그로 분석 대상이 크래시해서는 안됩니다. 성능 분석을 하는데 분석 과정에서 분석 대상을 크래시하거나 오동작하게 할 수 있다면, 이런 도구는 실 서비스에선 쓸 수가 없습니다.
  • 적절한 시각화 방법을 제공해야 합니다. 위의 gprof 출력처럼 해석하기 어려운 것보다, 좀 더 쉽게 파악할 수 있는 쪽이 좋습니다.

대안: eBPF + BCC

Linux 커널 v3.18 부터 eBPF란 기능이 생겼습니다. (유의미하게 쓸 수 있는 것은 v4.9 이후)
이를 고수준 언어에서 활용하게해주는 BCC 툴킷이 있습니다.

eBPF: extended Berkeley Packet Filter

eBPF 는 x86-64 와 arm64 의 공통점을 따온 것처럼 보이는 별도의 어셈블리 언어입니다.
실제로 이런 코드를 사람이 직접 작성하지는 않고, 성능 측정을 위한 C 언어 코드를 작성하면 이를 eBPF 프로그램으로 트랜스파일합니다. (BCC 툴체인의 기능)

이 eBPF 프로그램을 bpf() 시스템 콜을 통해서 linux 커널에 전달하면, 해당 내용을 커널 안의 샌드박스 형태의 인터프리터 — JVM 처럼 다른 프로그램을 실행시켜주는 VM — 로 동작합니다. 다만 커널에서 돌릴 것이라 몇 가지 검증을 합니다. (동작 중에 크래시할만한 코드가 있는지 확인합니다.)

  • 아무 함수나 부를 수 있는 것은 아닙니다.
  • 스택이나 메모리 접근 방식도 제한됩니다. (직접 선언한 값이나, 스택으로 넘어온 값에서 참조하는 일부 값만 접근)
  • 데이터는 미리 선언한 일종의 해시맵에만 저장할 수 있습니다.

이 프로그램은 몇 가지 데이터를 수집할 수 있습니다.

  • 시스템 콜, 혹은 커널 내에서의 함수 호출
  • 유저 영역 (유저 프로그램) 내의 함수 호출
  • 프로그램에서 정의한 트레이싱 지점 (python 이나 JVM, node.js 같은 고수준 언어/프레임워크에서 주로 제공합니다)

이를 미리 선언한 해시맵에 저장하는 방식으로 데이터를 수집할 수 있습니다.

유저 영역에서는 이미 동작 중인 eBPF 프로그램과 통신해서 동작을 수정하거나 — 예를 들어 측정 대상을 추가 — 현재까지 수집된 데이터를 가져가거나 할 수 있습니다. (이 역시 bpf() 시스템 콜을 통해서 이뤄집니다)

BCC: eBPF Compiler Collection

eBPF는 성능 측정을 위한 훌륭한 기능을 제공합니다. 하지만 이를 위해서는 C언어를 이용해서 프로그램을 짜고, 데이터를 주고 받아야 합니다. 이런 번잡함을 줄이기 위해서 BCC를 이용합니다. BCC를 사용하면 아래와 같은 방법으로 성능 분석을 할 수 있습니다.

  1. C 코드로 성능 데이터 수집하는 코드 작성
  2. Python이나 go 혹은 lua 로 1에서 작성한 데이터를 eBPF 프로그램으로 생성. 만약 필터링이 필요한 경우 — 특정 프로세스나 스레드로 제한하는 등 — 1의 프로그램을 전송하기 전에 수정합니다.
  3. BCC 컴파일 (1의 C코드를 eBPF 프로그램으로 변환) 후 커널에 로드
  4. eBPF 프로그램을 추가로 데이터 측정할 곳에 연결합니다.

이 과정을 마친 후에는 커널에 있는 eBPF 프로그램과 유저 영역에 있는 프로그램이 통신할 수 있습니다.
주기적으로 현재까지의 데이터를 가져와서 통계를 보여주거나, 아니면 추가로 특정 데이터를 더 수집하거나 하는 일을 할 수 있습니다.

왜 유용한가?

eBPF 는 일정한 제약이 가해지기 때문에, 성능 측정 대상을 크래시하게 만들기 어렵습니다 — 측정하는 데이터에 따라선 측정하는 동안 성능이 떨어질 순 있습니다.
또한 이 측정은 측정 대상에 해당하는 프로그램 수정이나 재시작이 필요하지 않기 때문에 실 서비스에서도 적용할 수 있고, 측정 부하도 매우 낮습니다 — 모든 측정은 커널 안에서 이뤄집니다.
그리고 이 모든 과정이 측정 대상 외부에서 이뤄져서, 필요한 만큼 측정 방법을 바꾸고, 수집할 데이터를 달리하면서 성능 문제를 추적할 수 있습니다.

즉, 아래와 같은 과정을 빠르게 반복할 수 있습니다:

  1. 성능 문제에 대한 가설을 세웁니다: “ㅁㅁ” 가 문제인 것 같다.
  2. 이 “ㅁㅁ” 에 해당하는 측정 데이터를 찾고 eBPF + BCC 프로그램으로 만듭니다 — 대부분의 경우 BCC에 포함된 스크립트로 존재합니다.
  3. 측정하고, 가설이 맞았는지 확인합니다. 틀렸다면 다시 범위를 좁히거나 다른 영역으로 넘어가서 1로.

예제 프로그램 분석해보기

간단한 C++기반 HTTP API 서버: flaskr

위 프로그램에서는 다음과 같은 일을 하는 하나의 API를 제공합니다.

  • HTTP 요청을 받습니다.
  • 데이터베이스에서 모든 항목을 얻어옵니다.
  • 해당 항목을 JSON 배열로 직렬화합니다.
  • 해당 배열을 문자열로 변환해서 HTTP 응답으로 반환합니다.
  • 그리고 누가 보낸 요청인지 로그로 남깁니다. (요청한 호스트 주소와 URL)

해당하는 코드는 다음과 같습니다.

flaskr-cpp

경험에 의존해서 판단하면, 이 정도의 처리는 4 core 기준으로 초당 1000건 정도는 할 수 있을 것 같습니다.
정말 그런지 위 코드를 siege 부하 테스트 툴로 성능 측정해봤습니다.
(32개 연결 / 연결당 16k 요청 / 응답 받을 때마다 다음 요청 전송)

siege -c 32
      -r 16384
      -b http://example.com

첫 테스트 결과는 다음과 같습니다. (서버는 4 core)

  • 초당 110요청 처리; 코어 당 27.5 요청/초 처리.
  • 요청 당 처리 시간: 36 ms

이제 왜 이렇게 느린지 — 혹은 느리지 않은지? — 확인해보도록 하겠습니다.

가설 #1: 어디선가 CPU를 많이 쓴다.

CPU를 많이 쓰는 코드는 어떻게 찾을까요? BCC에 있는 profile 스크립트를 활용해보도록 하겠습니다.
해당 eBPF + BCC 프로그램을 다음과 같이 동작합니다:

  • 주기적으로 스레드를 멈춥니다 (초당 50-200번 정도)
  • 멈춘 시점의 콜 스택을 기록합니다
  • 해당 빈도 정보를 모아서 시각화합니다.

sudo profile -p $(pgrep -nx flaskr) -f -F 199 30

위 명령으로 30초간, 매 초 199번 콜 스택 정보를 모았습니다.
이 데이터를 flamegraph로 시각화하면 아래와 같습니다.

blog-profile1-cropped

이 그래프에서 수직 방향은 콜 스택을, 수평 방향은 실행 시간을 의미합니다. 즉, 여기서 수평 방향을 긴 항목(=실행 시간이 긴)에 대해서 콜 스택을 분석해서 오래 걸리는 부분이 어딘지 파악합니다.

분석해보면 다음과 같은 함수가 오래 걸렸습니다.

  • __GI_nss_files_servent: DNS 설정을 쓰는 C 함수 (10%)
  • 여러 시스템 콜 (OS 내부)
  • TCP 전송 (6.3%)
  • 소켓 닫기 (3%)
  • 파일 읽기 (2%)

앞서 보여드린 API 핸들러의 코드가 없습니다!

그래서 정말로 CPU 가 문제인지를 Windows 작업 관리자나 macOS Activity Monitor 와 유사한 툴인 htop 으로 확인해봤습니다.

profile-htop

CPU 사용량이 코어 한 개 분량도 안되는 42%입니다. 즉, CPU 문제는 아닌 것 같습니다.

어딘가 대기하는 코드가 있다.

CPU가 남아도는데 느리다면, 무언가를 기다리고 있는 코드가 있다는 얘기입니다.

가설 #2: 데이터베이스가 충분히 빠른가?

HTTP API 서비스를 만들어보면, 데이터베이스가 병목인 경우가 흔합니다.
별도 서버에 있는 MariaDB를 쓰고 있으니 다음과 같은 부분이 느릴 수 있습니다.

  • DB 서버에 접속하는데 걸리는 시간
  • SQL 쿼리를 실행하는 시간
  • SQL 쿼리 결과를 가져오는데 걸리는 시간

그래서 이런 처리가 느린 부분이 있는지를 MariaDB 드라이버의 해당 함수들에 대해서 확인해봤습니다.
이 작업은 다음과 같은 BCC 스크립트를 활용했습니다.
아래 명령을 써서 libmariadb.so 라이브러리에 있는 mysql_ 로 시작하는 모든 함수의 실행 시간 분포 통계를 측정합니다.

sudo funclatency -p $(pgrep -nx flaskr) -F \
/usr/lib/mariadb/libmariadb.so:mysql_*

측정한 결과 실행 시간이 긴 두 개를 뽑았습니다.

blog_mysql_real_query
blog_mysql_fetch_fields

두 함수 모두 실행 시간이 길지 않습니다. mysql_real_query가 긴편이지만 이것도 겨우 2ms 정도 걸립니다.
요청당 쿼리는 한 번씩 보내니, 한 요청 처리하는데 걸리는 36ms 시간에 배하면 데이터베이스 처리는 큰 영향을 주지 않습니다.

가설 #3: 다른 대기 코드가 있다

Linux 에서 스레드가 대기상태에 진입하면 다음과 같은 일이 일어납니다.

  1. 스레드가 대기 상태에 진입할 수 있는 함수 호출 (sleep, I/O, lock 획득, …)
  2. OS에 진입 후 할당받은 CPU를 다른 스레드에게 재할당

이 때 2에 해당하는 시각을 기록하고, 다시 CPU를 할당받은 시각을 측정해서 시간 차이를 구하면, 얼마나 오래 기다리고 있는지 파악할 수 있습니다.
이런 작업을 처리해주는 BCC 스크립트인 offcputime 을 써서 이를 측정해봤습니다.

blog-offcpu-cropped

여기서는 수평 방향 길이가 대기 시간 중 차지하는 비율이고, 수직 방향은 콜 스택입니다.
가장 넓은 부분(78%)이 poll() 함수에 해당하는 부분입니다. 헌데, 이 poll() 을 부르는 코드가 없습니다.

그러면 반대 방향으로 생각해봅시다. 대기하던 스레드가 깨어나려면, 대기 조건에 해당하는걸 다른 곳에서 해결해준 경우입니다. 예를 들어 디스크를 읽었다면 I/O 완료에 해당하는게 될 것이고, sleep 이라면 시간 만료에 해당하는 커널 이벤트입니다. 이 때 대기 중이던 스레드를 깨어주는 스레드 쪽의 콜 스택을 확인하면, 어떤 이유로 기다렸는지를 추측할 수 있습니다.

이에 해당하는 BCC 스크립트인 offwaketime 으로 이를 측정해봤습니다.

blog-waker-cropped

poll 한 쪽을 꺠우는 콜 스택을 보면 udp_rcv 를 확인할 수 있습니다. 즉, poll() 은 UDP 응답을 기다리고 있습니다.

질문: 누가 UDP를 쓰고 있는가?

웹 서버는 TCP/IP 기반이라 UDP를 쓰지 않습니다. (아마도)
그래서 UDP를 쓰는 서비스가 뭐가 있는지 생각해보면,

  • DHCP
  • DNS
  • RTP

등에서 사용합니다.

그런데 코드를 다시 들여다보니, 로그를 남기기 위해서 DNS 호스트 주소를 역으로 조회하고 있었습니다.
(이 부분은 핸들러가 아니라 미들웨어에 들어가있는 코드입니다)

가설 #4: DNS 조회가 오래 걸리고 있다

DNS 조회는 다음과 같은 C 함수에서 처리합니다.

  • getnameinfo
  • getaddrinfo
  • gethostname
  • (기타 등등)

이 함수들의 실행 시간 분포를 다시 funclatency 를 써서 확인해봤습니다.

blog-getnameinfo-remote

DNS 조회 시간이 33ms 에서 134ms 정도 소요되고 있습니다. 즉, DNS조회가 느린게 성능에 제일 큰 영향을 주고 있었습니다.

해결

이 문제는 대부분의 linux 배포판이 DNS 쿼리를 캐싱하지 않아서 생기는 문제입니다.
서버 내에 DNS 처리를 캐싱하는 서비스를 실행하고 나니 성능이 다음과 같이 변합니다.

  • 초당 1,567 요청 처리; 코어 당 390 요청/초 처리.
  • 요청 당 처리 시간: 2.5 ms

약 14배 정도 더 처리하고 있으며, 처음 생각했던 초당 1000 요청 처리하는 수준을 넘습니다.

Linux kernel v4.13+ 에 대한 주의사항

해당 커널의 구조체 랜덤화 기능 때문에, BCC 스크립트가 바로 동작하지 않을 수 있습니다.
다음 수정 사항이 필요한 경우가 있습니다. Python 스크립트 내의 bpf_text=""" 다음 줄에 아래에 보이는 것처럼 두 줄을 추가해줍니다.

bfp_text = """
#define randomized_struct_fields_start struct {
#define randomized_struct_fields_end };

결론

운영 체제 수준에서 제공하는 기능인 eBPF와 이를 사용한 BCC 툴킷을 써서 실행 중인 서비스를 멈추거나 수정하지 않고도 성능을 측정하고 문제의 원인을 찾을 수 있었습니다.
앞서 다뤘던 것처럼 가설을 세우고, 이를 반복적으로 검증하는 과정을 거쳐서 성능 문제를 추적하는데 매우 유용한 도구로 앞으로 많이 활용되리라 생각합니다.

답글 남기기

댓글을 게시하려면 다음의 방법 중 하나를 사용하여 로그인 하세요:

WordPress.com 로고

WordPress.com의 계정을 사용하여 댓글을 남깁니다. 로그아웃 /  변경 )

Google+ photo

Google+의 계정을 사용하여 댓글을 남깁니다. 로그아웃 /  변경 )

Twitter 사진

Twitter의 계정을 사용하여 댓글을 남깁니다. 로그아웃 /  변경 )

Facebook 사진

Facebook의 계정을 사용하여 댓글을 남깁니다. 로그아웃 /  변경 )

w

%s에 연결하는 중