备库报警邮件的分析案例（一)

今天早上到了公司后，收到了这样一封报警邮件，发现收到备库的报警案例也比较多，着实颠覆了我对备库基本不需要关注管理的观点。后面可以把几个案例做成一个主题来说说。
报警邮件的内容如下：
 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，同时数据库日志还有临时表空间不足的警告。
所以真是一环扣一环，稍后来进一步分析临时表空间使用超标的缘由。