昨天写了一篇停库没有响应的问题分析,其实对于我来说,还是有些不太踏实,里面有几点需要改进。
因为是测试环境,所以操作的时候就随意了一些,如果是生产环境,直接kill进程是很不规范的。对于启库停库的时间把握,只是感觉有延迟,但是延迟究竟有多大还是不够严谨;问题的原因最后没有给出很清晰的答案,主要是因为后面自己没有经过大量的测试,所以这个地方还是不够严谨。
我们来继续分析一下。
目前的问题可以简化为两个:停库慢,启库慢。
我们来逐个击破。
首先是停库慢,shutdown immediate之后,就没有任何反应了,等了若干分钟都是如此。这如果是一个线上环境可是要出大问题的。
日志如下:
Shutting down instance (immediate)
Shutting down instance: further logons disabled
Stopping background process MMNL
Stopping background process MMON
License high water mark = 2
All dispatchers and shared servers shutdown
ALTER DATABASE CLOSE NORMAL
ORA-1109 signalled during: ALTER DATABASE CLOSE NORMAL...
ALTER DATABASE DISMOUNT
Shutting down archive processes
Archiving is disabled
Tue Jul 05 10:15:25 2016
。。。
伴随有如下的错误。
TNS-12535: TNS:operation timed out
ns secondary err code: 12560
nt main err code: 505
TNS-00505: Operation timed out
nt secondary err code: 0
nt OS err code: 0
Client address: <unknown>
所以可以看出问题似乎出来网络层面。如果查看日志目录下的文件。就会发现最新的更新文件都是下面的样子。
-rw-r----- 1 oracle oinstall 2226 Jul 5 09:52 dgtest_nsv1_22580.trc
-rw-r----- 1 oracle oinstall 159 Jul 5 10:00 dgtest_nsv1_22586.trm
-rw-r----- 1 oracle oinstall 2226 Jul 5 10:00 dgtest_nsv1_22586.trc
-rw-r----- 1 oracle oinstall 134 Jul 5 10:09 dgtest_nsv1_22602.trm
-rw-r----- 1 oracle oinstall 2226 Jul 5 10:09 dgtest_nsv1_22602.trc
-rw-r----- 1 oracle oinstall 82 Jul 5 10:14 dgtest_ora_22767.trm
-rw-r----- 1 oracle oinstall 1042 Jul 5 10:14 dgtest_ora_22767.trc
-rw-r----- 1 oracle oinstall 7765351 Jul 5 10:16 drcdgtest.log
-rw-r----- 1 oracle oinstall 288 Jul 5 10:17 dgtest_nsv1_22613.trm
-rw-r----- 1 oracle oinstall 4468 Jul 5 10:17 dgtest_nsv1_22613.trc
-rw-r----- 1 oracle oinstall 23410904 Jul 5 10:17 alert_dgtest.log
可以看出还是在DG Broker相关的地方存在一些检查。
如果查看dr日志,会发现下面的信息。
07/05/2016 10:13:25
Failed to connect to remote database dgtest2. Error is ORA-12170
Failed to send message to site dgtest2. Error code is ORA-12170.
Data Guard Broker Status Summary:
Type Name Severity Status
Configuration dg_test_gc Warning ORA-16607
Primary Database dgtest Error ORA-16782
Physical Standby Database dgtest2 Error ORA-12170
07/05/2016 10:16:25
Failed to connect to remote database dgtest2. Error is ORA-12170
Failed to send message to site dgtest2. Error code is ORA-12170.
所以问题已经看起来很明显了。
然后在若干分钟后,实例是终止了。然后我们继续查看startup
这个时候发现startup也卡住了。在alter database open阶段,没有任何反应。日志也没有输出。过了好一会儿,看到突然输出了不少的日志。然后open失败。
SQL> alter database open;
alter database open
*
ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 23096
Session ID: 96 Serial number: 9
查看alert日志,发现有了新进展,日志如下:
Errors in file /U01/app/oracle/diag/rdbms/dgtest/dgtest/trace/dgtest_arc1_23160.trc:
ORA-19815: WARNING: db_recovery_file_dest_size of 4322230272 bytes is 100.00% used, and has 0 remaining bytes available.
ARC1: Error 19809 Creating archive log file to '/U01/app/oracle/fast_recovery_area/DGTEST/archivelog/2016_07_05/o1_mf_1_127_%u_.arc'
ARCH: Archival stopped, error occurred. Will continue retrying
ORACLE Instance dgtest - Archival Error
ORA-16038: log 1 sequence# 127 cannot be archived
ORA-19809: limit exceeded for recovery files
ORA-00312: online log 1 thread 1: '/U01/app/oracle/oradata/dgtest/redo01.log'
Archiver process freed from errors. No longer stopped
ARC2: LGWR is scheduled to archive destination LOG_ARCHIVE_DEST_2 after log switch
ARCH: Archival stopped, error occurred. Will continue retrying
ORACLE Instance dgtest - Archival Error
ORA-16014: log 1 sequence# 127 not archived, no available destinations
ORA-00312: online log 1 thread 1: '/U01/app/oracle/oradata/dgtest/redo01.log'
可以看到问题的原因还是和空间有关,而这里的空间就是闪回区大小了,有一个参数可以灵活控制。
当然这个时候查看闪回区大小肯定是有问题的。而磁盘空间还是有空余的。
SQL> select *from v$flash_recovery_area_usage
FILE_TYPE PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES
-------------------- ------------------ ------------------------- ---------------
CONTROL FILE 0 0 0
REDO LOG 0 0 0
ARCHIVED LOG 99.48 0 121
BACKUP PIECE 0 0 0
IMAGE COPY 0 0 0
FLASHBACK LOG 0 0 0
FOREIGN ARCHIVED LOG 0 0 0
我们修复一下,调大一些。
SQL> alter system set db_recovery_file_dest_size=5G;
System altered.
闪回区的问题就解决了。这个时候继续启动到open阶段,发现虽然启动没有问题了,但是速度依旧是慢。
所以这个时候问题回到原点,虽然发现了问题,但是停库慢,启库慢的问题还是没有解决。
我认真查看了日志,还是发现了不少网络超时的日志。所以决定先把DG Broker的进程先停掉。
TNS-12535: TNS:operation timed out
ns secondary err code: 12560
nt main err code: 505
TNS-00505: Operation timed out
nt secondary err code: 0
nt OS err code: 0
Client address: <unknown>
Tue Jul 05 10:39:58 2016
NSV1 started with pid=22, OS id=23540
SQL> alter system set dg_broker_start=false;
System altered.
当然后续还看到警告日志,发现归档路径其实也要考虑。
SQL> alter system set log_archive_dest_2='';
System altered.
能够看到一个有意思的地方就是CKPT的一些信息。
马上能够看到CKPT的日志有了更新。
-rw-r----- 1 oracle oinstall 23447074 Jul 5 10:51 alert_dgtest.log
-rw-r----- 1 oracle oinstall 93 Jul 5 10:52 dgtest_ckpt_23300.trm
-rw-r----- 1 oracle oinstall 1097 Jul 5 10:52 dgtest_ckpt_23300.trc
日志如下:
*** 2016-07-05 10:37:52.426
*** SESSION ID:(126.1) 2016-07-05 10:37:52.426
*** CLIENT ID:() 2016-07-05 10:37:52.426
*** SERVICE NAME:() 2016-07-05 10:37:52.426
*** MODULE NAME:() 2016-07-05 10:37:52.426
*** ACTION NAME:() 2016-07-05 10:37:52.426
Adjusting CKPT timeout to 1s because LGWR dest is enabled
*** 2016-07-05 10:40:52.614
Control file enqueue hold time tracking dump at time: 382179
1: 2920ms (rw) file: kct.c line: 2522 count: 140733193388033 total: 2920ms time: 140733193769848
Reverting CKPT timeout to 3s default
当然后面发现还是有警告,这个排除只有一个参数了。
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
log_archive_config string dg_config=(dgtest,dgtest2)
SQL> alter system set log_archive_config='';
System altered.
修复之后,停库就很快了。大概10多秒就能搞定。
10:59:02 SQL> shutdown immediate
Database closed.
Database dismounted.
ORACLE instance shut down.
10:59:14 SQL>
这个时候还有一个问题是启库慢。
10:59:34 SQL> startup
ORACLE instance started.
Database mounted.
Database opened.
11:00:14 SQL>
我认真查看了下alert日志发现启动的日志中含有的参数如下:
System parameters with non-default values:
processes = 150
pre_page_sga = TRUE
lock_sga = FALSE
shared_pool_size = 848M
large_pool_size = 16M
java_pool_size = 16M
streams_pool_size = 0
sga_target = 0
。。。
看到这里其实问题就很明显了,还有一个参数需要修改,是pre_page_sga默认是false,而现在是true
11:01:55 SQL> alter system set pre_page_sga=false scope=spfile;
System altered.
然后再次启动,就会发现启库快了很多。
11:02:28 SQL> startup
ORACLE instance started.
Database mounted.
Database opened.
11:02:37 SQL>
这样的情况就是让人基本满意的。