期限に間に合いませんでしたが、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) で試してみました。
- VirtualBox 4.0 for Windows hosts (VirtualBox-4.0.0-69151-Win.exe)
- Oracle Solaris 10 (x86)
- Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
下調べ
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
参考
- 最前線UNIXのカーネル P.264 8.2.6 ファイルのロック
- 詳解 Linuxカーネル 第3版 P.545 12.7 ファイルロック
- http://docs.oracle.com/cd/E19253-01/819-1210/truss-1/index.html
備忘録
- Perl でのファイルロックのかけ方はもっとモダンな方法がある気がするがその辺はまた時間があればやる。
- Perlクックブック〈VOLUME1〉 P.346 レシピ7.18 ファイルをロックする
- プログラミングPerl〈VOLUME1〉 P.490 16.2.1 ファイルのロック
- ファイルロックのシステムコールについても理解が浅いがその辺はまた時間があればやる。当たり前だが、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
$ 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
