« CentOS5.5のVirtualBox4.0のWindowsXP ProfessionalのVirtualPC2007のWindowsXPのIE7(長過ぎw) | トップページ | shutdown immeidateしない、ほかの理由に遭遇! #2 »

2011年2月 8日 (火)

shutdown immeidateしない、ほかの理由に遭遇!

別途検証して別エントリにする予定だけど(遠征先で時間ないので…)、この状態でshutdown immeidateが待機するとshutdown timeoutしないというのも特徴みたい…

Oracleのバージョンは11g R2 11.2.0.1.0 for Linux (32bit)だけどUnix/Linux系なら発生するよ、きっと。

そういえば、以前こんなエントリ書いてましたっけ「shutdown timeout

では、早速再現テスト。

まず、SQL*Plusを起動、SYSユーザに接続してOracleインスタンスを起動します…

[oracle@leaffish ˜]$ sqlplus /nolog

SQL*Plus: Release 11.2.0.1.0 Production on 火 2月 8 00:46:11 2011

Copyright (c) 1982, 2009, Oracle. All rights reserved.

00:46:11 > conn / as sysdba
アイドル・インスタンスに接続しました。
00:46:16 SYS> startup
ORACLEインスタンスが起動しました。

Total System Global Area 422670336 bytes
Fixed Size 1336960 bytes
Variable Size 373295488 bytes
Database Buffers 41943040 bytes
Redo Buffers 6094848 bytes
データベースがマウントされました。
データベースがオープンされました。
00:47:17 SYS>


別端末でSQL*Plusを起動してSYSTEMユーザまたはSYSユーザに接続.
(別途詳しく検証する予定だけど、今のところSYSTEM/SYSユーザ以外では発生してないので)

[oracle@leaffish ˜]$ 
[oracle@leaffish ˜]$ sqlplus /nolog

SQL*Plus: Release 11.2.0.1.0 Production on 火 2月 8 00:50:18 2011

Copyright (c) 1982, 2009, Oracle. All rights reserved.

00:50:18 > conn system
パスワードを入力してください:
接続されました。
00:50:23 SYSTEM>


次にOracleを起動したSQL*PlusのSYSユーザでshutdown immeidateを発行する…

00:51:22 SYS> shutdown immediate
データベースがクローズされました。
データベースがディスマウントされました。
ORACLEインスタンスがシャットダウンされました。
00:51:34 SYS>


この状態だとOracleインスタンスは正常にshutdown immeidateで停止できる。あたりまえだけど。

では、再現テストですよん。

では次のパターンはどうか?

前述した手順と同じく、SYSで接続してOracleインスタンスを起動する…

[oracle@leaffish ˜]$ sqlplus /nolog

SQL*Plus: Release 11.2.0.1.0 Production on 火 2月 8 00:54:47 2011

Copyright (c) 1982, 2009, Oracle. All rights reserved.

00:54:47 > conn / as sysdba
アイドル・インスタンスに接続しました。
00:54:52 SYS> startup
ORACLEインスタンスが起動しました。

Total System Global Area 422670336 bytes
Fixed Size 1336960 bytes
Variable Size 373295488 bytes
Database Buffers 41943040 bytes
Redo Buffers 6094848 bytes
データベースがマウントされました。
データベースがオープンされました。
00:55:46 SYS>


前述した手順と同様に、別端末でSQL*Plusを起動し、SYSTEMユーザ(SYSユーザでもいいよ)へ接続する。
さらに、! (SQL*Plusのhost command)でshellに入っておく…。ここがポイント

[oracle@leaffish ˜]$ 
[oracle@leaffish ˜]$
[oracle@leaffish ˜]$ sqlplus /nolog

SQL*Plus: Release 11.2.0.1.0 Production on 火 2月 8 01:01:42 2011

Copyright (c) 1982, 2009, Oracle. All rights reserved.

01:01:42 > conn system
パスワードを入力してください:
接続されました。
01:01:47 SYSTEM> !
[oracle@leaffish ˜]$


shutdow immeidateの待機を再現させますよー、Oracleインスタンスを起動したSQL*PlusのSYSユーザでshutdown immeidate文を発行する…

01:03:04 SYS> 
01:03:05 SYS> shutdown immediate


いつまでたってもOracleインスタンスは停止しない。この例では載せていないがマニュアルに記載されているshutdown timeoutも1時間たっても2時間たっても発生しないようだ…(別途検証予定)


アラートログを確認してみると…5分毎に、”SHUTDOWN: Active processes prevent shutdown operation”というログを出力し続けてる…

Tue Feb 08 01:03:07 2011
Shutting down instance (immediate)
Shutting down instance: further logons disabled
Stopping background process QMNC
Stopping background process MMNL
Stopping background process MMON
License high water mark = 2
All dispatchers and shared servers shutdown
Tue Feb 08 01:08:17 2011
SHUTDOWN: Active processes prevent shutdown operation
Tue Feb 08 01:13:24 2011
SHUTDOWN: Active processes prevent shutdown operation
Tue Feb 08 01:18:31 2011
SHUTDOWN: Active processes prevent shutdown operation
Tue Feb 08 01:23:37 2011
SHUTDOWN: Active processes prevent shutdown operation
Tue Feb 08 01:28:43 2011
SHUTDOWN: Active processes prevent shutdown operation


プロセスのトレースファイルで最新のものでファイルサイズが増えつつけているものがある…
tailでのぞいてみると…

PID=3542のOSプロセスをkillできずにループしているように見える…

[oracle@leaffish trace]$ ll -lrt

・・・中略・・・

-rw-r----- 1 oracle oinstall 61 2月 8 01:00 discus_mman_3483.trm
-rw-r----- 1 oracle oinstall 863 2月 8 01:00 discus_mman_3483.trc
-rw-r----- 1 oracle oinstall 61 2月 8 01:00 discus_dbrm_3477.trm
-rw-r----- 1 oracle oinstall 904 2月 8 01:00 discus_dbrm_3477.trc
-rw-r----- 1 oracle oinstall 45 2月 8 01:01 discus_ora_3539.trm
-rw-r----- 1 oracle oinstall 669 2月 8 01:01 discus_ora_3539.trc
-rw-r----- 1 oracle oinstall 235323 2月 8 01:08 alert_discus.log
-rw-r----- 1 oracle oinstall 6420 2月 8 01:12 discus_ora_3513.trm
-rw-r----- 1 oracle oinstall 60565 2月 8 01:12 discus_ora_3513.trc
[oracle@leaffish trace]$
[oracle@leaffish trace]$ tail -f discus_ora_3513.trc
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:15.641
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:16.663
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:17.678
ksukia: Starting kill, flags = 1
ksukia: Attempt 119 to re-kill process OS PID=3542.
ksukia: killed 1 out of 1 processes.

*** 2011-02-08 01:13:18.699
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:19.709
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:20.735
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:21.750
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:22.756
ksukia: Starting kill, flags = 1
ksukia: Attempt 120 to re-kill process OS PID=3542.
ksukia: killed 1 out of 1 processes.

*** 2011-02-08 01:13:23.779
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:24.790
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

*** 2011-02-08 01:13:25.821
ksukia: Starting kill, flags = 1
ksukia: killed 0 out of 1 processes.

[oracle@leaffish trace]$

killできないと繰り返しログに吐かれているプロセス PID=3542とは何者?…
psとpstreeコマンドでみてみると…

SQL*Plusの!(host command)でshellに入る生成されるプロセスらしい…、このプロセスSYSTEMユーザやSYSユーザ以外接続している場合はなぜか今のところ生成されいないように見える…

この<defunct>なプロセスは何屋さん? shutdown immediateをimmediateじゃない状態にするのは大量のundoデータだけじゃないのね〜><

それもSQL*Plusの!(host command)は便利なので、私も多用していまして、ついつい、SQL*Plusに接続して、!でshellに入って、SQL*Plusから入ったのを忘れてさらに、SQL*Plus起動して、!でshellに入って…なんてことやってしまうことは多々あります。><

これが原因で、shutdown immeidateが待機させられるなんて〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜><。

[oracle@leaffish ˜]$ ps -ef | grep 3542
oracle 3542 3541 0 01:01 ? 00:00:00 [oracle] <defunct>
oracle 3785 3056 0 01:24 pts/5 00:00:00 grep 3542
[oracle@leaffish ˜]$
[oracle@leaffish ˜]$ pstree -up oracle

・・・中略・・・

gnome-terminal(2806)─┬─bash(2812)───sqlplus(3398)───oracle(3513)
├─bash(2909)───tail(3055)
├─bash(2937)
├─bash(3031)───sqlplus(3541)─┬─bash(3543)
│ └─oracle(3542)
├─bash(3056)───pstree(3772)
├─gnome-pty-helpe(2811)
└─{gnome-terminal}(2813)

・・・以下略・・・


もう少し検証してみましょう! 

shellからだけexitしてみるも……Oracleはまだ停止しない…

01:01:42 > conn system
パスワードを入力してください:
接続されました。
01:01:47 SYSTEM> !
[oracle@leaffish ˜]$ exit
exit

01:30:56 SYSTEM>


じゃ、SQL*Plusからもexitしよう

01:01:42 > conn system
パスワードを入力してください:
接続されました。
01:01:47 SYSTEM> !
[oracle@leaffish ˜]$ exit
exit

01:30:56 SYSTEM> exit
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing optionsとの接続が切断されました。
[oracle@leaffish ˜]$


次の瞬間……

データベースがクローズされました。
データベースがディスマウントされました。
ORACLEインスタンスがシャットダウンされました。
01:32:10 SYS>

なんだと〜〜〜〜〜〜〜〜。いつからこーなんだー。 怖くてSQL*Plusから!(host command)でshellに入れないじゃないか〜〜〜><


次回へつづく。


shutdown immeidateしない、ほかの理由に遭遇!
shutdown immeidateしない、ほかの理由に遭遇! #2
shutdown immeidateしない、ほかの理由に遭遇! #3
shutdown immeidateしない、ほかの理由に遭遇! おまけ

|

トラックバック

この記事のトラックバックURL:
http://app.cocolog-nifty.com/t/trackback/106341/50809411

この記事へのトラックバック一覧です: shutdown immeidateしない、ほかの理由に遭遇!:

コメント

コメントを書く