Re:"acquiring the instance startup/shutdown lock" organized by id:wmo6hash at OOW Unconference

期限に間に合いませんでしたが、2012年4月6日 Oracle OpenWorld Unconference presented by JPOUG 開催 | Japan Oracle User Group (JPOUG) での id:wmo6hash さんからの宿題にチャレンジしてみました。

3年前の Unconference の諸橋さんの Oracle Databaseをもっと別の見方をしてみよう〜Oracleホームの下の不思議〜 は最後まで見れませんでしたが、今回は最後まで見れました。

VirtualBox の仮想アプライアンスをダウンロードするだけであとは20分くらいでこのデモ環境を作りました」とはじまり、「あれ、デモになるとなぜかうまくいかないですね」「デモには魔物が潜んでいます」とちょっとアダプタを外されて何かをされていました。
隣にいらした渡部さんが「あれ、計画通りぽいですね」、「たしかに」と私。
そしてデモが再開し、SQL*Plusから「startup force」を実行するとORA-エラーが発生。アラートログには ORA-09968 などが出力されていたと思います。「原因と処置はなんでしょう?」と問いかけがあり、「JPOUGのTシャツ来てる人達には前もって話してたのに宿題やってないの?」と。聴衆から笑いが起こりました。
「OSを再起動する」などの意見が出ていました。諸橋さんは「OSを再起動すると直るので、世の中のほとんどの人はそうしていて、原因は迷宮入りしているのではないか」とのこと。私は「lsof でそのファイルを使っているプロセスを調べる」と答えました。そして、なんと答えが発表されないまま Unconference は終了!

そして翌日にぼんやり考えていて「lkDBNAME にファイルロックをかけてやれば同じような現象が起こるのではないか」と思いついて検証をしてみました。

環境

手元に Linux がないので、Solaris 10 (x86) で試してみました。

下調べ

lkORCL の中を見るとただのテキストファイルですね。

-bash-3.00$ cat /u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL 
DO NOT DELETE THIS FILE!
Oracle Database が起動している状態で fuser で lkORCL を使っているプロセスを調べてみる。fuser はファイルを使っているプロセスを調べるコマンドです。
>|sh|
-bash-3.00# fuser /u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL 
/u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL:      768o     766o     764o     762o     760o     758o     756o     754o     750o     746o     740o     738o

PID の後ろに「o」がついているので、lkORCL をオープンしていることがわかる。PID からプロセス名を調べてみる。

-bash-3.00# ps -f -p 738
     UID   PID  PPID   C    STIME TTY         TIME CMD
  oracle   738     1   0 16:49:33 ?           0:00 ora_pmon_orcl

PMON など Oracle Database のプロセスがオープンしている。

再現手順

Oracle Database をシャットダウンしている状態で lkORCL をファイルロックしてみる。

-bash-3.00$ perl -e 'open(FH,">> /u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL") and flock(FH,2) and sleep(300)'

ファイルロックがかかっていることを確認する。

-bash-3.00# fuser /u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL
/u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL:     4302o

Oracle Database を起動してみる。

-bash-3.00$ sqlplus / as sysdba

SQL*Plus: Release 11.2.0.2.0 Production on Sat Apr 7 19:23:25 2012

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

Connected to an idle instance.

SQL> startup
ORACLE instance started.

Total System Global Area  534462464 bytes
Fixed Size                  2225832 bytes
Variable Size             377489752 bytes
Database Buffers          150994944 bytes
Redo Buffers                3751936 bytes
ORA-01102: cannot mount database in EXCLUSIVE mode


SQL> startup force
ORACLE instance started.

Total System Global Area  534462464 bytes
Fixed Size                  2225832 bytes
Variable Size             377489752 bytes
Database Buffers          150994944 bytes
Redo Buffers                3751936 bytes
ORA-01102: cannot mount database in EXCLUSIVE mode

私の記憶が確かなら昨日のデモと似たようなエラーが出た。

アラートログを見てみる。

-bash-3.00$ tail -10 /u01/app/oracle/diag/rdbms/orcl/orcl/trace/alert_orcl.log 
DISM started, OS id=4406
ORACLE_BASE from environment = /u01/app/oracle
Sat Apr 07 19:23:39 2012
ALTER DATABASE   MOUNT
sculkget: failed to lock /u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL exclusive
sculkget: lock held by PID: 4302
ORA-09968: unable to lock file
Solaris-AMD64 Error: 11: Resource temporarily unavailable
Additional information: 4302
ORA-1102 signalled during: ALTER DATABASE   MOUNT...

これはたぶん昨日のデモで出てたメッセージと似た感じだ。よく見ると「sculkget: lock held by PID: 4302」ってロックをかけているプロセスの PID が出てますね。ちょっと昨日のセッションにどう出てたか覚えてませんが。

「Ctrl+C」でファイルロックをとめて、

$ perl -e 'open(IN,">> /u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL") and flock(IN,2) and sleep(10000)'
^C
-bash-3.00$ 

Oracle Database を起動してみる。

SQL> startup
ORA-01081: cannot start already-running ORACLE - shut it down first
SQL> shutdown immediate
ORA-01507: database not mounted


ORACLE instance shut down.
SQL> startup
ORACLE instance started.

Total System Global Area  534462464 bytes
Fixed Size                  2225832 bytes
Variable Size             377489752 bytes
Database Buffers          150994944 bytes
Redo Buffers                3751936 bytes
Database mounted.
Database opened.

結論

  • $ORACLE_HOME/dbs/lkDBNAME をファイルロックしているプロセスがあると、ORA-09968 や ORA-1102 が発生してインスタンスを起動できない。
  • ファイルロックするプロセスを停止するなりして、ロックを解放すると解決する。

ということではないかと思います。

おまけ

インスタンス起動時に何をしているのか調べてみた。

startup nomount して、

SQL> startup nomount
ORACLE instance started.

Total System Global Area  534462464 bytes
Fixed Size                  2225832 bytes
Variable Size             373295448 bytes
Database Buffers          155189248 bytes
Redo Buffers                3751936 bytes

lkORCL をファイルロックして、

-bash-3.00$ perl -e 'open(FH,">> /u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL") and flock(FH,2) and sleep(300)'

ここで、truss をしかけて、

-bash-3.00# pgrep -f ora_|while read LINE
do truss -aelfdE -vall -o ${LINE}.log -p ${LINE} &
done

mount する。

SQL> alter database mount;
alter database mount
*
ERROR at line 1:
ORA-01102: cannot mount database in EXCLUSIVE mode

truss の出力結果を確認すると、なんと DBWR が lkORCL をオープンしてファイルロックをとろうとしていた。

-bash-3.00$ less 1087.log 
Base time stamp:  1333805818.2811  [ Sat Apr  7 22:36:58 JST 2012 ]
1087/1:         psargs: ora_dbw0_orcl
(中略)
1087/1:         17.9051  0.0000 open("/u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL", O_RDWR|O_CREAT|O_EXCL, 0660) Err#17 EEXIST
1087/1:         17.9052  0.0000 open("/u01/app/oracle/product/11.2.0/dbhome_1/dbs/lkORCL", O_RDWR) = 17
1087/1:         17.9053  0.0000 fcntl(17, F_SETFD, 0x00000001)                  = 0
1087/1:         17.9053  0.0000 fcntl(17, F_SETLK, 0xFFFFFD7FFFDFE1A0)          Err#11 EAGAIN
1087/1:                 typ=F_WRLCK  whence=SEEK_SET start=0     len=0     sys=0  pid=1182
(中略)
1087/1:         17.9097  0.0000 open("/u01/app/oracle/diag/rdbms/orcl/orcl/trace/alert_orcl.log", O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE, 0660) = 17
1087/1:         17.9098  0.0000 fcntl(17, F_SETFD, 0x00000001)                  = 0

備忘録

  • Perl でのファイルロックのかけ方はもっとモダンな方法がある気がするがその辺はまた時間があればやる。
  • ファイルロックのシステムコールについても理解が浅いがその辺はまた時間があればやる。当たり前だが、OSによって実装は異なると思われる。
  • エラーメッセージの内容がセッションと少し違うような気もする。
  • Linux だと同じ手順でインスタンスを起動できてしまうと同僚から聞いた。Linux で起動時に lkDBNAME にファイルロックをかけているシステムコールを調べて、そのシステムコールをそのまま使って(Perl で syscall 使うなどして)ファイルロックをかければ上記と同じエラーが発生して起動に失敗するのではないかと思う。時間があるときに試す。


追記(2012/04/14):
Linux でも事象を再現することができたので追記します。

$ uname -r
2.6.18-194.el5xen
$ cat /etc/issue
Enterprise Linux Enterprise Linux Server release 5.5 (Carthage)
Kernel \r on an \m
$ sqlplus / as sysdba
SQL> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bi
PL/SQL Release 10.2.0.5.0 - Production
CORE    10.2.0.5.0      Production
TNS for Linux: Version 10.2.0.5.0 - Production
NLSRTL Version 10.2.0.5.0 - Production

起動時に DBWR がファイルロックをかけるのに使っているシステムコールを確認する。

$ ps -ef|grep [d]bw
oracle   24881     1  0 14:53 ?        00:00:00 ora_dbw0_orcl
$ strace -o strace_dbwr.log -p 24881 &
$ tail -f strace_dbwr.log 
(中略)
open("/opt/app/oracle/oracle/product/10.2.0/db_1/dbs/lkORCL", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
open("/opt/app/oracle/oracle/product/10.2.0/db_1/dbs/lkORCL", O_RDWR) = 15
umask(022)                              = 0
fcntl(15, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
fcntl(15, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0

インスタンスが停止している状態で、同じようにファイルロックをかけて、

$ perl -MFcntl -e '$locked=pack("ssL",Fcntl::F_WRLCK,q/SEEK_SET/,0);open(FH,">> /opt/app/oracle/oracle/product/10.2.0/db_1/dbs/lkORCL") and fcntl(FH, F_SETLK, $locked) and sleep(300)'

ロックがかかっているぽいことを確認して、

# fuser /opt/app/oracle/oracle/product/10.2.0/db_1/dbs/lkORCL
/opt/app/oracle/oracle/product/10.2.0/db_1/dbs/lkORCL: 25398

インスタンスを起動すると、

$ sqlplus / as sysdba

SQL*Plus: Release 10.2.0.5.0 - Production on Sat Apr 14 15:59:59 2012

Copyright (c) 1982, 2010, Oracle.  All Rights Reserved.

Connected to an idle instance.

SQL> startup
ORACLE instance started.

Total System Global Area  612368384 bytes
Fixed Size                  2098208 bytes
Variable Size             218106848 bytes
Database Buffers          385875968 bytes
Redo Buffers                6287360 bytes
ORA-01102: cannot mount database in EXCLUSIVE mode


SQL> startup force
ORACLE instance started.

Total System Global Area  612368384 bytes
Fixed Size                  2098208 bytes
Variable Size             218106848 bytes
Database Buffers          385875968 bytes
Redo Buffers                6287360 bytes
ORA-01102: cannot mount database in EXCLUSIVE mode

事象再現に成功。
アラートログを確認すると、

ALTER DATABASE   MOUNT
Sat Apr 14 16:00:02 JST 2012
sculkget: failed to lock /opt/app/oracle/oracle/product/10.2.0/db_1/dbs/lkORCL exclusive
sculkget: lock held by PID: 25398
Sat Apr 14 16:00:02 JST 2012
ORA-09968: unable to lock file
Linux-x86_64 Error: 11: Resource temporarily unavailable
Additional information: 25398
Sat Apr 14 16:00:02 JST 2012
ORA-1102 signalled during: ALTER DATABASE   MOUNT...

ORA-09968 が出ています。

「Ctrl+c」でロックを外して、

$ perl -MFcntl -e '$locked=pack("ssL",Fcntl::F_WRLCK,q/SEEK_SET/,0);open(FH,">> /opt/app/oracle/oracle/product/10.2.0/db_1/dbs/lkORCL") and fcntl(FH, F_SETLK, $locked) and sleep(300)'
C^

インスタンスを起動してみると、

SQL> shutdown immediate
ORA-01507: database not mounted


ORACLE instance shut down.
SQL> startup
ORACLE instance started.

Total System Global Area  612368384 bytes
Fixed Size                  2098208 bytes
Variable Size             218106848 bytes
Database Buffers          385875968 bytes
Redo Buffers                6287360 bytes
Database mounted.
Database opened.

起動成功。
ということで、Linux でも再現することができました。


追記(2012/11/13):
少なくとも 11.2.0.2 ではロックファイルの命名規則は lk ではなく lk のもよう。

$ sqlplus / as sysdba
SQL> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
PL/SQL Release 11.2.0.2.0 - Production
CORE    11.2.0.2.0      Production
TNS for Linux: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production

SQL> 
SQL> alter system set db_unique_name = ORCL2 scope=spfile; 
SQL> shutdown immediate
SQL> !ls -l
total 28
-rw-rw---- 1 oracle oracle 1544 Oct  2  2010 hc_DBUA0.dat
-rw-rw---- 1 oracle oracle 1544 Nov 13 01:51 hc_orcl.dat
-rw-r--r-- 1 oracle oracle 2851 May 15  2009 init.ora
-rw-r----- 1 oracle oracle  621 Oct  2  2010 initorcl.ora
-rw-r----- 1 oracle oracle   24 Oct  2  2010 lkORCL
-rw-r----- 1 oracle oracle 1536 Oct 14 20:44 orapworcl
-rw-r----- 1 oracle oracle 3584 Nov 13 01:51 spfileorcl.ora
SQL> startup
SQL> !ls -l
total 32
-rw-rw---- 1 oracle oracle 1544 Oct  2  2010 hc_DBUA0.dat
-rw-rw---- 1 oracle oracle 1544 Nov 13 01:52 hc_orcl.dat
-rw-r--r-- 1 oracle oracle 2851 May 15  2009 init.ora
-rw-r----- 1 oracle oracle  621 Oct  2  2010 initorcl.ora
-rw-r----- 1 oracle oracle   24 Oct  2  2010 lkORCL
-rw-rw---- 1 oracle oracle   24 Nov 13 01:52 lkORCL2
-rw-r----- 1 oracle oracle 1536 Oct 14 20:44 orapworcl
-rw-r----- 1 oracle oracle 3584 Nov 13 01:52 spfileorcl.ora
SQL> exit
$ su -
# cd /home/oracle/app/oracle/product/11.2.0/dbhome_2/dbs/
# lsof lkORCL 
# lsof lkORCL2 
COMMAND  PID   USER   FD   TYPE DEVICE SIZE    NODE NAME
oracle  3147 oracle   14uR  REG   3,65   24 1769595 lkORCL2
oracle  3149 oracle   13uR  REG   3,65   24 1769595 lkORCL2
oracle  3155 oracle   17uR  REG   3,65   24 1769595 lkORCL2
oracle  3159 oracle   17uR  REG   3,65   24 1769595 lkORCL2
oracle  3163 oracle   19uR  REG   3,65   24 1769595 lkORCL2
oracle  3165 oracle   17uR  REG   3,65   24 1769595 lkORCL2
oracle  3167 oracle   17uR  REG   3,65   24 1769595 lkORCL2
oracle  3169 oracle   17uR  REG   3,65   24 1769595 lkORCL2
oracle  3171 oracle   17uR  REG   3,65   24 1769595 lkORCL2
oracle  3173 oracle   17uR  REG   3,65   24 1769595 lkORCL2
oracle  3175 oracle   17uR  REG   3,65   24 1769595 lkORCL2
oracle  3177 oracle   17uR  REG   3,65   24 1769595 lkORCL2