Yoan
넷플릭스 테크 블로그에 올라온 포스트를 번역하였습니다. 시스템 엔지니어로써 기본적으로 알아야하는 명령어들입니다. 리마인드 겸 제 입맛에 맞게 해석-작성되었으니.. 참고해주시면 감사하겠습니다.
당신은 서버의 퍼포먼스 이슈가 발생하여 서버에 로그인 하였을 때 1분 동안 확인 하는 것이 무엇입니까?
우리(넷플릭스)는 거대한 EC2 리눅스 클라우드를 가지고 있으며, 다수의 퍼포먼스 분석 툴을 이용한 모니터링 및 퍼포먼스에 대한 연구를 진행하고 있습니다.
그 툴들에는 Atlas 와 Vector 가 포함되어 있지요. 이러한 도구들은 대부분의 이슈를 해결하는데 도움이 되지만, 때때로 인스턴스에 접근하여 기존의 보편적인 리눅스 퍼포먼스 툴을 사용해야 하는 일들이 생깁니다.
이 포스트를 통해, 넷플릭스 퍼포먼스 엔지니어링 팀이 1분 동안에 당신이 사용할 수 있는 표준 리눅스 툴들을 이용하여 최고의 퍼포먼스 조사하는 방법을 보여드리겠습니다.
첫번째 1분: summary
당신은 1분동안 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의 일부를 완성하는데 도움을 줄 것입니다.(성능 병목 현상을 찾기 위한 방법) 모든 리소스들(CPUs, memory, disks, e.t.c)의 utilization, saturation, and error metrics를 확인하는 것이 포함되어 있습니다.
요약한 커맨드들을 간단하게 설명하겠습니다. 더 많은 정보를 원하시면 맨페이지를 확인하시기 바랍니다.
1. uptime
$ uptime
23:51:26 up 21:31, 1 user, load average: 30.02, 26.43, 19.02
이 커맨드는 서버의 평균 부하를 빠르게 보는 방법입니다. 리눅스 시스템에서 프로세스들이 실행되기까기 대기하는 시간이지요. 이 숫자엔 CPU를 이용해야하는 프로세스들, DISK I/O를 발생시키는 프로세스들이 포함됩니다. 이 커맨드는 리소스 부하에 대한 정보를 제공하시만 다른 툴들 없이는 자세한 정보를 확인할 수 없습니다. 단순히 빠르게 파악할 수 있을 뿐이지요.
3개의 숫자는 1분, 5분, 15분간의 평균적인 값입니다. 이 숫자들은 지나간 시간동안 어떻게 부하가 변경되었는지 파악할 수 있게 합니다. 예를 들어 당신이 문제가 있는 서버를 확인하였을때, 1분의 부하가 15분때의 부하보다 낮다면 당신은 이슈를 놓쳤다고 불 수 있습니다.
부하의 평균 값은 최근 증가량을 보여주는 것입니다. 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.
이 명령어는 최근 10개의 시스템 메세지를 보여줍니다, 에러와 야기된 퍼포먼스의 이슈를 확인 할 수 있습니다. 예제에 oom-killer와 TCP drop이 발생한것이 보이네요.
이 스텝을 놓치지 마세요. dmesg는 항상 확인해야합니다.
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
vmstat은 일반적으로 사용되는 툴입니다. (BSD에서 처음 만들어졌죠) 이것은 각 라인마다 통계치를 출력해줍니다. vmstat에 argument를 1로 설정할 경우 1초마다의 평균 값을 출력합니다.
해당 출력 된 컬럼을 확인해봅시다.
- r : CPU에서 실행되는 프로세스의 값입니다. 이것은 CPU 포화 상태를 판단하는데 있어서 Load 정보보다 더 좋은 정보를 제공합니다. 디스크 I/O는 포함되지 않습니다.
- free : Free 메모리 정보입니다.(kilobytes)
- si,so : Swap in, Swap out 정보를 출력합니다. 만약 0이 아니면, Out of memory 상태인 것입니다.
- us,sy,id,wa,st : 이것은 CPU 시간의 고장입니다? 모든 CPU들의 평균 값으로 각각 user time, system time (kernel), idle, wait I/O 그리고 stolen time을 표시합니다.
System time은 I/O 프로세싱에 필수적입니다. 20%가 넘어가는 평균적인 시스템 시간은 아마도 커널이 현재 I/O 를 비효율적으로 사용한다는 것이겠죠.
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
[...]
이 커맨드는 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
이 커맨더는 top과 비슷한 작은 요약본과 같습니다. 하지만 스크린을 초기화시키는 것이아니라 지속적으로 출력을 합니다. 이 것은 시간이 지나면서의 패턴 변화를 파악하는데 있어서 유용합니다. 또한 기록이 가능하지요.
예제를 보면 2개의 자바 프로세스가 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
[...]
이 커맨드는 블록 디바이스(disks)를 이해하는데 매우 좋은 툴입니다. 작업 부하량과 결과 퍼포먼스를 함께 보여줍니다.
- r/s, w/s, rkB/s, wkB/s : 각 디바이스의 read, writes, read Kbyes 그리고 write Kbytes 값을 초단위로 보여줍니다.
- await : I/O의 평균값(milliseconds)을 보여줍니다. 이것은 어플리케이션의 시간을 표시하는데 큐에 적재된 시간과 대기시간도 포함되어 있습니다.
- avgqu-sz : 디바이스 평균 요청 값을 보여줍니다. 1보다 큰 값은 포화 상태의 증거입니다.
- %util : 디바이스 utilization입니다. 장치가 실행하고 있던 일의 두번째 시간을 보여줍니다. 60%이상의 값은 퍼포먼스가 낮은 상태임을 뜻합니다.
7. free -m
$ free -m
total used free shared buffers cached
Mem: 245998 24545 221453 83 59 541
-/+ buffers/cache: 23944 222053
Swap: 0 0 0
2개의 컬럼을 보여줍니다.
- buffers : buffer cache로 블록 디바이스 I/O 사용.
- cached : page cache로 파일시스템에서의 사용.
”-/+ buffers/cache”는 free 메모리 와 사용량에 대한 작은 혼란을 야기합니다. 리눅스는 캐싱된 free memory를 사용합니다. 하지만 어플리케이션이 필요로 할때 빠르게 반환할 수 있습니다. 그렇기에 캐싱된 메모리는 free memory 에 포함된다고 생각하면 됩니다. 자세한 내용은 linuxatemyram을 확인하시기 바랍니다.
리눅스에서 ZFS를 사용할 경우 추가로 혼란을 야기합니다. ZFS는 자신의 파일 시스템 캐시를 free -m 컬럼에 반영하지 않습니다. 따라서 이것은 low memory로 보일 수 있습니다. 실제로는 정상이지만요 (표시가 되지 않으니)
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
네트워크 인터페이스 처리량을 확인합니다.
9. sar -n TCP,ETCP 1
$ 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
TCP 메트릭스를 간략하게 보여줍니다.
- active/s : 내부에서 시작된 TCP 커넥션/s 입니다. (e.g., via conneect())
- passive/s : 외부에서 시작된 TCP 커넥션/s 입니다. (e.g., via accept())
- retrans/s : TCP 재송신/s
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
그럼 이만 :-)