備庫報警郵件的分析案例(一)

jeanron100發表於2015-11-10
今天早上到了公司後,收到了這樣一封報警郵件,發現收到備庫的報警案例也比較多,著實顛覆了我對備庫基本不需要關注管理的觀點。後面可以把幾個案例做成一個主題來說說。
報警郵件的內容如下:
 ZABBIX-監控系統:
------------------------------------
報警內容: DG_issue
------------------------------------
報警級別: PROBLEM
------------------------------------
監控專案: dg_issue:2015-11-10 08:10:05.0Log Transport ServicesError
Error 12537 received logging on to the standby2015-11-10 08:10:05.0
Log Transport ServicesErrorARC0: Error 12537 attaching to RFS for reconnect
2015-11-10 08:10:05.0 Log Transport ServicesErrorPING[ARC0]: Error 3113 when pinging standby (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=10.127.2.17)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=stestmdb_XPT)(INSTANCE_NAME=testmdb)(SERVER=dedicated))).
------------------------------------
報警時間:2015.11.10-08:12:04
這是一套10gR2的環境,看到這個報警,自己感覺挺奇怪的,就產生了幾個問題,一個是為什麼不是每天都收到報警,另外一個問題是在那個時間段到底發生了什麼,是否存在潛在的問題。
我們來分析一下這個問題,當然還有一些疑點需要繼續補充,不過大體已經有了方向。
首先是問題發生的時間,是否有一定的規律。
檢視資料庫日誌,發現是每天都有備庫read-only,online的操作。那就可能是scheduler或者crontab觸發,備庫中還是主要用crontab來處理排程任務。檢視crontab -l發現確實有。
45 3 * * * . $HOME/.bash_profile;$HOME/dbadmin/scripts/open_standby.sh
10 8 * * * . $HOME/.bash_profile;$HOME/dbadmin/scripts/close_standby.sh
每天的3:45會把備庫置為read only狀態,然後在8:10開始置為接收歸檔的狀態。
這樣的話,似乎這個時間點還是有規律可循的,那麼還是第一個問題,為什麼不是每天收到報警,而是今天收到了報警。
要想證明這個過程,我們還是需要確切的資訊,這個資訊還是日誌了,不過是從listener.log中發現點端倪。
檢視備庫listener.log 發現在8:10的時候出現了TNS-12518的錯誤。
10-NOV-2015 08:09:53 * (CONNECT_DATA=(SID=testmdb)(CID=(PROGRAM=emagent)(HOST=acc137.test.com)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.127.2.17)(PORT=43133)) * establish * testmdb * 0
10-NOV-2015 08:10:02 * service_update * testmdb * 0
10-NOV-2015 08:10:06 * (CONNECT_DATA=(SERVICE_NAME=stestmdb_XPT)(INSTANCE_NAME=testmdb)(SERVER=dedicated)(CID=(PROGRAM=oracle)(HOST=test136.test.com)(USER=oracle))
) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.127.64.136)(PORT=55277)) * establish * stestmdb_XPT * 12518
TNS-12518: TNS:listener could not hand off client connection
 TNS-12547: TNS:lost contact
  TNS-12560: TNS:protocol adapter error
   TNS-00517: Lost contact
    Linux Error: 32: Broken pipe
10-NOV-2015 08:10:09 * service_update * testmdb * 0
10-NOV-2015 08:10:17 * (CONNECT_DATA=(SERVICE_NAME=stestmdb_DGB)(SERVER=dedicated)(CID=(PROGRAM=oracle)(HOST=acc136.test.com)(USER=oracle))) * (ADDRESS=(PROTOCOL=t
cp)(HOST=10.127.64.136)(PORT=55284)) * establish * stestmdb_DGB * 0
這個問題官方的解釋如下:
$ oerr tns 12518
12518, 00000, "TNS:listener could not hand off client connection"
// *Cause: The process of handing off a client connection to another process
// failed.
// *Action: Turn on listener tracing and re-execute the operation. Verify
// that the listener and database instance are properly configured for
// direct handoff.  If problem persists, call Oracle Support.
// *Comment: The problem can be worked around by configuring dispatcher(s)
// to specifically handle the desired presentation(s), and connecting
// directly to the dispatcher, bypassing the listener.
可以看出連線似乎是被強制終止了。那麼如果還是疑惑,看看資料庫日誌就會明白了。
資料庫日誌:
Completed: ALTER DATABASE OPEN READ ONLY
Mon Nov 09 03:46:10 CST 2015
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
RFS[608]: Assigned to RFS process 15713
RFS[608]: Identified database type as 'physical standby'
RFS[608]: Archived Log: '/U01/app/oracle/admin/testmdb/arch/1_21176_782846320.dbf'
Mon Nov 09 06:32:21 CST 2015
RFS[608]: Archived Log: '/U01/app/oracle/admin/testmdb/arch/1_21177_782846320.dbf'
Mon Nov 09 06:46:10 CST 2015
ORA-1652: unable to extend temp segment by 128 in tablespace                 TEMP
Mon Nov 09 06:46:10 CST 2015
ORA-1652: unable to extend temp segment by 128 in tablespace                 TEMP
Mon Nov 09 08:10:02 CST 2015
Stopping background process MMNL
Mon Nov 09 08:10:03 CST 2015
Stopping background process MMON
Mon Nov 09 08:10:04 CST 2015
Active process 11157 user 'oracle' program 'oracle@acc137.test.com'
Active process 21559 user 'oracle' program 'oracle@acc137.test.com'
Active process 2861 user 'oracle' program 'oracle@acc137.test.com'
Active process 22631 user 'oracle' program 'oracle@acc137.test.com'
Active process 2865 user 'oracle' program 'oracle@acc137.test.com'
Active process 2863 user 'oracle' program 'oracle@acc137.test.com'
Active process 21533 user 'oracle' program 'oracle@acc137.test.com'
CLOSE: waiting for server sessions to complete.
CLOSE: all sessions shutdown successfully.
Mon Nov 09 08:10:07 CST 2015
SMON: disabling cache recovery
Mon Nov 09 08:10:09 CST 2015
Starting background process MMON
Mon Nov 09 08:10:09 CST 2015
ALTER DATABASE RECOVER MANAGED STANDBY DATABASE  THROUGH ALL SWITCHOVER DISCONNECT  NODELAY
Mon Nov 09 08:10:09 CST 2015
Attempt to start background Managed Standby Recovery process (testmdb)
Starting background process MMNL
MMON started with pid=11, OS id=21447
MRP0 started with pid=12, OS id=21449
Mon Nov 09 08:10:09 CST 2015
MRP0: Background Managed Standby Recovery process started (testmdb)
在問題發生的時間點上,剛好需要把備庫置為日誌應用模式,所以需要斷開已有資料庫應用連線。這個時候如果再次做備庫的心跳檢查就很可能會出現這個問題
可以從listener.log中看出 問題發生的時間點,主庫所在的伺服器test136.test.com開始嘗試連線結果失敗,所以在v$dataguard_status中就記上了一筆。
10-NOV-2015 08:10:06 * (CONNECT_DATA=(SERVICE_NAME=stestmdb_XPT)(INSTANCE_NAME=testmdb)(SERVER=dedicated)(CID=(PROGRAM=oracle)(HOST=test136.test.com)(USER=oracle))
好吧,這個問題似乎這樣解釋也算合理。所以也可以認為這個問題可以忽略,不過細心的我發現了兩個細節。
一個是檔案系統的空間似乎不夠了,另外一個就是資料庫日誌中竟然出現了ORA-1652: unable to extend temp segment by 128 in tablespace      這樣的警告。
繼續逐個擊破,首先是檢視備庫的檔案系統,這樣來看,空間也是快滿了,但是已經跑了些年了,目前新增硬碟目前還是不實際的。就來看看有沒有辦法來做無米之炊。
$ df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/sda3             7.8G  908M  6.5G  13% /
/dev/sda6             7.8G  909M  6.5G  13% /var
/dev/sda5             7.8G  2.0G  5.5G  27% /usr
/dev/sda1             122M   12M  104M  10% /boot
tmpfs                  48G   44K   48G   1% /dev/shm
/dev/shm               48G   44K   48G   1% /tmp
/dev/sda7             497G  451G   21G  96% /home
首先檢視資料庫的表空間使用情況。發現目前使用了近384G。
Current Instance
~~~~~~~~~~~~~~~~
   DB Id    DB Name      Inst Num Instance
----------- ------------ -------- ------------
   56961518 testmdb            1 testmdb
Tablespace              Total MB    Free MB     Used MB  LrgstMB       MaxExt %Fr A
-------------------- --- - - ---- ------------ ---------- ----------- -------- ------------ --- -
sum                        383,842     98,993     284,849
那麼做個簡單的減法就是497-384=113G,那麼還應該剩下近100G才對,怎麼剩下了才21G的空間。
找到資料檔案的路徑,簡單列出檔案,還是發現了一些問題。
$ ls -lrt
total 458251788
-rw-r----- 1 oracle oinstall   209715712 Apr  7  2013 redo04.log
-rw-r----- 1 oracle oinstall   209715712 Apr  7  2013 redo05.log
-rw-r----- 1 oracle oinstall   209715712 Apr  7  2013 redo06.log
-rw-r----- 1 oracle oinstall    52429312 Apr  7  2013 redo02.log
-rw-r----- 1 oracle oinstall    52429312 Apr  7  2013 redo03.log
-rw-r----- 1 oracle oinstall    52429312 Apr  7  2013 redo01.log
-rw-r----- 1 oracle oinstall 34359730176 Nov 10 06:18 temp02.dbf
-rw-r----- 1 oracle oinstall 34359730176 Nov 10 06:33 temp03.dbf
-rw-r----- 1 oracle oinstall 34358697984 Nov 10 06:45 temp01.dbf
-rw-r----- 1 oracle oinstall    10493952 Nov 10 08:12 users01.dbf
-rw-r----- 1 oracle oinstall  8603574272 Nov 10 08:12 undotbs01.dbf
-rw-r----- 1 oracle oinstall   503324672 Nov 10 08:12 system01.dbf
-rw-r----- 1 oracle oinstall  1310728192 Nov 10 08:12 sysaux01.dbf
。。
-rw-r----- 1 oracle oinstall 34351357952 Nov 10 08:12 acc_data01.dbf
-rw-r----- 1 oracle oinstall     9682944 Nov 10 10:11 control03.ctl
-rw-r----- 1 oracle oinstall     9682944 Nov 10 10:11 control02.ctl
-rw-r----- 1 oracle oinstall     9682944 Nov 10 10:11 control01.ctl
首先是備庫中的redo日誌檔案的更新時間戳都是2013年了,其實redo的檔案是部分沒有使用到。這個也可以刪除,redo01,02,03在資料字典中沒有任何體現,還是可以刪除的,而且大小也確實有問題。
SQL> select group#,member,status from v$logfile;
    GROUP# MEMBER                                        STATUS
---------- --------------------------------------------- ----------
         4 /U01/app/oracle/oradata/testmdb/redo04.log
         5 /U01/app/oracle/oradata/testmdb/redo05.log
         6 /U01/app/oracle/oradata/testmdb/redo06.log
不過清理redo的收效還是很低。
我們來繼續觀察,就會發現temp資料檔案竟然有3個。檢視資料字典,發現是三個滿配的資料檔案。
SQL> select enabled,status,name from v$tempfile;
ENABLED    STATUS     NAME
---------- ---------- --------------------------------------------------
READ WRITE ONLINE     /U01/app/oracle/oradata/testmdb/temp01.dbf
READ WRITE ONLINE     /U01/app/oracle/oradata/testmdb/temp02.dbf
READ WRITE ONLINE     /U01/app/oracle/oradata/testmdb/temp03.dbf
那麼三個加起來就有近90G,而主庫卻只有兩個臨時資料檔案。可見臨時資料檔案也是後期加入的。
所以現在的問題就是確認是否可以刪除多餘的臨時資料檔案,比如給一個30G的是否足夠,單純從系統來看30G的大小應該是滿足了。
那麼這個問題就可以換個角度來看,為什麼temp空間會有90G,同時資料庫日誌還有臨時表空間不足的警告。
所以真是一環扣一環,稍後來進一步分析臨時表空間使用超標的緣由。

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/23718752/viewspace-1827685/,如需轉載,請註明出處,否則將追究法律責任。

相關文章