停止数据库没有响应的问题分析(r9笔记第51天)
昨天写了一篇停库没有响应的问题分析，其实对于我来说，还是有些不太踏实，里面有几点需要改进。
因为是测试环境，所以操作的时候就随意了一些，如果是生产环境，直接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>
这样的情况就是让人基本满意的。
- JavaScript 教程
- JavaScript 编辑工具
- JavaScript 与HTML
- JavaScript 与Java
- JavaScript 数据结构
- JavaScript 基本数据类型
- JavaScript 特殊数据类型
- JavaScript 运算符
- JavaScript typeof 运算符
- JavaScript 表达式
- JavaScript 类型转换
- JavaScript 基本语法
- JavaScript 注释
- Javascript 基本处理流程
- Javascript 选择结构
- Javascript if 语句
- Javascript if 语句的嵌套
- Javascript switch 语句
- Javascript 循环结构
- Javascript 循环结构实例
- Javascript 跳转语句
- Javascript 控制语句总结
- Javascript 函数介绍
- Javascript 函数的定义
- Javascript 函数调用
- Javascript 几种特殊的函数
- JavaScript 内置函数简介
- Javascript eval() 函数
- Javascript isFinite() 函数
- Javascript isNaN() 函数
- parseInt() 与 parseFloat()
- escape() 与 unescape()
- Javascript 字符串介绍
- Javascript length属性
- javascript 字符串函数
- Javascript 日期对象简介
- Javascript 日期对象用途
- Date 对象属性和方法
- Javascript 数组是什么
- Javascript 创建数组
- Javascript 数组赋值与取值
- Javascript 数组属性和方法
- 「Mysql索引原理（十四）」索引案例3-优化排序
- 字符仿真
- 「Mysql索引原理（十五）」维护索引和表-修复损坏的表
- 「Mysql索引原理（十六）」维护索引和表-更新索引统计信息
- 「Mysql索引原理（十七）」维护索引和表-减少索引和数据的碎片
- 「通信框架Netty4 源码解读（一）」起步，关于IO的简单总结，模拟一个redis客户端
- Unet实现文档图像去噪、去水印
- 「influxDB 原理与实践（一）」安装部署，实现基础的添加删除查询功能
- 「influxDB 原理与实践（二）」详解influxDB的写入与查询
- Nginx系列：https配置
- 笛卡尔积、等值连接、自然连接、外连接一文看懂
- nginx系列：常用利用shell统计日志
- Nginx系列：图片过滤处理
- Nginx系列：几款负载均衡第三方插件的安装与使用
- 「高并发通信框架Netty4 源码解读（三）」NIO缓冲区Buffer详解