今週の名言
「すべて商売は売りて喜び、買いて喜ぶようにすべし。売りて喜び、買いて喜ばざるは道にあらず。貸借の道もまた貸して喜び、借りて喜ばざるは道にあらず。」
二宮尊徳
今回もOracle Net関連
リスナーは重要
Oracleデータベースはよほどのことがない限り、クライアントからネットワーク経由で接続して使います。従って接続に伴う問題は非常に深刻です。
Oracleサポートの現場でも、接続障害の解決に求められる緊急度は特に高いようです。
Oracle Databaseで接続障害が発生した際の調査手法
最近のWebアプリケーションは、コネクションプールにより常時セッションを張っていることが多いので、リスナーは１日１回早朝等に再接続をするときだけ起動していればよいという考え方もあります。
しかし、データベースが正常に稼働していたとしても、リスナーが起動していなければ新たな接続すらできないので、リスナー・プロセスの起動とそれを監視することはやはり必要です。
インスタンスはリスナーに登録されなければならない
起動されたインスタンス（データベース）は、リスナーにサービスとして登録されていなければなりません。
$ lsnrctl status
LSNRCTL for Linux: Version 12.1.0.2.0 - Production on 05-7月 -2015 16:01:58
Copyright (c) 1991, 2014, Oracle. All rights reserved.
(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))に接続中
リスナーのステータス
------------------------
別名 LISTENER
バージョン TNSLSNR for Linux: Version 12.1.0.2.0 - Production
開始日 05-7月 -2015 14:54:43
稼働時間 0 日 1 時間 7 分 15 秒
トレース・レベル off
セキュリティ ON: Local OS Authentication
SNMP OFF
パラメータ・ファイル /u01/app/oracle/product/12.1.0.2/db_1/network/admin/listener.ora
ログ・ファイル /u01/app/oracle/diag/tnslsnr/oraclelinux6/listener/alert/log.xml
リスニング・エンドポイントのサマリー...
(DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=tcps)(HOST=oraclelinux6.onefact.jp)(PORT=5500))(Security=(my_wallet_directory=/u01/app/oracle/admin/ora12c/xdb_wallet))(Presentation=HTTP)(Session=RAW))
サービスのサマリー...
サービス"ora12c"には、1件のインスタンスがあります。
インスタンス"ora12c"、状態READYには、このサービスに対する1件のハンドラがあります...
サービス"ora12cXDB"には、1件のインスタンスがあります。
インスタンス"ora12c"、状態READYには、このサービスに対する1件のハンドラがあります...
コマンドは正常に終了しました。
Oracle 12cからサービス登録が変わった？
マニュアルを見ていて、11gと12cの微妙な違いに気がつきました。
Oracle® Database Net Services管理者ガイド
11gリリース2 (11.2)
B56288-04
サービス登録
PMONプロセスがリスナーに自動的に情報を登録する機能。
Oracle® Database Net Services管理者ガイド
12cリリース1 (12.1)
B71288-03
サービス登録
リスナー登録(LREG)プロセスがリスナーに自動的に情報を登録する機能です。
12cになって、従来のPMONに代わって新規に実装されたLREGというプロセスがサービス（リスナー）登録を行うようになったようですが、サービス登録の内部動作が変わったりしたのでしょうか？
気になったので確認してみることにします。
サービス登録の動作を確認する
11gR2
1. インスタンスを先に起動し、リスナーを後から起動する。
インスタンスとリスナーのどちらを先に起動させるかで、挙動が異なるかを確認します。
最初にデータベースを起動します。
データベースを起動する。
xx:xx:xx SQL> startup
ORACLEインスタンスが起動しました。
Total System Global Area 835104768 bytes
Fixed Size 2257840 bytes
Variable Size 536874064 bytes
Database Buffers 289406976 bytes
Redo Buffers 6565888 bytes
データベースがマウントされました。
データベースがオープンされました。
13:45:46 SQL>
アラートログ
2015-07-05 13:45:46.982000 +09:00
Completed: ALTER DATABASE OPEN
db_recovery_file_dest_size of 4182 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
Starting background process CJQ0
CJQ0 started with pid=21, OS id=4628
13:45:46 にインスタンスが起動しました。
このタイミングで、tnspingと接続の確認を行ってみます。
[xx:xx:xx] $ sqlplus /nolog
SQL*Plus: Release 11.2.0.4.0 Production on 日 7月 5 13:47:49 2015
Copyright (c) 1982, 2013, Oracle. All rights reserved.
13:47:49 SQL> conn scott/tiger@orcl
ERROR:
ORA-12541: TNS: リスナーがありません
リスナーが起動していないので、tnspingも接続も失敗することがわかります。
リスナーを起動する。
インスタンスの次にリスナーを起動します。
[xx:xx:xx] $ lsnrctl start
LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 13:48:51
............................................................................
リスナー起動直後に別コンソールからネット接続を試みます。
xx:xx:xx SQL> conn scott/tiger@orcl
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません
13:48:53 SQL> conn scott/tiger@orcl
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません
13:49:10 SQL>
13:48:53 と 13:49:10 にネット接続を試みましたが、成功しませんでした。
リスナーログ
05-7月 -2015 13:48:51 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=oraclelinux.onefact.jp)(USER=oracle))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=186647552)) * status * 0
2015-07-05 13:48:53.488000 +09:00
05-7月 -2015 13:48:53 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60167)) * establish * orcl.onefact.jp * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
2015-07-05 13:49:10.279000 +09:00
05-7月 -2015 13:49:10 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60185)) * establish * orcl.onefact.jp * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
13:48:51 にリスナーを起動しましたが、ネット接続を試みた時点でリスナーがサービスを認識していないことはリスナーログからも確認することができます。
それでも、接続を試みます。
xx:xx:xx SQL> conn scott/tiger@orcl
接続されました。
13:49:46 SQL>
13:49:46 にやっとネット接続が成功しました。
リスナーログ抜粋
2015-07-05 13:49:43.579000 +09:00
Dynamic address is already listened on (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
05-7月 -2015 13:49:43 * service_register * orcl * 0
2015-07-05 13:49:46.453000 +09:00
05-7月 -2015 13:49:46 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60205)) * establish * orcl.onefact.jp * 0
05-7月 -2015 13:49:46 * service_update * orcl * 0
2015-07-05 13:50:28.619000 +09:00
リスナーログを見ると、13:49:43 に「service_register」というのが確認できます。
これがリスナーがインスタンスをサービスとして認識したことを表し、以降ネット接続が可能となります。
リスナーを起動してからサービスが登録されるまで、52秒もかかっています。
2. リスナーを先に起動し、インスタンスを後から起動する。
時間の前後が逆になってしまっていますが、今度はリスナーを先に起動するパターンを確認します。
リスナー起動前の状態
[13:37:19] $ tnsping orcl
TNS Ping Utility for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 13:37:45
Copyright (c) 1997, 2013, Oracle. All rights reserved.
パラメータ・ファイルを使用しました:
/u01/app/oracle/product/11.2.0.4/db_1/network/admin/sqlnet.ora
エイリアスを解決するためにTNSNAMESアダプタを使用しました。
(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = oraclelinux.onefact.jp)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = orcl.onefact.jp)))に接続の試行中
TNS-12541: TNS: リスナーがありません。
リスナーを起動する。
[13:36:38] $ lsnrctl start
LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 13:38:18
Copyright (c) 1991, 2013, Oracle. All rights reserved.
/u01/app/oracle/product/11.2.0.4/db_1/bin/tnslsnrを起動しています。お待ちください...
TNSLSNR for Linux: Version 11.2.0.4.0 - Production
システム・パラメータ・ファイルは/u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.oraです。
ログ・メッセージを/u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xmlに書き込みました。
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC1521)))に接続中
リスナーのステータス
------------------------
別名 LISTENER
バージョン TNSLSNR for Linux: Version 11.2.0.4.0 - Production
開始日 05-7月 -2015 13:38:18
稼働時間 0 日 0 時間 0 分 0 秒
トレース・レベル off
セキュリティ ON: Local OS Authentication
SNMP OFF
パラメータ・ファイル /u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.ora
ログ・ファイル /u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xml
リスニング・エンドポイントのサマリー...
(DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
リスナーはサービスをサポートしていません。
コマンドは正常に終了しました。
[13:38:18] $
13:38:18 にリスナーを起動しましたが、インスタンスはまだ起動されていないので、当然サービスとして登録されていません。
リスナーログ抜粋
2015-07-05 13:38:18.674000 +09:00
システム・パラメータ・ファイルは/u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.oraです。
ログ・メッセージを/u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xmlに書き込みました。
トレース情報を/u01/app/oracle/diag/tnslsnr/oraclelinux/listener/trace/ora_4467_140172889650944.trcに書き込みました。
トレース・レベルは現在0です。
pid=4467で起動しました
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
Listener completed notification to CRS on start
TIMESTAMP * CONNECT DATA [* PROTOCOL INFO] * EVENT [* SID] * RETURN CODE
WARNING: Subscription for node down event still pending
05-7月 -2015 13:38:18 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=oraclelinux.onefact.jp)(USER=oracle))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=186647552)) * status * 0
ここでtnspingを試してみます。
[13:37:45] $ tnsping orcl
TNS Ping Utility for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 13:39:17
Copyright (c) 1997, 2013, Oracle. All rights reserved.
パラメータ・ファイルを使用しました:
/u01/app/oracle/product/11.2.0.4/db_1/network/admin/sqlnet.ora
エイリアスを解決するためにTNSNAMESアダプタを使用しました。
(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = oraclelinux.onefact.jp)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = orcl.onefact.jp)))に接続の試行中
OK (0ミリ秒)
[13:39:17] $
リスナーが起動済みなので、tnspingは成功します。
つまり、tnspingはインスタンスへの接続を確認するものではなく、リスナーが機能しているかを確認する目的で使うものです。
リスナーログ抜粋
2015-07-05 13:39:17.149000 +09:00
05-7月 -2015 13:39:17 * ping * 0
インスタンスを起動する
リスナーが起動されているのを確認できたので、次にインスタンスを起動します。
13:36:03 SQL> startup
ORACLEインスタンスが起動しました。
Total System Global Area 835104768 bytes
Fixed Size 2257840 bytes
Variable Size 536874064 bytes
Database Buffers 289406976 bytes
Redo Buffers 6565888 bytes
データベースがマウントされました。
データベースがオープンされました。
13:41:36 SQL>
13:41:36 にインスタンスが起動されました。
アラートログ抜粋
2015-07-05 13:41:36.771000 +09:00
Completed: ALTER DATABASE OPEN
db_recovery_file_dest_size of 4182 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
Starting background process CJQ0
CJQ0 started with pid=22, OS id=4541
別コンソールからネット接続を試みます。
[xx:xx:xx] $ sqlplus /nolog
SQL*Plus: Release 11.2.0.4.0 Production on 日 7月 5 13:41:09 2015
Copyright (c) 1982, 2013, Oracle. All rights reserved.
13:41:09 SQL> conn scott/tiger@orcl
ERROR:
ORA-12528: TNS:リスナー:
該当するインスタンスはすべて、新規接続をブロックしています
13:41:31 SQL> conn scott/tiger@orcl
接続されました。
13:41:40 SQL>
startupコマンド投入直後である、13:41:09 においてリスナーは起動済みですが、まだインスタンスは新規接続を受け付けない状態です。（ORA-12528）
ただし、インスタンス起動完了直後の 13:41:40 には接続が成功していることがわかります。
リスナーを後から起動した場合と比べて明らかに早いです。
2015-07-05 13:41:29.890000 +09:00
Dynamic address is already listened on (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
05-7月 -2015 13:41:29 * service_register * orcl * 0
2015-07-05 13:41:31.303000 +09:00
2015-07-05 13:41:31.303000 +09:00
05-7月 -2015 13:41:31 * service_update * orcl * 0
05-7月 -2015 13:41:31 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60132)) * establish * orcl.onefact.jp * 12528
TNS-12528: TNS:リスナー: 該当するインスタンスはすべて、新規接続をブロックしています
2015-07-05 13:41:35.882000 +09:00
05-7月 -2015 13:41:35 * service_update * orcl * 0
2015-07-05 13:41:37.360000 +09:00
05-7月 -2015 13:41:37 * service_update * orcl * 0
2015-07-05 13:41:40.363000 +09:00
05-7月 -2015 13:41:40 * service_update * orcl * 0
05-7月 -2015 13:41:40 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60135)) * establish * orcl.onefact.jp * 0
3. インスタンスを先に起動し、リスナーを後から起動する。その後サービス登録コマンドを実行する。
インスタンスは起動済みですが、リスナーは起動されていない状態から始めます。
念のため、ネット接続を試みてみます。
xx:xx:xx SQL> conn scott/tiger@orcl
ERROR:
ORA-12541: TNS: リスナーがありません
13:59:47 SQL>
リスナーを起動する。
[xx:xx:xx] $ lsnrctl start
LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 14:00:17
Copyright (c) 1991, 2013, Oracle. All rights reserved.
/u01/app/oracle/product/11.2.0.4/db_1/bin/tnslsnrを起動しています。お待ちください...
TNSLSNR for Linux: Version 11.2.0.4.0 - Production
システム・パラメータ・ファイルは/u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.oraです。
ログ・メッセージを/u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xmlに書き込みました。
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC1521)))に接続中
リスナーのステータス
------------------------
別名 LISTENER
バージョン TNSLSNR for Linux: Version 11.2.0.4.0 - Production
開始日 05-7月 -2015 14:00:17
稼働時間 0 日 0 時間 0 分 0 秒
トレース・レベル off
セキュリティ ON: Local OS Authentication
SNMP OFF
パラメータ・ファイル /u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.ora
ログ・ファイル /u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xml
リスニング・エンドポイントのサマリー...
(DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
リスナーはサービスをサポートしていません。
コマンドは正常に終了しました。
[14:00:17] $
リスナー起動直後に接続確認をする。
xx:xx:xx SQL> conn scott/tiger@orcl
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません
14:00:19 SQL>
リスナーログ抜粋
05-7月 -2015 14:00:17 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=oraclelinux.onefact.jp)(USER=oracle))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=186647552)) * status * 0
2015-07-05 14:00:19.326000 +09:00
05-7月 -2015 14:00:19 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60262)) * establish * orcl.onefact.jp * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
14:00:17 にリスナーを起動しましたが、起動直後はまだインスタンスを認識していないため接続は ORA(TNS)-12514 エラーで失敗します。
インスタンスを明示的にリスナーに登録する。
xx:xx:xx SQL> alter system register;
システムが変更されました。
13:59:31 SQL> alter system register;
システムが変更されました。
14:00:25 SQL>
14:00:25 に投入した「ALTER SYSTEM REGISTER」コマンドにより、1.のように52秒も待たずにインスタンスをリスナーへ登録することができます。
実は、リスナー起動前の 13:59:31 にもこのコマンドを実行していますが、インスタンス登録先のリスナーがないにもかかわらず特にエラーにならずに終了しています。
2015-07-05 14:00:25.437000 +09:00
05-7月 -2015 14:00:25 * service_register * orcl * 0
2015-07-05 14:00:33.233000 +09:00
05-7月 -2015 14:00:33 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60278)) * establish * orcl.onefact.jp * 0
2015-07-05 14:00:34.445000 +09:00
05-7月 -2015 14:00:34 * service_update * orcl * 0
conn scott/tiger@orcl
接続されました。
14:00:33 SQL>
インスタンスがリスナーに登録されたので、接続できるようになりました。
インスタンスを停止する。
インスタンスがリスナーに登録された状態から、インスタンスを停止させます。
14:00:25 SQL> shutdown immediate
データベースがクローズされました。
データベースがディスマウントされました。
ORACLEインスタンスがシャットダウンされました。
14:14:36 SQL>
リスナーログ抜粋
2015-07-05 14:14:34.271000 +09:00
05-7月 -2015 14:14:34 * service_died * orcl * 12537
インスタンス（プロセス）が停止すると、リスナーから見てサービスは死んだとみなされ「service_died」がログに出力されます。
まとめ
- リスナーにインスタンスがサービスとして登録されて初めて、インスタンス（データベース）に対するネット接続が可能となります。
- リスナーを後から起動すると、インスタンスが登録するまでにある程度の時間がかかります。（PMONが定期的にリスナーに登録しにいくので最長60秒程度かかる場合があります。）
- リスナーを先に起動しておくと、インスタンスは起動直後にリスナーに登録されます。
- 2.の場合でも「ALTER SYSTEM REGISTER」コマンドを実行すると、インスタンスを即時にリスナーへ登録することができます。
長くなってしまったので、Oracle12cの結果は次回としたいと思います。
今回はここまで
