Oracle 監聽器日誌解析
Oracle監聽器是駐留在Oracle實例所在服務器上的獨立進程。作為客戶端進程連接實例的重要溝通組件，Oracle監聽器扮演著重要的地位。本篇將從監聽器日誌入手，分析閱讀監聽器日誌和日常監聽器常見行為。
1、Oracle監聽器功能
在筆者《說說Oracle監聽器》（http://space.itpub.net/17203031/viewspace-682627）系列中，已經比較清楚的介紹過Oracle監聽器的工作方式和體系地位。這裏簡要加以累述。
Oracle監聽器是一個獨立的操作系統進程，運行在操作系統進程列表中。擁有獨立於數據庫實例的啟動、終止命令控制臺（lsnrctl）；
Oracle監聽器進程伺候在服務器一個特定端口上（默認為1521），等待通過Oracle Net Service連入到服務器的客戶端請求；
另一方面，Oracle監聽器根據系統設置情況（各種環境變量）接受數據庫實例的服務列表。服務Service是對外提供的服務名稱，供本地命名服務依據Service名稱連入到其中。Service是對應數據庫SID，也就是指定的Oracle實例數據庫位置。建立和維護服務列表的過程叫做註冊register；
註冊register過程分為兩種，靜態註冊和動態註冊。靜態註冊就是通過直接將服務名寫死在listener.ora文件中。動態註冊是通過pmon後臺進程周期性的到監聽器來註冊；
當一個client請求通過TCP協議訪問到特定端口的監聽程序，Oracle監聽器會對比請求中的Service名稱和掌握的註冊Service列表。如果不匹配，就拒絕。如果匹配，就定位到了特定的實例，包括Oracle_home地址；
監聽程序不負責進行用戶名密碼的驗證，此時會向Oracle實例請求一個Server Process與client Process進行你個交互；
2、Oracle監聽器狀態信息
在大部分平臺下，我們可以通過lsnrctl監聽器控制程序與監聽器進行交互和控制操作。其中，使用status命令，可以獲取到當前監聽器狀態信息。
C:\Documents and Settings\Administrator>lsnrctl status
LSNRCTL for 32-bit Windows: Version 10.2.0.1.0 - Production on 29-6月 -2011 13:41:27
Copyright (c) 1991, 2005, Oracle. All rights reserved.
正在連接到 (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=acca-119hs63yxc)(PORT=1521)
))
LISTENER 的 STATUS
------------------------
別名 LISTENER
版本 TNSLSNR for 32-bit Windows: Version 10.2.0.1.0 - Produ
ction
啟動日期 29-6月 -2011 10:51:26
正常運行時間 0 天 2 小時 50 分 3 秒
跟蹤級別 off
安全性 ON: Local OS Authentication
SNMP OFF
監聽程序參數文件 C:\tool\oracle\oracle\product\10.2.0\db_1\network\admi
n\listener.ora
監聽程序日誌文件 C:\tool\oracle\oracle\product\10.2.0\db_1\network\log\listener.log
監聽端點概要...
(DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=acca-119hs63yxc)(PORT=1521)))
服務摘要..
服務 "OTSXDB" 包含 1 個例程。
例程 "ots", 狀態 READY, 包含此服務的 1 個處理程序...
服務 "OTS_XPT" 包含 1 個例程。
例程 "ots", 狀態 READY, 包含此服務的 1 個處理程序...
服務 "ots" 包含 1 個例程。
例程 "ots", 狀態 READY, 包含此服務的 1 個處理程序...
命令執行成功
命令status可以查看當前監聽器的所有信息。當前監聽器對應的服務包括三個，分別為otsxdb、otx_xpt和ots。三個服務名是對外使用的，本質上對應的Oracle實例都是ots。
監聽器進程工作都有對應的日誌信息，在狀態顯示中，我們也可以看到日誌文件位置（C:\tool\oracle\oracle\product\10.2.0\db_1\network\log\listener.log）。下面我們從一個新的日誌文件，看監聽器工作。
3、Oracle監聽器日誌解析
下面是我們截取的監聽器片段，篇幅原因，有省略。
以 pid=2736 開始
監聽: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=acca-119hs63yxc)(PORT=1521)))
Listener completed notification to CRS on start
TIMESTAMP * CONNECT DATA [* PROTOCOL INFO] * EVENT [* SID] * RETURN CODE
29-6月 -2011 10:51:27 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=)(USER=Administrator))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=169869568)) * status * 0
29-6月 -2011 10:51:39 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=)(USER=Administrator))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=169869568)) * status * 0
29-6月 -2011 10:52:00 * (CONNECT_DATA=(SID=OTS)(CID=(PROGRAM=C:\tool\oracle\oracle\product\10.2.0\db_1\perl\5.8.3\bin\MSWin32-x86-multi-thread\perl.exe)(HOST=ACCA-119HS63YXC)(USER=SYSTEM))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.39.93)(PORT=3126)) * establish * OTS * 12505
TNS-12505: TNS: 監聽程序當前無法識別連接描述符中所給出的 SID
29-6月 -2011 10:52:00 * service_register * ots * 0
29-6月 -2011 10:52:11 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=)(USER=Administrator))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=169869568)) * status * 0
29-6月 -2011 10:52:48 * service_update * ots * 0
29-6月 -2011 10:53:00 * service_update * ots * 0
（有省略。。。）
29-6月 -2011 10:53:17 * ping * 0
29-6月 -2011 10:53:18 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=)(USER=SYSTEM))(COMMAND=status)(ARGUMENTS=64)(SERVICE=(ADDRESS=(PROTOCOL=TCP)(HOST=acca-119hs63yxc)(PORT=1521)))(VERSION=169869568)) * status * 0
29-6月 -2011 10:53:29 * (CONNECT_DATA=(SID=OTS)(CID=(PROGRAM=C:\tool\oracle\oracle\product\10.2.0\db_1\perl\5.8.3\bin\MSWin32-x86-multi-thread\perl.exe)(HOST=ACCA-119HS63YXC)(USER=SYSTEM))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.39.93)(PORT=3141)) * establish * OTS * 0
29-6月 -2011 10:53:57 * (CONNECT_DATA=(SERVICE_NAME=ots)(CID=(PROGRAM=D:\PLSQL Developer\plsqldev.exe)(HOST=LIUZIYU-PC)(USER=Liuziyu))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.39.40)(PORT=1760)) * establish * ots * 0
29-6月 -2011 10:54:00 * (CONNECT_DATA=(SERVICE_NAME=ots)(CID=(PROGRAM=D:\PLSQL Developer\plsqldev.exe)(HOST=LIUZIYU-PC)(USER=Liuziyu))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.39.40)(PORT=1761)) * establish * ots * 0
29-6月 -2011 10:54:00 * (CONNECT_DATA=(SERVICE_NAME=ots)(CID=(PROGRAM=D:\PLSQL Developer\plsqldev.exe)(HOST=LIUZIYU-PC)(USER=Liuziyu))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.39.40)(PORT=1762)) * establish * ots * 0
29-6月 -2011 10:54:03 * service_update * ots * 0
29-6月 -2011 10:54:09 * service_update * ots * 0
日誌內容很多，我們分為重點的幾個部分。
在日誌頭，Oracle告知了我們日誌格式，使用*進行內容分割。
TIMESTAMP * CONNECT DATA [* PROTOCOL INFO] * EVENT [* SID] * RETURN CODE
其中包括連接時間時間，請求數據Data和其他相關事件信息。這些可以幫助我們分析日誌內容。
監聽器無法找到指定服務
對應片段：
29-6月 -2011 10:52:00 * (CONNECT_DATA=(SID=OTS)(CID=(PROGRAM=C:\tool\oracle\oracle\product\10.2.0\db_1\perl\5.8.3\bin\MSWin32-x86-multi-thread\perl.exe)(HOST=ACCA-119HS63YXC)(USER=SYSTEM))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.39.93)(PORT=3126)) * establish * OTS * 12505
TNS-12505: TNS: 監聽程序當前無法識別連接描述符中所給出的 SID
分析日誌格式後，可以發現在這個時間（10:52），Oracle監聽器接受到程序的訪問，程序來自主機（ACCA-119HS63YXC），使用system用戶登錄，程序名稱是perl.exe。由於當前系統沒有註冊Service信息，也沒有註冊SID信息，所以不能夠連接識別對SID=OTS請求。
報錯無法識別SID。
實例主動進行動態註冊
此時，數據庫服務器先於監聽程序啟動，默認要等待很長的時間才會發生動態註冊。我們使用alter system register;命令手動啟動動態註冊過程。監聽程序上發現pmon進程的註冊進程，並且記錄在日誌中。
29-6月 -2011 10:52:00 * service_register * ots * 0
將數據庫sid=ots對應的三個實例進行註冊。
用戶Client連接進程
當出現連接請求的時候，日誌記錄。
29-6月 -2011 10:55:19 * (CONNECT_DATA=(SERVICE_NAME=ots)(CID=(PROGRAM=D:\PLSQL Developer\plsqldev.exe)(HOST=LIUZIYU-PC)(USER=Liuziyu))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.39.40)(PORT=1782)) * establish * ots * 0
根據日誌格式，可以理解為從遠程（HOST=LIUZIYU-PC，IP=10.1.39.40）主機通過TCP協議訪問到監聽程序，要求連接到ots服務上。使用的程序是pl/sql developer。
周期性pmon註冊
動態註冊是一種經常性的註冊行為，pmon每隔幾分鐘的時間就會向監聽器進行一次註冊動作。
29-6月 -2011 10:55:33 * service_update * ots * 0
4、結論
監聽器是我們經常打交道的數據庫組件之一。同數據庫的alert_log一樣，監聽器日誌能夠幫助我們解決很多日常故障問題。
Oracle 監聽器日誌解析