【システムパフォーマンス】システム全体の解析をするツールを使ってみる
2023.06.26
2024.03.24
パフォーマンスチューニング
iostatISUCONLinuxmpstatnstatsarvmstat
はじめに
下記のシステムパフォーマンスで紹介されているカウンタを使ったシステム全体を解析するツールをざっくり紹介して、実際にISUCONのアプリで使ってみたいと思います。
カーネルカウンタを使ったシステム全体を解析するツール
今回紹介するのはカーネルカウンタを使ったシステム全体を解析できる下記のツールになります。
vmstatmpstatiostatnstatsar
vmstat
vmstatは、CPUやメモリの稼働状況を表示してくれます。
vmstat(8) - Linux manual page
先頭の行はブート以降の集計（procとmemoryのみその瞬間〕、以降の行はその瞬間の集計になっています。
r: 実行可能なプロセス数b: I/Oの完了を待っているプロセス数swpd: スワップアウトされたメモリfree: 利用可能なメモリbuff: バッファのメモリcache: キャッシュのメモリsi: スワップインされたメモリso: スワップアウトされたメモリbi: ブロックデバイスから読み込んだブロック数bo: ブロックデバイスから書き込んだブロック数in: 割り込み回数cs: コンテキストスイッチ回数us: ユーザー時間の割合sy: システム時間の割合id: アイドル時間の割合wa: I/O待ちの時間の割合st: 仮想マシンでCPUを盗まれた(Stolen)時間の割合
1$ vmstat 1
2procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
3 r b swpd free buff cache si so bi bo in cs us sy id wa st
4 0 0 518268 75248 111032 876912 0 4 25 30 240 235 0 0 99 0 0
5 0 0 518268 75248 111032 876912 0 0 0 0 870 952 0 1 99 0 0
6 0 0 518268 75248 111032 876912 0 0 0 0 847 968 1 0 99 0 0
7 ...mpstat
mpstatは、CPUごとの使用率を表示してくれます。
mpstat(1) - Linux manual page
-P ALLでCPUごとに出力できます。
CPU: プロセッサ番号%usr: %niceを除くユーザー時間の割合%nice: nice値で優先度をつけたプロセスのユーザー時間の割合%sys: システム時間の割合%iowait: I/O待ち時間の割合%irq: ハードウェア割り込みによるCPU使用時間の割合%soft: ソフトウェア割り込みによるCPU使用時間の割合%steal: 他のテナントに使われたCPU時間の割合%guest: ゲスト仮想マシンに使われたCPU時間の割合%gnice: nice値で優先度をつけたゲストを実行したCPU時間の割合%idle: アイドル時間の割合
1$ mpstat -P ALL
2Linux 5.15.0-69-generic (ubuntu2204.localdomain) 06/25/23 _x86_64_ (2 CPU)
3
401:53:07 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
501:53:07 all 0.43 0.00 0.36 0.05 0.00 0.08 0.00 0.00 0.00 99.07
601:53:07 0 0.60 0.00 0.49 0.07 0.00 0.09 0.00 0.00 0.00 98.75
701:53:07 1 0.25 0.00 0.21 0.03 0.00 0.08 0.00 0.00 0.00 99.42iostat
iostatは、ディスクごとのIOの使用状況を表示してくれます。
iostat(1) - Linux manual page
-xで拡張統計が表示され、-sでショート版の出力が可能になります。-xsで表示される内容は下記の通りです。
tps: 1秒あたりのトランザクション数kB/s: 1秒あたりのKB数rqm/s: 1秒あたりのキューイング、マージされたI/Oリクエスト数await: 平均I/Oリクエスト時間areq-sz: 平均I/Oリクエストサイズaqu-sz: 平均リクエスト数%util: I/Oリクエストを処理してビジーだった時間の割合
1$ iostat -xs
2Linux 5.15.0-69-generic (ubuntu2204.localdomain) 06/25/23 _x86_64_ (2 CPU)
3
4avg-cpu: %user %nice %system %iowait %steal %idle
5 0.43 0.00 0.44 0.05 0.00 99.07
6
7Device tps kB/s rqm/s await areq-sz aqu-sz %util
8dm-0 6.74 73.74 0.00 5.17 10.94 0.03 0.46
9loop0 0.00 0.01 0.00 0.81 14.60 0.00 0.00
10loop1 0.01 0.47 0.00 0.68 38.14 0.00 0.00
11loop2 0.00 0.00 0.00 0.68 7.28 0.00 0.00
12loop3 0.00 0.02 0.00 0.47 5.32 0.00 0.00
13loop4 0.01 0.19 0.00 0.94 32.02 0.00 0.00
14loop5 0.00 0.01 0.00 0.08 2.81 0.00 0.00
15loop6 0.00 0.00 0.00 0.00 1.27 0.00 0.00
16sda 3.70 73.84 3.06 1.81 19.97 0.01 0.46nstat
nstatは、TCP/IPスタックの統計量を表示してくれます。
rtacct(8) - Linux manual page
表示されるのは、下記のような項目です。
IpInReceives: インバウンドIPパケット数IpOutRequests: アウトバウンドIPパケット数TcpActiveOpens: TCPアクティブ接続数TcpPassiveOpens: TCPパッシブ接続数TcpInSegs: TCPインバウンドセグメント数TcpOutSegs: TCPアウトバウンドセグメント数TcpRetransSegs: TCP再送セグメント数
-sを指定すると、カウントをリセットしないで表示してくれます。-sなしで実行するとカウンタがリセットされるので、2度目に実行した場合にそのインターバルでの値が確認できます。
1isucon@ubuntu2204:~/bench$ nstat -s
2#kernel
3IpInReceives 158 0.0
4IpInDelivers 158 0.0
5IpOutRequests 127 0.0
6TcpInSegs 158 0.0
7TcpOutSegs 127 0.0
8TcpExtTCPHPHits 4 0.0
9TcpExtTCPHPAcks 123 0.0
10TcpExtTCPBacklogCoalesce 4 0.0
11TcpExtTCPAutoCorking 9 0.0
12TcpExtTCPOrigDataSent 127 0.0
13TcpExtTCPDelivered 127 0.0
14IpExtInOctets 8198 0.0
15IpExtOutOctets 10492 0.0
16IpExtInNoECTPkts 158 0.0sar
sarは、さまざまな統計量を表示できます。
オプションでCPU、メモリ、ネットワークなど幅広く確認できます。
sar(1) - Linux manual page
統計量を記録するスケジュールは、/etc/cron.d/sysstatで定義されています。出力されるのはその間隔での統計量になります。また、sar 1 5で1秒間隔で5回などの出力も可能です。
1$ sar
2Linux 5.15.0-69-generic (ubuntu2204.localdomain) 06/25/23 _x86_64_ (2 CPU)
3
400:00:16 CPU %user %nice %system %iowait %steal %idle
500:10:16 all 0.40 0.02 0.41 0.04 0.00 99.13
600:20:16 all 0.36 0.00 0.31 0.03 0.00 99.30
7...
812:00:16 all 0.36 0.00 0.33 0.02 0.00 99.29
912:10:16 all 0.35 0.00 0.32 0.02 0.00 99.30
1012:20:09 all 0.38 0.00 0.41 0.01 0.00 99.20
1112:30:16 all 0.41 0.00 0.39 0.01 0.00 99.20
1212:40:16 all 0.40 0.00 0.49 0.03 0.00 99.08
1312:50:16 all 0.41 0.00 0.52 0.01 0.00 99.06
1413:00:16 all 0.40 0.00 0.41 0.01 0.00 99.18
15Average: all 0.40 0.00 0.43 0.02 0.00 99.15
16
17$ sar 1 5
18Linux 5.15.0-69-generic (ubuntu2204.localdomain) 06/25/23 _x86_64_ (2 CPU)
19
2013:08:00 CPU %user %nice %system %iowait %steal %idle
2113:08:01 all 0.00 0.00 0.55 0.00 0.00 99.45
2213:08:02 all 0.54 0.00 0.54 0.00 0.00 98.92
2313:08:03 all 0.55 0.00 0.55 0.00 0.00 98.91
2413:08:04 all 0.54 0.00 0.00 0.00 0.00 99.46
2513:08:05 all 0.00 0.00 1.08 0.00 0.00 98.92
26Average: all 0.33 0.00 0.54 0.00 0.00 99.13ISUCONアプリで試してみる
ISUCONのアプリのベンチマークを動かしてみて、それぞれのツールで確認してみます。
ISUCONのアプリをローカルで動かす方法は下記で紹介しています。
ISUCONアプリをローカルで構築してみる
:::affiliate-message 本ページはAmazonアフィリエイトのリンクを含みます。
今回動かすのは、ISUCON12予選問題になります。
vmstat
vmstatを実行した結果は下記の通りです。
1vagrant@ubuntu2204:~$ vmstat 1
2procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
3 r b swpd free buff cache si so bi bo in cs us sy id wa st
4 0 0 531372 88044 146924 819888 0 2 17 20 154 151 0 0 99 0 0
5...
6 3 0 531372 76704 146944 836868 0 0 4348 0 926 1828 22 19 58 1 0
7 2 0 533172 78828 144932 839356 0 1704 16220 1704 1360 2803 22 29 41 8 0
8 1 0 533172 75340 144932 843672 0 0 4508 0 1183 1239 36 15 47 1 0
9 1 0 535740 78576 142908 844960 0 2568 15004 2568 883 2485 13 37 48 2 0
10 6 0 535740 65472 142740 857944 0 0 15172 0 1190 2622 21 27 50 2 0
11 6 0 536772 74580 140852 852192 0 1076 6888 1076 918 1449 12 30 32 26 0
12 2 0 539596 77816 138604 852996 0 2964 14904 2988 1196 2532 17 38 42 3 0
13...
1412 1 551164 75292 126820 881588 0 2008 1824 75904 1184 865 1 49 32 18 0
1518 0 552964 66724 124372 893604 0 1816 2208 31364 1158 841 0 42 47 12 0
16 4 0 558876 74548 116964 900792 0 5848 4356 5848 1366 916 1 44 55 1 0
17 7 0 562988 77584 109296 910024 0 4232 17568 13216 1125 830 1 45 49 6 0
18 4 0 565812 74808 103228 922284 20 3072 40872 48072 1624 1499 3 40 41 15 0
19...
2022 0 568644 72856 101100 926712 416 2840 18788 4888 2532 3674 36 42 9 13 0
2116 0 568644 68076 102076 931200 240 0 4284 4964 2811 5839 53 39 4 5 0
22 8 0 569668 74376 101580 927896 88 988 6356 7060 4022 7200 35 43 7 15 0
2313 1 569668 68076 102648 933224 104 0 4952 6496 3485 7335 43 41 5 11 0
24...
25 1 1 572756 76936 111816 919344 0 0 1952 5808 2978 5963 7 28 42 23 0
2625 2 572500 71900 112288 923268 288 0 3088 5728 2531 7561 38 40 14 8 0
27 1 1 572244 66608 113500 926864 264 0 2248 6092 4325 10908 18 43 20 18 0
28 2 0 573020 84752 111980 910616 256 812 1368 6596 4490 8830 10 34 34 23 0
29 0 1 573020 81728 112944 912888 80 0 1576 29412 3042 6220 5 31 41 22 0
30...
31 6 1 571996 64876 116444 922424 0 0 404 10540 2478 4099 4 44 25 28 0
3233 3 572252 70672 115756 917280 16 28 304 7896 2742 5234 14 42 17 27 0
33 4 0 572252 73456 115912 915284 68 64 976 4840 1859 4454 40 48 5 7 0
34...mpstat
mpstatを実行した結果は下記の通りです。システム時間の割合が増えているところでI/待ち時間が増えていたりします。
1vagrant@ubuntu2204:~$ mpstat -P ALL 1
2Linux 5.15.0-69-generic (ubuntu2204.localdomain) 06/25/23 _x86_64_ (2 CPU)
3
414:08:07 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
514:08:08 all 0.54 0.00 1.08 0.00 0.00 0.00 0.00 0.00 0.00 98.39
614:08:08 0 1.03 0.00 2.06 0.00 0.00 0.00 0.00 0.00 0.00 96.91
714:08:08 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
8
9...
10
1114:08:46 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
1214:08:47 all 55.56 0.00 15.56 5.56 0.00 6.67 0.00 0.00 0.00 16.67
1314:08:47 0 57.41 0.00 18.52 7.41 0.00 0.00 0.00 0.00 0.00 16.67
1414:08:47 1 52.78 0.00 11.11 2.78 0.00 16.67 0.00 0.00 0.00 16.67
15
1614:08:47 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
1714:08:48 all 85.33 0.00 5.33 0.00 0.00 5.33 0.00 0.00 0.00 4.00
1814:08:48 0 86.84 0.00 5.26 0.00 0.00 2.63 0.00 0.00 0.00 5.26
1914:08:48 1 83.78 0.00 5.41 0.00 0.00 8.11 0.00 0.00 0.00 2.70
20
2114:08:48 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
2214:08:49 all 74.16 0.00 10.11 10.11 0.00 4.49 0.00 0.00 0.00 1.12
2314:08:49 0 59.52 0.00 11.90 21.43 0.00 4.76 0.00 0.00 0.00 2.38
2414:08:49 1 87.23 0.00 8.51 0.00 0.00 4.26 0.00 0.00 0.00 0.00
25
2614:08:49 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
2714:08:50 all 63.16 0.00 14.47 13.16 0.00 6.58 0.00 0.00 0.00 2.63
2814:08:50 0 55.00 0.00 12.50 25.00 0.00 7.50 0.00 0.00 0.00 0.00
2914:08:50 1 72.22 0.00 16.67 0.00 0.00 5.56 0.00 0.00 0.00 5.56
30
3114:08:50 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
3214:08:51 all 81.01 0.00 7.59 5.06 0.00 5.06 0.00 0.00 0.00 1.27
3314:08:51 0 78.57 0.00 7.14 7.14 0.00 4.76 0.00 0.00 0.00 2.38
3414:08:51 1 83.78 0.00 8.11 2.70 0.00 5.41 0.00 0.00 0.00 0.00
35
36...
37
3814:08:53 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
3914:08:54 all 51.89 0.00 1.62 0.00 0.00 0.00 0.00 0.00 0.00 46.49
4014:08:54 0 95.00 0.00 2.00 0.00 0.00 0.00 0.00 0.00 0.00 3.00
4114:08:54 1 1.18 0.00 1.18 0.00 0.00 0.00 0.00 0.00 0.00 97.65
42
4314:08:54 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
4414:08:55 all 52.15 0.00 0.54 0.00 0.00 0.00 0.00 0.00 0.00 47.31
4514:08:55 0 95.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 5.00
4614:08:55 1 2.33 0.00 1.16 0.00 0.00 0.00 0.00 0.00 0.00 96.51
47
4814:08:55 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
4914:08:56 all 51.89 0.00 1.08 0.00 0.00 0.54 0.00 0.00 0.00 46.49
5014:08:56 0 94.90 0.00 1.02 0.00 0.00 0.00 0.00 0.00 0.00 4.08
5114:08:56 1 3.45 0.00 1.15 0.00 0.00 1.15 0.00 0.00 0.00 94.2iostat
iostatを実行した結果は下記の通りです。I/O待ち時間が1ミリ秒を超えていたりしています。
1vagrant@ubuntu2204:~$ iostat -xsz 2
2Linux 5.15.0-69-generic (ubuntu2204.localdomain) 06/25/23 _x86_64_ (2 CPU)
3
4...
5
6avg-cpu: %user %nice %system %iowait %steal %idle
7 10.00 0.00 3.61 0.28 0.00 86.11
8
9Device tps kB/s rqm/s await areq-sz aqu-sz %util
10dm-0 60.00 574.00 0.00 1.00 9.57 0.06 5.20
11sda 45.00 574.00 15.00 1.33 12.76 0.07 5.20
12
13...
14
15avg-cpu: %user %nice %system %iowait %steal %idle
16 40.22 0.00 46.38 11.23 0.00 2.17
17
18Device tps kB/s rqm/s await areq-sz aqu-sz %util
19dm-0 2283.50 10292.00 0.00 0.84 4.51 1.92 93.60
20sda 1357.50 10292.00 925.50 1.08 7.58 1.91 93.80
21
22...
23
24avg-cpu: %user %nice %system %iowait %steal %idle
25 9.38 0.00 38.54 20.49 0.00 31.60
26
27Device tps kB/s rqm/s await areq-sz aqu-sz %util
28dm-0 2170.50 10110.00 0.00 0.67 4.66 1.46 99.40
29sda 1369.00 10110.00 801.50 0.81 7.38 1.45 99.40
30
31
32avg-cpu: %user %nice %system %iowait %steal %idle
33 14.74 0.00 33.68 18.60 0.00 32.98
34
35Device tps kB/s rqm/s await areq-sz aqu-sz %util
36dm-0 1878.00 7480.00 0.00 0.62 3.98 1.16 99.40
37sda 1132.00 7480.00 746.00 0.66 6.61 1.09 99.40
38
39...
40
41avg-cpu: %user %nice %system %iowait %steal %idle
42 5.57 0.00 31.36 18.82 0.00 44.25
43
44Device tps kB/s rqm/s await areq-sz aqu-sz %util
45dm-0 2346.50 10182.00 0.00 0.51 4.34 1.19 98.20
46sda 1288.50 10186.00 1059.00 0.65 7.91 1.20 98.20nstat
nstatを実行した結果は下記の通りです。
1vagrant@ubuntu2204:~$ nstat
2#kernel
3IpInReceives 12068 0.0
4IpInDelivers 12068 0.0
5IpOutRequests 12064 0.0
6TcpActiveOpens 90 0.0
7TcpPassiveOpens 90 0.0
8TcpEstabResets 4 0.0
9TcpInSegs 12068 0.0
10TcpOutSegs 12060 0.0
11TcpRetransSegs 4 0.0
12TcpOutRsts 4 0.0
13TcpExtDelayedACKs 214 0.0
14TcpExtDelayedACKLocked 2 0.0
15TcpExtDelayedACKLost 4 0.0
16TcpExtTCPHPHits 6197 0.0
17TcpExtTCPPureAcks 569 0.0
18TcpExtTCPHPAcks 6264 0.0
19TcpExtTCPLossProbes 4 0.0
20TcpExtTCPDSACKOldSent 4 0.0
21TcpExtTCPDSACKRecv 4 0.0
22TcpExtTCPDSACKIgnoredNoUndo 4 0.0
23TcpExtTCPRcvCoalesce 52 0.0
24TcpExtTCPOrigDataSent 7069 0.0
25TcpExtTCPKeepAlive 1 0.0
26TcpExtTCPDelivered 7161 0.0
27TcpExtTCPDSACKRecvSegs 4 0.0
28IpExtInOctets 3005549 0.0
29IpExtOutOctets 3010683 0.0
30IpExtInNoECTPkts 12070 0.0sar
sarでメモリのページング統計を出力した結果は下記の通りです。
1vagrant@ubuntu2204:~$ sar -B 2
2Linux 5.15.0-69-generic (ubuntu2204.localdomain) 06/26/23 _x86_64_ (2 CPU)
3
410:55:08 pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s pgscand/s pgsteal/s %vmeff
510:55:10 756.22 284.58 1970.15 5.97 79.10 0.00 0.00 0.00 0.00
610:55:12 864.00 196.00 4.50 0.50 1393.00 1916.50 0.00 2768.00 144.43
710:55:14 34.00 0.00 1.50 0.50 914.50 0.00 0.00 0.00 0.00
810:55:16 854.00 1418.00 243.50 47.50 25175.00 0.00 0.00 0.00 0.00
910:55:18 1054.73 106115.42 951.74 23.38 11443.28 14604.98 0.00 21716.42 148.69
1010:55:20 1914.00 6710.00 841.50 65.00 551.50 0.00 0.00 0.00 0.00
1110:55:22 788.06 10670.65 532.34 13.93 220.40 0.00 0.00 0.00 0.00
1210:55:24 648.00 9248.00 477.00 12.50 2229.50 3160.00 0.00 4042.00 127.91
1310:55:26 688.00 6596.00 381.50 20.50 159.00 0.00 0.00 0.00 0.00
1410:55:28 884.00 9756.00 466.50 17.50 133.50 0.00 0.00 0.00 0.00
1510:55:30 876.00 8062.00 471.50 23.00 204.00 0.00 0.00 0.00 0.00
1610:55:32 606.00 30072.00 414.50 17.50 2137.50 3263.00 0.00 4092.00 125.41
1710:55:34 1872.00 22098.00 1605.00 43.00 241.00 0.00 0.00 0.00 0.00
1810:55:36 318.00 9696.00 317.50 9.50 182.50 0.00 0.00 0.00 0.00
1910:55:38 582.00 6706.00 505.00 21.00 52.00 0.00 0.00 0.00 0.00
2010:55:40 682.00 8096.00 409.00 23.00 2340.00 3325.50 0.00 4199.00 126.27
2110:55:42 598.00 10940.00 3132.00 20.00 2689.00 3420.00 0.00 4848.00 141.75
2210:55:44 112.00 5858.00 36.50 0.00 3.00 0.00 0.00 0.00 0.00
2310:55:46 214.00 6256.00 229.50 0.50 2118.50 0.00 0.00 0.00 0.00
2410:55:48 195.02 5998.01 246.27 1.99 1.99 0.00 0.00 0.00 0.00
2510:55:50 296.00 212.00 160.50 10.00 188.00 0.00 0.00 0.00 0.00
2610:55:52 84.00 0.00 105.50 1.00 1302.50 0.00 0.00 0.00 0.00
2710:55:54 0.00 732.00 0.00 0.00 1.00 0.00 0.00 0.00 0.00
2810:55:56 0.00 22.00 0.00 0.00 1.50 0.00 0.00 0.00 0.00
2910:55:58 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
3010:56:00 0.00 0.00 0.00 0.00 1.49 0.00 0.00 0.00 0.00
3110:56:02 0.00 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00
3210:56:04 0.00 332.00 3.00 0.00 1.00 0.00 0.00 0.00 0.00
3310:56:06 0.00 0.00 0.00 0.00 1.50 0.00 0.00 0.00 0.00
34Average: 514.52 9188.29 465.99 13.02 1854.40 1025.43 0.00 1439.24 140.36今後
ここから問題のありそうな箇所を探し出し、さらに詳細に解析できるようにする必要があると感じました。
参考
- vmstat(8) - Linux manual page
- mpstat(1) - Linux manual page
- iostat(1) - Linux manual page
- rtacct(8) - Linux manual page
- sar(1) - Linux manual page
- JM Project (Japanese)
Support
\ この記事が役に立ったと思ったら、サポートお願いします！ /
Share
関連記事
【Continuous Profiling】Pyroscopeを試してみる
2023.11.25
ISUCONアプリをローカルで構築してみる
2023.06.15
