はじめに
システムのパフォーマンスについて勉強する機会があったので、
パフォーマンス情報の取得方法について簡単にメモ。
パフォーマンス情報の取得方法
一定間隔のサマリ情報
※サマリ情報を確認する場合、最初の一行目は
起動時からのサマリ情報となるため無視する
root# sar -ubr 3 3
Linux 3.10.0-514.6.1.el7.x86_64 (test.sample.com) 2017年11月19日 _x86_64_ (2 CPU)
22時23分24秒 CPU %user %nice %system %iowait %steal %idle
22時23分27秒 all 1.69 0.00 0.51 0.00 0.00 97.80
22時23分24秒 tps rtps wtps bread/s bwrtn/s
22時23分27秒 1.00 0.00 1.00 0.00 34.67
22時23分24秒 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit kbactive kbinact kbdirty
22時23分27秒 280468 3585084 92.74 1848 2371256 4523820 56.13 1573332 1741284 64
22時23分27秒 CPU %user %nice %system %iowait %steal %idle
22時23分30秒 all 2.20 0.00 0.68 0.00 0.00 97.12
22時23分27秒 tps rtps wtps bread/s bwrtn/s
22時23分30秒 0.66 0.00 0.66 0.00 21.26
22時23分27秒 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit kbactive kbinact kbdirty
22時23分30秒 280372 3585180 92.75 1848 2371256 4523820 56.13 1573340 1741284 64
22時23分30秒 CPU %user %nice %system %iowait %steal %idle
22時23分33秒 all 2.38 0.00 0.85 0.00 0.00 96.77
22時23分30秒 tps rtps wtps bread/s bwrtn/s
22時23分33秒 0.67 0.00 0.67 0.00 21.33
22時23分30秒 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit kbactive kbinact kbdirty
22時23分33秒 280100 3585452 92.75 1848 2371256 4523788 56.13 1573340 1741284 68
root# vmstat 3 3
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
4 0 0 264772 1848 2478080 0 0 366 23 415 807 3 2 93 2 0
0 0 0 265028 1848 2478080 0 0 0 77 799 1554 4 1 96 0 0
1 0 0 264780 1848 2478084 0 0 0 11 841 1635 3 1 95 1 0
root# iostat -x 3 2
Linux 3.10.0-514.6.1.el7.x86_64 (test.sample.com) 2017年11月19日 _x86_64_ (2 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
2.74 0.00 1.55 1.95 0.00 93.76
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.02 0.27 9.23 3.39 642.08 41.37 108.31 0.26 20.97 20.52 22.19 3.71 4.68
dm-0 0.00 0.00 0.13 0.00 1.62 0.00 25.02 0.00 1.06 1.06 0.00 0.74 0.01
dm-1 0.00 0.00 0.03 0.00 0.23 0.00 18.00 0.00 1.82 1.82 0.00 1.82 0.00
dm-2 0.00 0.00 0.03 0.00 0.38 0.00 27.69 0.00 2.51 2.51 0.00 1.53 0.00
dm-3 0.00 0.00 0.03 0.00 0.38 0.00 27.69 0.00 1.99 1.99 0.00 1.57 0.00
dm-4 0.00 0.00 0.03 0.00 0.38 0.00 27.69 0.00 1.11 1.11 0.00 0.94 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
2.04 0.00 0.85 0.00 0.00 97.10
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 0.00 0.67 0.00 10.67 32.00 0.00 1.50 0.00 1.50 1.50 0.10
dm-0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-4 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
その瞬間の情報
root# ps -ef
・・・
oracle 6203 1 0 22:25 ? 00:00:00 ora_j001_orcl
oracle 6205 1 0 22:25 ? 00:00:00 ora_j002_orcl
postfix 6248 2499 0 22:25 ? 00:00:00 cleanup -z -t unix -u
postfix 6253 2499 0 22:25 ? 00:00:00 trivial-rewrite -n rewrite -t unix -u
postfix 6256 2499 0 22:25 ? 00:00:00 local -t unix
postfix 6257 2499 0 22:25 ? 00:00:00 local -t unix
・・・
- top
- 情報:その瞬間の起動プロセスと各プロセスごとのリソース使用状況
root# top -b -n 1
top - 22:26:29 up 44 min, 2 users, load average: 0.01, 0.05, 0.14
Tasks: 261 total, 1 running, 260 sleeping, 0 stopped, 0 zombie
%Cpu(s): 2.7 us, 1.5 sy, 0.0 ni, 93.9 id, 1.9 wa, 0.0 hi, 0.1 si, 0.0 st
KiB Mem : 3865552 total, 275000 free, 1111032 used, 2479520 buff/cache
KiB Swap: 4194300 total, 4194300 free, 0 used. 1721444 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3410 root 20 0 2012416 232756 48284 S 18.8 6.0 1:30.87 gnome-shell
2501 root 20 0 251128 42628 10716 S 6.2 1.1 0:25.43 Xorg
1 root 20 0 125372 3860 2388 S 0.0 0.1 0:02.11 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:00.09 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
7 root rt 0 0 0 0 S 0.0 0.0 0:00.09 migration/0
・・・
- pstack
- 情報:指定したプロセスがその瞬間に実行している
コールスタック情報
root# pstack 4088
#0 0x00007ff351cfcfca in semtimedop () from /lib64/libc.so.6
#1 0x000000000cd9362d in sskgpwwait ()
#2 0x000000000cd90f98 in skgpwwait ()
#3 0x000000000c8ddeab in ksliwat ()
#4 0x000000000c8dd2b1 in kslwaitctx ()
#5 0x0000000000c2e59c in kslwait ()
#6 0x00000000013b38eb in ktmmon ()
#7 0x00000000013ae020 in ktmSmonMain ()
#8 0x0000000002e519ec in ksbrdp ()
#9 0x00000000030eca40 in opirip ()
#10 0x0000000001b9bd68 in opidrv ()
#11 0x00000000026ac2d1 in sou2o ()
#12 0x0000000000ba8bbe in opimai_real ()
#13 0x00000000026b6a1c in ssthrdmain ()
#14 0x0000000000ba8a8c in main ()
詳細な処理の記録情報
root# tcpdump
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on wlan0, link-type EN10MB (Ethernet), capture size 262144 bytes
13:36:28.976861 IP 192.168.0.33.ssh > 192.168.0.36.61838: Flags [P.], seq 405791128:405791368, ack 3704156114, win 294, length 240
13:36:29.024540 IP 192.168.0.36.61838 > 192.168.0.33.ssh: Flags [.], ack 240, win 254, length 0
13:36:29.932405 IP 192.168.0.33.44348 > 192.168.0.1.domain: 4654+ PTR? 33.0.168.192.in-addr.arpa. (43)
13:36:29.936219 ba:27:eb:ee:1d:10 (oui Unknown) > b8:27:eb:ee:1d:10 (oui Unknown), ethertype Unknown (0x886c), length 153:
0x0000: 8001 00b7 0000 1018 0001 0002 0000 0000 ................
0x0010: 002c 0000 0000 0000 0000 0000 0000 0000 .,..............
0x0020: 004f f0d5 bff2 0a12 776c 3000 0000 0000 .O......wl0.....
・・・
root# strace -p 4080
Process 4080 attached
times(NULL) = 429775225
semtimedop(589832, {{16, -1, 0}}, 1, {2, 920000000}) = -1 EAGAIN (Resource temporarily unavailable)
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 51616}, ru_stime={0, 531645}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 51617}, ru_stime={0, 531660}, ...}) = 0
times(NULL) = 429775517
times(NULL) = 429775517
・・・
おわりに
実際にパフォーマンス問題が起きて調査する際は、
上記にあげたツールを組み合わせて原因追求していきます。
そのためには日頃から適切な情報収集をしておく必要がありますね。