RAC One Node の検証 その６
＜RAC One Node の検証 その６＞
ペンネーム : ダーリン
前回はサーバ停止による RAC One Node のフェイルオーバーをシミュ
レートしてみました。インスタンスが稼働している側のサーバが停
止すると、もう一方のサーバ側で自動的にインスタンスが起動する
ことを確認しました。その際の注意点としては起動するサーバが変
わってもインスタンス名が ” 変わらない ” ことです。Omotion で
切り替えたときはインスタンス名が ” 変わる ” ので間違えないよ
うに。
サーバとインスタンスの関係は固定的ではなく、どのサーバでなん
という名前のインスタンスが起動しているかは決まっていないとい
うことですねぇ。
さて今回は障害発生により、フェイルオーバーした時に発生するサー
ビス停止時間（データベースに接続できない時間）がどのくらいに
なるかを確認します。いわゆるダウンタイムです。
では、今回もサーバ(ノード１側)をシャットダウンします。
( grid ユーザで実施)
------------------------------------------------------------
NAME TARGET STATE SERVER STATE_DETAILS
------------------------------------------------------------
Cluster Resources
------------------------------------------------------------
ora.oel55sv01.vip
1 ONLINE INTERMEDIATE oel55sv02 FAILED OVER
ora.oel55sv02.vip
1 ONLINE ONLINE oel55sv02
ora.ron.db
1 ONLINE ONLINE oel55sv02 Open
ora.ron.srvron1.svc
1 ONLINE ONLINE oel55sv02
------------------------------------------------------------
今回も無事フェイルオーバーできました。
“＜RAC One Node の検証 その２＞” で行った検証と同様に新規接続
の状態を確認してみた結果、以下のようになりました。
前回の検証結果を踏まえて今回はホスト名を追加しています。
インスタンス名だけではどちらのノードに接続しているのか判断で
きないということが分かったので。
TIME INSTANCE HOSTNAME STATUS
-------- -------- --------- ------
20:06:02 RON_1 oel55sv01 OPEN <<< ノード１ shutdown 開始
20:06:07 RON_1 oel55sv01 OPEN
20:06:12 RON_1 oel55sv01 OPEN
20:06:17 RON_1 oel55sv01 OPEN
20:06:22 RON_1 oel55sv01 OPEN
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません
:
<<
:
ERROR:
ORA-12528: TNS:リスナー:
該当するインスタンスはすべて、新規接続をブロックしています
:
<<
:
ERROR:
ORA-01033: Oracleの初期化またはシャットダウン中です。 プロセスID: 0
セッションID: 0、シリアル番号: 0
:
<<
:
20:08:36 RON_1 oel55sv02 OPEN <<< ノード２へ再接続
20:08:42 RON_1 oel55sv02 OPEN
20:08:49 RON_1 oel55sv02 OPEN
20:08:55 RON_1 oel55sv02 OPEN
20:09:00 RON_1 oel55sv02 OPEN
20:09:06 RON_1 oel55sv02 OPEN
20:09:11 RON_1 oel55sv02 OPEN
20:09:16 RON_1 oel55sv02 OPEN
20:09:21 RON_1 oel55sv02 OPEN
20:09:26 RON_1 oel55sv02 OPEN
20:09:32 RON_1 oel55sv02 OPEN
20:09:37 RON_1 oel55sv02 OPEN
---------- -------- ------
この結果から 20:06:22 から 20:08:36 までの約 2 分 14 秒間、
新規接続ができない状態でした。
その内訳を各種ログと付き合わせてみると、、、
ノード１(oel55sv01) のsyslog：
------------------------------------------------------------
Aug 25 20:06:03 oel55sv01 shutdown[15954]: shutting down for system halt
Aug 25 20:06:04 oel55sv01 pcscd: winscard.c:304:SCardConnect() Reader E-Gate 0 0 Not Found
Aug 25 20:06:06 oel55sv01 modclusterd: shutdown succeeded
Aug 25 20:06:08 oel55sv01 ricci: shutdown succeeded
Aug 25 20:06:08 oel55sv01 smartd[2025]: smartd received signal 15: Terminated
Aug 25 20:06:08 oel55sv01 smartd[2025]: smartd is exiting (exit status 0)
Aug 25 20:06:10 oel55sv01 avahi-daemon[1846]: Got SIGTERM, quitting.
:
:
Aug 25 20:06:20 oel55sv01 kernel: Kernel logging (proc) stopped.
Aug 25 20:06:20 oel55sv01 kernel: Kernel log daemon terminating.
Aug 25 20:06:21 oel55sv01 exiting on signal 15
------------------------------------------------------------
まずは、ノード1側の syslog です。ここからは OS が停止するまで
に 18 秒程度かかっていることが確認できています。時刻的には、
この間はまだ接続できている状態ですね。
# 厳密には OS が停止する前に Oracle が停止しているはずですが。
続いて、ノード２側のクラスタ関連のログを見てみます。
ノード２ (oel55sv02) の ocssd.log:
------------------------------------------------------------ 2010-08-25 20:06:37.878: [ CSSD][2845830032]clssnmPollingThread: node oel55sv01 (1) at 50% heartbeat fatal, removal in 14.730 seconds 2010-08-25 20:06:37.878: [ CSSD][2845830032]clssnmPollingThread: node oel55sv01 (1) is impending reconfig, flag 394254, misstime 15270 2010-08-25 20:06:37.878: [ CSSD][2845830032]clssnmPollingThread: local diskTimeout set to 27000 ms, remote disk timeout set to 27000, impending reconfig status(1) 2010-08-25 20:06:37.909: [ CSSD][2941807504]clssnmReadDskHeartbeat:manual shutdown of nodename oel55sv01, nodenum 1 2010-08-25 20:06:38.882: [ CSSD][2845830032]clssnmPollingThread: Removal started for node oel55sv01 (1), flags 0x6140e, state 3, wt4c 0 2010-08-25 20:06:38.882: [ CSSD][2845830032]clssnmDiscHelper: oel55sv01, node(1) connection failed, endp (0x331), probe((nil)), ninf->endp 0x331 2010-08-25 20:06:38.882: [ CSSD][2845830032]clssnmDiscHelper: node 1 clean up, endp (0x331), init state 5, cur state 5 ------------------------------------------------------------
上記の 20:06:37.878 の時点でハートビートの失敗がノード切り離
しまでの時間の 50% 経過しています。ということは残り時間と同じ
時間分前にさかのぼれば、ハートビートの失敗が始まった時刻と考
えられます。
20:06:37.878 – 14.730秒 = 20:06:23.148
つまり、ほぼノード１がダウンした直後からハートビートが失敗し
始めていますね。
# 実はノード２(oel55sv02)の時刻が2秒ほど進んでいました。
# 悪しからず。
また、20:06:37.878 の 14.730 秒後に切り離されると思ったのです
が、実はその約 1 秒後( 2010-08-25 20:06:38.882 )にノード１の
切り離しが始まっています。
ノード２の別のログ(crsd.log)では、このタイミングでノードの切
替え処理の開始が記録されていました。
ノード２ (oel55sv02) の crsd.log:
------------------------------------------------------------ 2010-08-25 20:06:38.912: [ CRSCCL][2669419408]Reconfig event received by clssgsgrpstat 2010-08-25 20:06:38.912: [ CRSCCL][2669419408]cclGetMemberData called 2010-08-25 20:06:38.912: [ CRSCCL][2669419408]Disconnecting connection to member 1 node 10.0.0.101. : 2010-08-25 20:06:39.867: [ CRSSE][2604608400] Master Change Event; New Master Node ID:2 This Node's ID:2 2010-08-25 20:06:39.867: [ CRSPE][2606709648] PE Role|State Update: old role [SLAVE] new [MASTER]; old state [Running] new [Configuring] 2010-08-25 20:06:39.867: [ CRSPE][2606709648] PE MASTER NAME: oel55sv02 2010-08-25 20:06:39.867: [ CRSPE][2606709648] Starting to read configuration ------------------------------------------------------------
“Disconnecting connection to member 1 node 10.0.0.101.”
ちなみに、上記の “10.0.0.101” は今回ノード１側のインターコネ
クト用 NIC に設定した IP アドレスです。
“Master Change Event; New Master Node ID:2 This Node’s ID:2”
マスターノードを “2” に変更しているということでしょう。
上記はクラスタの挙動をいくつかのログでトレースした結果です。
続いて、Oracle データベースの様子をノード２側のアラートログか
らみてみます。
ノード２ (oel55sv02) の alert_RON_1.log:
------------------------------------------------------------
Wed Aug 25 20:06:59 2010
Starting ORACLE instance (normal)
:
Wed Aug 25 20:07:44 2010
ALTER DATABASE MOUNT
:
Wed Aug 25 20:07:54 2010
Database mounted in Shared Mode (CLUSTER_DATABASE=TRUE)
Lost write protection disabled
Completed: ALTER DATABASE MOUNT
ALTER DATABASE OPEN
:
Wed Aug 25 20:08:34 2010
Completed: ALTER DATABASE OPEN
:
Wed Aug 25 20:08:39 2010
ALTER SYSTEM SET service_names='srvRON1' SCOPE=MEMORY SID='RON_1';
------------------------------------------------------------
Oracleデータベースはというと、、、
20:06:59 に起動開始し、 20:08:34 にオープン。 20:08:39 にサービス名の登録が行われています。
今回再接続された時刻は 20:08:36 なので、データベースがオー
プンした直後に接続したということですね。
切替前に接続できた最後の時刻が 20:06:22 で、切替後に再接続
できた時刻が 20:08:36 なので、その間約 2 分 14 秒 がデータ
ベースにアクセスできない時間帯でした。
また、この時間の内訳の大半は以下のようになっています。
・ノード切り離しまでの待機時間: 20:06:22 ～ 20:06:37 = 0:15
・データベースの起動時間 : 20:06:59 ～ 20:08:34 = 1:35
上記の他、ノード切り離しからデータベース起動までの間は、主に、
CRS へのリソースの登録や、各種リソース(仮想IPやリスナ)の起動
が行われているようです。
たとえば、、、こんな感じです。
2010-08-25 20:06:43.476: 'ora.oel55sv01.vip'('oel55sv02')の起動を試行しています
2010-08-25 20:06:43.487: 'ora.scan1.vip'('oel55sv02')の起動を試行しています
2010-08-25 20:06:46.626: 'ora.scan1.vip'('oel55sv02')の起動が成功しました
2010-08-25 20:06:46.631: 'ora.oel55sv01.vip'('oel55sv02')の起動が成功しました
2010-08-25 20:06:46.744: 'ora.LISTENER_SCAN1.lsnr'('oel55sv02')の起動を試行しています
2010-08-25 20:06:47.299: 'ora.LISTENER_SCAN1.lsnr'('oel55sv02')の起動が成功しました
以下は、DBの起動とサービス登録。
2010-08-25 20:06:47.335: 'ora.ron.db'('oel55sv02')の起動を試行しています
2010-08-25 20:08:35.657: 'ora.ron.db'('oel55sv02')の起動が成功しました
2010-08-25 20:08:36.108: 'ora.ron.srvron1.svc'('oel55sv02')の起動を試行しています
2010-08-25 20:08:40.916: 'ora.ron.srvron1.svc'('oel55sv02')の起動が成功しました
さて、”＜RAC One Node の検証 その２＞” で行った Omotion によ
るノード切替では、新規接続ができなくなる時間は 30 秒強でした。
サービス切替のタイミングなどで一時的に接続できなくなるものの
切替先のインスタンスをあらかじめ起動しておくため比較的短時間
で接続先を切り替えることができるためです。
一方、今回のように障害が発生した場合、RAC One Node では切替先
のノードにデータベースが立ち上がっていないため、データベース
が起動するまでの時間がまるまるサービス停止時間になってしまい
ます。
これを回避したいのであれば、( One Node ではない ) RAC の導入
を検討する必要があるかもしれません。要はこの 2 分間の停止が与
えるビジネスインパクト次第ということでしょう。
さて、次回は別のパターンで障害をシミュレートしてみます。