Linux Performance Analysis in 60 seconds

이 글은 넷플릭스 기술 블로그의 Linux Performance Analysis in 60,000 Milliseconds를 읽으면서 정리한 것이다.

Linux Performance Analysis in 60,000 Milliseconds

넷플릭스는 수많은 AWS EC2 인스턴스를 사용하고 이 인스턴스들의 성능을 모니터링하는 도구를 사용한다. 클라우드 성능 모니터링에 Atlas를 사용하고, 온디맨드 모니터링에 Vector를 사용한다. Atlas나 Vector로 대부분의 이슈를 해결할 수 있지만 가끔은 직접 서버에 로그인해서 확인해볼 필요가 있다.

First 60 Seconds: Summary

이 글에서는 넷플릭스 성능 엔지니어링 팀이 처음 60초간 무엇을 먼저 확인하는지를 다룬다. 첫 60초 동안에는 10개의 커맨드로 시스템 리소스 사용량과 프로세스를 살펴본다. 오류가 있는지도 보고 포화된 리소스가 있는지, 리소스의 사용률도 확인한다. 이러한 지표는 해석하기가 쉽다. 포화는 리소스가 처리할 수 있는 것보다 많은 일을 해야할 때 생긴다. 리소스가 포화되었는지는 요청 큐의 길이나 대기 시간 등으로 나타난다.

uptime
dmesg | tail
vmstat 1
mpstat -P ALL 1
pidstat 1
iostat -xz 1
free -m
sar -n DEV 1
sar -n TCP,ETCP 1
top

위의 커맨드 중 일부는 sysstat 패키지가 설치되어있어야 한다. 이 커맨드들이 보여주는 지표는 USE Method (Utilization-Saturation-Error Method, 성능 병목 현상을 찾는 방법)로 현상을 분석하는 데에 도움이 된다. USE Method에서는 모든 종류의 리소스(프로세서, 메모리, 디스크, ...)에 대해서 사용률, 포화 상태, 오류를 확인한다. 그리고 각각의 리소스를 확인해보고 그 리소스가 병목 현상이 아니라는 것을 주의깊게 판단해야 한다. 이렇게 리소스를 하나씩 제거함으로써 성능에 문제가 있는지 확인할 수 있다.

1. uptime

$ uptime
23:51:26 up 21:31, 1 user, load average: 30.02, 26.43, 19.02

uptime 명령어는 평균 부하(load average)를 빠르게 보여준다. load average: 뒤의 숫자 세 개는 최근 1분, 5분, 15분 간의 평균 부하를 보여준다.

평균 부하는 보통 실행 가능한 상태에 있는 (runnable) 프로세스의 수를 나타낸다. 이때 실행 가능한 프로세스는 프로세서 상에서 실행중이거나, 대기열에서 대기중인 프로세스이다. 리눅스에서는 평균 부하가 실행가능한 프로세스 뿐만 아니라 I/O로 인해 블락된 프로세스도 포함한다.

따라서 평균 부하는 프로세스로 인한 부하 + I/O 로 인한 부하를 직관적으로 보여준다. 물론 명확한 지표는 아니지만 말이다. 평균 부하에 대한 자세한 글은 여기서 볼 수 있다.

위의 예시에서는 1분간 평균값에서는 30이고 15분 평균값에서는 19이다. 이 정도로 큰 값은 무슨 일이 생기고 있음을 의미한다. 아마도 CPU에 너무 많은 부하가 간 것일 수도 있다. 뒷 부분에서 나올 vmstat이나 mpstat 명령어가 자세한 걸 확인해줄 것이다.

2. dmesg | tail

$ dmesg | tail
[1880957.563150] perl invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0
[...]
[1880957.563400] Out of memory: Kill process 18694 (perl) score 246 or sacrifice child
[1880957.563408] Killed process 18694 (perl) total-vm:1972392kB, anon-rss:1953348kB, file-rss:0kB
[2320864.954447] TCP: Possible SYN flooding on port 7001. Dropping request.  Check SNMP counters.

dmesg는 커널 로그를 보여주는 명령어다. dmesg의 출력을 tail의 입력으로 파이프라인으로 연결하면 로그의 마지막 10줄을 보여준다. 위의 예시는 oom killer ㅡ 메모리가 부족할 때 사용중인 프로세스를 죽여서 메모리를 확보하는 기능 ㅡ 가 실행되서 TCP 요청을 드랍되었음을 확인할 수 있다.

3. vmstat 1

$ vmstat 1
procs ---------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
34  0    0 200889792  73708 591828    0    0     0     5    6   10 96  1  3  0  0
32  0    0 200889920  73708 591860    0    0     0   592 13284 4282 98  1  1  0  0
32  0    0 200890112  73708 591860    0    0     0     0 9501 2154 99  1  0  0  0
32  0    0 200889568  73712 591856    0    0     0    48 11900 2459 99  0  0  0  0
32  0    0 200890208  73712 591860    0    0     0     0 15898 4840 98  1  1  0  0
^C

vmstat은 가상 메모리 관련 통계를 간단하게 보여주는 도구로 수십년 전에 BSD에서 처음 등장했다. vmstat 명령어의 인자로 1을 사용했는데 1초마다 통계를 보여주라는 의미이다. 여기서 첫 번째 줄은 부팅 이후의 평균값을 보여주고, 두번째 줄부터는 1초마다 현재의 통계를 보여준다.

r: CPU에서 실행을 기다리는 프로세스의 수를 나타낸다. 이 값은 I/O를 반영하지 않기 때문에 uptime의 평균 부하보다 CPU 포화 상태를 확인하기에 좋다. 만약 r 값이 CPU의 개수보다 많다면 포화 상태라고 할 수 있다.

free: free 상태의 메모리를 킬로바이트 단위로 보여준다. 뒤에어 알아볼 "free -m" 커맨드로 더 자세하게 확인할 수 있다.

si, so: 스왑인/스왑아웃 상태의 메모리를 나타낸다. 만약 si나 so가 0보다 크다면 스왑 메모리를 사용하는 것이므로 메모리가 부족한 상태이다.

us,sy,id,wa,st: CPU 사이의 평균값

us: 사용자 프로세스에서 실행된 시간

sy: 커널에서 실행된 시간 (사용자 프로세스에서의 시스템 호출, I/O, 커널 스레드 실행 등등)

id: idle (아무것도 하지 않는) 시간

wa: I/O 대기 시간

st: 도난당한 시간(stolen time) ㅡ 다른 게스트를 실행하고 있거나, 가상화에서 다른 컨테이너를 실행하고 있거나 ㅡ 을 나타낸다.

us + sy를 더해서 CPU 시간을 보면 CPU가 바쁜 상태인지를 확인할 수 있다.

만약 I/O 대기 시간이 높으면 디스크 입출력으로 인한 병목이 발생했을 수 있다. 이때는 I/O 대기 시간을 CPU idle 상태와 비슷하게 해석할 수 있는데, id는 단순히 idle한 상태라는 것만 알려주지만 wa는 왜 CPU가 idle 상태가 되었는지도 알려주기 때문이다.

I/O는 커널을 통해서 이루어지므로 시스템 시간 (sy)는 I/O 처리를 할때 꼭 필요하다. 만약 sy가 20% 이상이라면 커널이 I/O를 효율적으로 처리하고있는지 확인해볼 필요가 있다.

위의 예시에서는 CPU 시간이 대부분 사용자 시간이므로 커널보다는 어플리케이션에 집중해야 한다는 걸 알려준다. 그리고 위에서 CPU는 90% 이상 사용중인데, 이 사실 자체는 단순히 CPU를 많이 활용하고 있다는 뜻이므로 크게 문제가 안된다.

4. mpstat -P ALL 1

$ mpstat -P ALL 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015  _x86_64_ (32 CPU)

07:38:49 PM  CPU   %usr  %nice   %sys %iowait   %irq  %soft  %steal  %guest  %gnice  %idle
07:38:50 PM  all  98.47   0.00   0.75    0.00   0.00   0.00    0.00    0.00    0.00   0.78
07:38:50 PM    0  96.04   0.00   2.97    0.00   0.00   0.00    0.00    0.00    0.00   0.99
07:38:50 PM    1  97.00   0.00   1.00    0.00   0.00   0.00    0.00    0.00    0.00   2.00
07:38:50 PM    2  98.00   0.00   1.00    0.00   0.00   0.00    0.00    0.00    0.00   1.00
07:38:50 PM    3  96.97   0.00   0.00    0.00   0.00   0.00    0.00    0.00    0.00   3.03
[...]

mpstat은 CPU별로 CPU 시간을 나눠서 보여준다. mpstat은 CPU 사이에 부하가 분산되는지를 확인하는 데 사용된다. 하나의 CPU만 사용량이 매우 높다면 어플리케이션이 스레드를 잘 활용하지 못한다는 증거일 수 있다.

5. pidstat 1

$ pidstat 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015    _x86_64_    (32 CPU)

07:41:02 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
07:41:03 PM     0         9    0.00    0.94    0.00    0.94     1  rcuos/0
07:41:03 PM     0      4214    5.66    5.66    0.00   11.32    15  mesos-slave
07:41:03 PM     0      4354    0.94    0.94    0.00    1.89     8  java
07:41:03 PM     0      6521 1596.23    1.89    0.00 1598.11    27  java
07:41:03 PM     0      6564 1571.70    7.55    0.00 1579.25    28  java
07:41:03 PM 60004     60154    0.94    4.72    0.00    5.66     9  pidstat

07:41:03 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
07:41:04 PM     0      4214    6.00    2.00    0.00    8.00    15  mesos-slave
07:41:04 PM     0      6521 1590.00    1.00    0.00 1591.00    27  java
07:41:04 PM     0      6564 1573.00   10.00    0.00 1583.00    28  java
07:41:04 PM   108      6718    1.00    0.00    0.00    1.00     0  snmp-pass
07:41:04 PM 60004     60154    1.00    4.00    0.00    5.00     9  pidstat
^C

pidstat은 top 명령어와 비슷하게 프로세스별로 통계를 보여주지만 시간에 따라 어떻게 변화하는지를 보여주기 때문에 유용하다. 위 예시에서는 두 개의 자바 프로세스가 높은 CPU 사용률의 원인임을 보여준다. 자바 프로세스 하나당 거의 16개의 CPU를 사용하고 있다.

6. iostat -xz 1

$ iostat -xz 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015  _x86_64_ (32 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          73.96    0.00    3.73    0.03    0.06   22.21

Device:   rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda        0.00     0.23    0.21    0.18     4.52     2.08    34.37     0.00    9.98   13.80    5.42   2.44   0.09
xvdb        0.01     0.00    1.02    8.94   127.97   598.53   145.79     0.00    0.43    1.78    0.28   0.25   0.25
xvdc        0.01     0.00    1.02    8.86   127.79   595.94   146.50     0.00    0.45    1.82    0.30   0.27   0.26
dm-0        0.00     0.00    0.69    2.32    10.47    31.69    28.01     0.01    3.23    0.71    3.98   0.13   0.04
dm-1        0.00     0.00    0.00    0.94     0.01     3.78     8.00     0.33  345.84    0.04  346.81   0.01   0.00
dm-2        0.00     0.00    0.09    0.07     1.35     0.36    22.50     0.00    2.55    0.23    5.62   1.78   0.03
[...]
^C

iostat은 블록 디바이스에 관련된 지표를 보여준다.

r/s, w/s, rKB/s, wKB/s:

r/s와 w/s는 디바이스가 1초당 처리한 읽기요청과 쓰기요청의 개수를 나타낸다. rKB/s, wKB/s는 1초당 처리한 읽기 요청과 쓰기 요청에서 처리한 데이터의 크기를 킬로바이트 단위로 표현한 것이다.

await: I/O 요청부터 처리까지 걸린 평균 시간이다. 높은 값은 디바이스가 포화 상태거나 문제가 생겼음을 나타낸다.

avgqu-sz: 해당 디바이스의 요청 큐의 평균 길이이다. 이 큐의 길이가 1보다 크면 포화상태를 의미할 수도 있다. iostat의 최근 버전에서는 aqu-sz 라고 표시한다.

%util: 디바이스의 사용률을 나타낸다. 전체 시간 중 I/O 요청을 처리하는 시간의 비율을 나타내는데, 이 값이 100%에 가까우면 포화 상태를 나타낼 수 있다. 하지만 가상 하드 디스크나 최신 SSD처럼 동시에 여러 개의 요청을 처리할 수 있는 환경에서는 이 값이 높다고 꼭 포화된 것은 아니다.

여기서 주의할 점은 디스크의 성능이 나쁘다고 해서 항상 어플리케이션의 성능도 나쁘지는 않다는 점이다. 입출력 버퍼를 사용하거나 non-blocking IO를 사용하거나 read-ahead를 하는 등등 다양한 기술로 디스크의 낮은 성능을 커버할 수 있다.

7. free -m

free -m은 메모리의 상태를 보여준다. (-m은 메가바이트 단위로 보여달라는 옵션)

$ free -m
              total        used        free      shared  buff/cache   available
Mem:           3711         999        1796          74         914        2479
Swap:             0           0           0

total: 메모리의 전체 크기

used: total - free - buffers - cache

buffers:블록 디바이스의 입출력에 사용되는 버퍼 캐시

cache: 파일시스템에 의해 사용되는 페이지 캐시 + 슬랩에 사용되는 메모리

여기서 buffers와 cache는 얼마나 많은 메모리가 파일시스템/디스크 등에 의해 캐시로 사용되는지를 나타낸다. free 메모리가 많다면 메모리의 일정 부분은 buffers와 cache에 사용된다. 예를 들어서 내 오드로이드의 메모리 사용량을 보면 CPU가 IDLE 상태임에도 불구하고 Buffers + Cache가 800MiB가 넘는다. 이러한 메모리는 어플리케이션이 필요로 할 때 쉽게 반납할 수 있다. 다만 buffers/cache가 너무 낮으면 파일시스템 성능이 급격하게 저하될 수 있다.

buff/cache: buffers + cache

shared: /proc/meminfo의 Shmem 필드를 보여주는데, 대부분 tmpfs를 위해 사용된다.

available: 스왑 없이 얼마나 많은 메모리가 새로운 어플리케이션에게 할당될 수 있는지를 나타낸다. 이 필드는 /proc/meminfo의 MemAvailable을 참조한다. 정확한 내용은 MemAvailable을 도입한 패치를 참고하자.

available은 free + reclaim 가능한 메모리라고 할 수 있다. free에는 buff/cache가 포함되지 않기 때문에 캐시를 위해 할당된 메모리가 실제로 사용되지 않음에도 불구하고 free는 적게 나타날 수 있다.

하지만 그렇다고 free + buff/cache를 모두 더해서 사용 가능한 메모리를 구하자니 buff/cache가 무조건 reclaim할 수 있는 메모리도 아니다보니, 사용 가능한 메모리를 확인하고 싶을 때는 별도로 계산되는 available 필드를 확인하는 게 가장 적합하다.

8. sar -n DEV 1

$ sar -n DEV 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015     _x86_64_    (32 CPU)

12:16:48 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
12:16:49 AM      eth0  18763.00   5032.00  20686.42    478.30      0.00      0.00      0.00      0.00
12:16:49 AM        lo     14.00     14.00      1.36      1.36      0.00      0.00      0.00      0.00
12:16:49 AM   docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00

12:16:49 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
12:16:50 AM      eth0  19763.00   5101.00  21999.10    482.56      0.00      0.00      0.00      0.00
12:16:50 AM        lo     20.00     20.00      3.25      3.25      0.00      0.00      0.00      0.00
12:16:50 AM   docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
^C

-n DEV는 네트워크 디바이스의 통계를 보여주는 옵션이다. 1은 1초마다 보여달라는 의미이다.

이 명령어로는 네트워크 인터페이스의 처리량(throughput)을 확인할 수 있다. rxpck/s, txpck/s는 초당 수신/송신 패킷의 수를, rxkB/s, txkB/s는 초당 수신/송신 패킷을 KiB 단위로 보여준다. rxcmp/s, txcmp/s는 초당 수신/송신되는 압축된 패킷의 수를 보여준다. %ifutil은 네트워크 인터페이스의 사용률을 보여준다.

이 도구로 현재 네트워크 인터페이스의 처리량이 NIC의 한계나 회선의 한계에 도달했는지 확인할 수 있다.

9. sar -n TCP,ETCP 1

여기서 -n 뒤에 오는 TCP는 TCP (IPv4) 관련 통계를, ETCP는 TCP (IPv4)에서 발생하는 오류의 통계를 보여달라는 의미이다.

$ sar -n TCP,ETCP 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015    _x86_64_    (32 CPU)

12:17:19 AM  active/s passive/s    iseg/s    oseg/s
12:17:20 AM      1.00      0.00  10233.00  18846.00

12:17:19 AM  atmptf/s  estres/s retrans/s isegerr/s   orsts/s
12:17:20 AM      0.00      0.00      0.00      0.00      0.00

12:17:20 AM  active/s passive/s    iseg/s    oseg/s
12:17:21 AM      1.00      0.00   8359.00   6039.00

12:17:20 AM  atmptf/s  estres/s retrans/s isegerr/s   orsts/s
12:17:21 AM      0.00      0.00      0.00      0.00      0.00
^C

active/s: 초당 클라이언트 측에서 수립한 연결의 개수 (예를 들어 connect()를 통해서)

passive/s: 초당 서버 측에서 수립한 연결의 개수 (예를 들어 accept()를 통해서)

retrans/s: 초당 TCP 패킷을 재전송한 횟수

패킷 재전송은 네트워크나 서버에 문제가 있다는 신호이다. 네트워크가 안정적이지 않거나 서버에 부하가 커서 패킷을 드랍하고 있을 수도 있다. 위 명령어에서는 초당 1개의 커넥션만 발생함을 보여준다.

10. top

$ top
top - 00:15:40 up 21:56,  1 user,  load average: 31.09, 29.87, 29.92
Tasks: 871 total,   1 running, 868 sleeping,   0 stopped,   2 zombie
%Cpu(s): 96.8 us,  0.4 sy,  0.0 ni,  2.7 id,  0.1 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:  25190241+total, 24921688 used, 22698073+free,    60448 buffers
KiB Swap:        0 total,        0 used,        0 free.   554208 cached Mem

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 20248 root      20   0  0.227t 0.012t  18748 S  3090  5.2  29812:58 java
  4213 root      20   0 2722544  64640  44232 S  23.5  0.0 233:35.37 mesos-slave
 66128 titancl+  20   0   24344   2332   1172 R   1.0  0.0   0:00.07 top
  5235 root      20   0 38.227g 547004  49996 S   0.7  0.2   2:02.74 java
  4299 root      20   0 20.015g 2.682g  16836 S   0.3  1.1  33:14.42 java
     1 root      20   0   33620   2920   1496 S   0.0  0.0   0:03.82 init
     2 root      20   0       0      0      0 S   0.0  0.0   0:00.02 kthreadd
     3 root      20   0       0      0      0 S   0.0  0.0   0:05.35 ksoftirqd/0
     5 root       0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/0:0H
     6 root      20   0       0      0      0 S   0.0  0.0   0:06.94 kworker/u256:0
     8 root      20   0       0      0      0 S   0.0  0.0   2:38.05 rcu_sched

top 명령어는 앞에서 살펴봤던 지표들 (us, sy, load average 등등)을 손쉽게 확인할 수 있다. top의 단점은 현재 시점에서의 지표들만 보여준다. 일정 시간마다 기존에 출력한 것을 지우고 새로운 값을 출력하기 때문에, 시간에 따라서 지표가 어떻게 변하는지 확인하기는 어렵다는 단점이 있다.

Follow-on Analysis

더 많은 커맨드와 접근 방법으로 시스템을 더 자세하게 분석할 수 있다. Brendan의 Linux Performance Tools tutorial에서는 40가지 이상의 커맨드로 벤치마킹, 프로파일링, 트레이싱, 정적 성능 튜닝, 관측가능성 등등을 다룬다.

See Also

Introducing Atlas

Introducing Vector

Netflix at Velocity 2015: Linux Performance Tools

Manuals

커맨드 라인에서 사용하는 명령어들 대부분은 문서화가 잘 되어있으니 명령어에 대한 자세한 내용은 매뉴얼을 참고하자.

uptime(1) - Linux manual page

vmstat(8) - Linux manual page

mpstat(1): Report processors related statistics - Linux man page

pidstat(1) - Linux manual page

iostat(1) - Linux manual page

free(1) - Linux manual page

sar(1) - Linux man page