公众号：杨建荣的学习笔记 · 作者：杨建荣 · 发布：2016-07-05 23:50:26 · 原文链接

昨天写了一篇停库没有响应的问题分析，其实对于我来说，还是有些不太踏实，里面有几点需要改进。

因为是测试环境，所以操作的时候就随意了一些，如果是生产环境，直接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>
这样的情况就是让人基本满意的。