DBに1000セッション張って負荷を確認してみようぜ!!の巻

※ここで記載した内容は独断と偏見に基づく個人の見解であり、実行しているコマンドや手順も必ずしも正しい手順ではありません。その為、あくまで参考程度にご覧頂ければと思います。

 

■検証概要

DBへリスナー経由のセッションを繰り返し生成する検証です。


■検証環境
OS:Oracle Enterprise Linux 5.8(x86_64)
DB:Oracle Database Enterprise Linux 11.2.0.1
シングル環境


■検証1

上述した今回の目的の検証を行う前にシェルからDBへ繋げるかテストします。

(1)viコマンドを使って以下の様なスクリプトを作成します。
 [oracle@hoge ~]$ vi hoge.sh
 #!/bin/sh
 sqlplus -s scott/tiger@o11201 << EOF
  ALTER SESSION SET NLS_DATE_FORMAT = 'RR-MM-DD HH24:MI:SS';
  SELECT sysdate FROM dual;
  exit
 EOF
 
上記では、[sqlplus -s]オプションを使用しSQL*PLUSへの接続時にバナーを表示させない様にしています。また、[@o11201]と指定している部分に関しては、手元の環境の接続識別子なので実際に実行する場合はご利用環境の接続識別子に合わせて下さい。


(2)作成したスクリプトの実行権限を付与
 [oracle@hoge ~]$ chmod +x hoge.sh

上記を実行しないと実行時に「bash: ./hoge.sh: 許可がありません」のエラーとなり実行できません。


(3)早速スクリプトを実行します。
 [oracle@hoge ~]$ ./hoge.sh
 Session altered.

 SYSDATE
 -----------------
 15-09-26 23:23:52
 

上手く実行できましたね。上記の結果のとおりdual仮想表から現在時刻を引っ張ってくる結果となります。


■検証2

上記の検証1でシェルからDBへ接続可能な事は確認出来ました。
いよいよDBへリスナー経由のセッションを大量生成するスクリプトを作成・実行していきましょう。今回も非常にシンプルな手順となっています。


(1)以下のスクリプトを作成します。
 [oracle@hoge ~]$ vi hoge2.sh

 #!/bin/sh
 for i in {1..1000}
 do
  echo " $i 回目のループです."
  sqlplus -s scott/tiger@o11201 << EOF
  ALTER SESSION SET NLS_DATE_FORMAT = 'RR-MM-DD HH24:MI:SS';
  SELECT sysdate FROM dual;
  exit
 EOF
 done

 
for文を使って検証1で作成したスクリプトの処理を1000回繰り返し実行する様にしただけです。

 

(2)作成したスクリプトに実行権限を付与します。

 [oracle@hoge ~]$ chmod +x hoge2.sh


(3)早速実行してみよう。
 [oracle@hoge ~]$ ./hoge2.sh
  1 回目のループです.
 Session altered.
 SYSDATE
 -----------------
 15-09-26 23:39:07
  2 回目のループです.
 Session altered.
 SYSDATE
 -----------------
 15-09-26 23:39:07
  3 回目のループです.
 Session altered.
 SYSDATE
 -----------------
 15-09-26 23:39:07
 ・・
 ・・
 ・・
 <※長いので省略※>
 ・・
 ・・
 ・・
  998 回目のループです.
 Session altered.
 SYSDATE
 -----------------
 15-09-26 23:42:11
  999 回目のループです.
 Session altered.
 SYSDATE
 -----------------
 15-09-26 23:42:11
  1000 回目のループです.
 Session altered.
 SYSDATE
 -----------------
 15-09-26 23:42:11
 
上手く実行出来ましたね。ちなみに対象の処理は23:39分から23:42分頃にかけて実行されました。

(4)リスナーログを見てみましょう。
 [oracle@hoge trace]$ tail -n 100 listener.log
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23178)) * establish * o11201 * 0
 Sat Sep 26 23:39:07 2015
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23179)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23180)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23181)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23182)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23183)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23184)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23185)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23186)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23187)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23188)) * establish * o11201 * 0
 26-SEP-2015 23:39:07 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23189)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23190)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23191)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23192)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23193)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23194)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23195)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23196)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23197)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23198)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23199)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23200)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23201)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23202)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23203)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23204)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23205)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23206)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23207)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23208)) * establish * o11201 * 0
 26-SEP-2015 23:39:08 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=o11201)(CID=(PROGRAM=sqlplus@hoge)(HOST=hoge)(USER=oracle ))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.2)(PORT=23209)) * establish * o11201 * 0
  
上記出力から該当時間帯にはsqlplus経由で o11201サービスに対し大量の専用サーバ接続が行われている事が確認出来ます。また、今回は接続・切断を大量に繰り返していますので[23178] -> [23179] -> [23180] -> ・・・と順々に多くのエフェメラルポートが使われている状況も確認出来ますね。

 

(5)負荷テスト実行時の負荷状況について簡単に見てみよう

 

SARの結果から大量の接続/切断を繰り返していた時間帯の負荷状況を確認しましょう。該当の処理は「23:39頃から23:42頃」にかけて実行されていましたので「23:40」の出力を該当時間帯としてみていきます。

 
  CPU %user %nice %system %iowait %steal %idle
 17:10:01 1 0.03 0.01 0.52 0.00 0.00 99.43
 17:10:01 2 0.02 0.02 0.18 0.00 0.00 99.77
 17:20:01 all 0.02 0.00 0.59 0.01 0.00 99.38
 17:20:01 0 0.02 0.00 1.14 0.02 0.00 98.82
 17:20:01 1 0.03 0.00 0.49 0.00 0.00 99.48
 17:20:01 2 0.02 0.00 0.19 0.00 0.00 99.80
 23:00:01 all 0.04 0.00 0.72 0.07 0.00 99.16
 23:00:01 0 0.05 0.00 1.36 0.19 0.00 98.39
 23:00:01 1 0.05 0.00 0.58 0.02 0.00 99.35
 23:00:01 2 0.03 0.00 0.26 0.00 0.00 99.71
 23:10:01 all 0.04 0.00 0.70 0.02 0.00 99.24
 23:10:01 0 0.04 0.00 1.34 0.04 0.00 98.58
 23:10:01 1 0.06 0.00 0.59 0.01 0.00 99.35
 23:10:01 2 0.02 0.00 0.22 0.00 0.00 99.75
 23:20:01 all 0.27 0.00 1.35 0.07 0.00 98.32
 23:20:01 0 0.33 0.00 2.26 0.20 0.00 97.21
 23:20:01 1 0.36 0.00 1.16 0.01 0.00 98.47
 23:20:01 2 0.13 0.00 0.70 0.00 0.00 99.17
 23:30:01 all 0.07 0.01 0.84 0.01 0.00 99.07
 23:30:01 0 0.08 0.01 1.67 0.02 0.00 98.22
 23:30:01 1 0.11 0.00 0.65 0.01 0.00 99.24
 23:30:01 2 0.03 0.02 0.26 0.00 0.00 99.68

23:40:01 all 0.40 0.00 1.46 0.02 0.00 98.12
 23:40:01 0 0.48 0.00 1.71 0.03 0.00 97.78
 23:40:01 1 0.51 0.00 2.01 0.01 0.00 97.46
 23:40:01 2 0.21 0.00 0.72 0.02 0.00 99.05
 23:50:01 all 0.08 0.00 0.85 0.01 0.00 99.07
 23:50:01 0 0.10 0.00 1.65 0.01 0.00 98.23
 23:50:01 1 0.11 0.00 0.70 0.00 0.00 99.19
 23:50:01 2 0.03 0.00 0.26 0.00 0.00 99.71
 Average: all 0.11 0.16 1.26 2.13 0.00 96.34
 Average: 0 0.16 0.28 1.98 5.14 0.00 92.44
 Average: 1 0.13 0.05 1.38 1.24 0.00 97.20
 Average: 2 0.06 0.15 0.50 0.19 0.00 99.12

まず該当時間帯のCPUの使用率ですが、23:40頃は他時間帯に比べてほんの僅かにユーザプロセスやシステムによるCPU使用率が上昇していた傾向が読み取れます。メモリ使用率やディスク使用率は殆ど他時間帯との負荷状況の差異が見られなかったので割愛します。

 

次にネットワークの負荷状況を確認します。該当時間帯は他時間帯に比べて1秒間における受送信パケット数やバイト数が多い状況が確認出来ます。

 
  IFACE rxpck/s txpck/s rxbyt/s txbyt/s rxcmp/s txcmp/s rxmcst/s
 17:10:01 eth0 0.00 0.00 0.00 0.00 0.00 0.00 0.00
 17:20:01 lo 0.04 0.04 1.82 1.82 0.00 0.00 0.00
 17:20:01 eth0 0.00 0.00 0.00 0.00 0.00 0.00 0.00
 22:50:01 lo 0.04 0.04 1.76 1.76 0.00 0.00 0.00
 22:50:01 eth0 0.00 0.00 0.00 0.00 0.00 0.00 0.00
 23:10:01 lo 0.47 0.47 27.56 27.56 0.00 0.00 0.00
 23:10:01 eth0 0.00 0.00 0.00 0.00 0.00 0.00 0.00
 23:30:01 lo 1.56 1.56 330.72 330.72 0.00 0.00 0.00
 23:30:01 eth0 0.00 0.00 0.00 0.00 0.00 0.00 0.00

23:40:01 lo 29.04 29.04 7860.97 7860.97 0.00 0.00 0.00
 23:40:01 eth0 0.00 0.00 0.00 0.00 0.00 0.00 0.00
 23:50:01 lo 0.45 0.45 25.28 25.28 0.00 0.00 0.00
 23:50:01 eth0 0.00 0.00 0.00 0.00 0.00 0.00 0.00
 Average: lo 2.88 2.88 878.64 878.64 0.00 0.00 0.00
 Average: eth0 0.00 0.00 0.00 0.00 0.00 0.00 0.00

なお、上記結果の各列の意味は以下です。(一部省略)

 

[IFACE 列] インタフェース名
[rxpck/s 列] 1秒間における受信パケット数
[txpck/s 列] 1秒間における送信パケット数
[rxbyt/s 列] 1秒間における受信バイト数
[txbyt/s 列] 1秒間における送信バイト数