某数据库接数突然升高故障分析报告

Oracle一体机用户组 2020-01-02

3117

问题和分析结果概述

问题描述

根据客户反映，某数据库隔一段时间就会出现数据库连接数突然升高，导致应用无法连接数据库、影响业务使用的情况。在未做任何处理的情况下，系统可自动恢复正常。

为保证系统平稳、高效运行，提升业务可用性和用户体验，需要查找问题的根本原因，提出解决方案，同时找到系统中存在的其他隐患。

环境描述

AIX 6100-07-05-1228

ORACLE 11.2.0.2 ,两节点 RAC集群数据库

原因概述

某系统连接数突然升高导致数据库不可用的问题，经初步分析，是由于操作系统内存不足导致内存被换到磁盘，操作系统响应缓慢所导致。

因此，我们建议，在不减少数据库SGA内存大小的情况下，将机器从当前内存大小46G/50G增加到70G内存，可有效解决该问题。

问题分析的详细过程

确认故障

通过下列SQL语句抓取两个节点的连接数变化情况

select to_char(sample_time, 'yyyymmdd hh24:mi:ss'), count(*)
  from dba_hist_active_sess_history
 where dbid = 87xxxx65
   and snap_id between 31633 and 31634
   and to_char(sample_time, 'yyyymmddhh24mi') between '201404211323' and
       '201404211328'
   and instance_number = 1
-- and instance_number = 2
 order by 1;

复制

结果所下所示

RAC节点1输出如下，可以看到连接数确实出现了瞬间突然升高的情况

时间	活动会话个数
0421 13:23:07	1
0421 13:23:17	2
0421 13:23:27	2
0421 13:23:37	3
0421 13:23:47	12
0421 13:23:57	29
0421 13:24:07	42
0421 13:24:17	47
0421 13:24:27	61
0421 13:24:37	70
0421 13:24:47	94
0421 13:24:57	170
0421 13:25:08	223
0421 13:25:18	257
0421 13:25:28	374
0421 13:25:38	405
0421 13:25:48	424
0421 13:25:58	430
0421 13:26:08	443
0421 13:26:19	457
0421 13:26:29	466
0421 13:26:39	452
0421 13:26:49	418
0421 13:26:59	368
0421 13:27:09	371
0421 13:27:20	323
0421 13:27:30	267
0421 13:27:40	200
0421 13:27:50	96
0421 13:28:00	15
0421 13:28:10	15
0421 13:28:20	6
0421 13:28:30	5
0421 13:28:40	5
0421 13:28:53	27

RAC节点2输出

时间	活动会话个数
0421 13:23:07	2
0421 13:23:18	1
0421 13:23:28	3
0421 13:23:48	13
0421 13:24:13	27
0421 13:24:23	32
0421 13:24:34	43
0421 13:24:44	53
0421 13:24:55	96
0421 13:25:05	157
0421 13:25:16	195
0421 13:26:48	364
0421 13:26:58	380
0421 13:27:08	350
0421 13:27:19	310
0421 13:27:29	295
0421 13:27:39	168
0421 13:27:49	88
0421 13:27:59	50
0421 13:28:09	34
0421 13:28:19	31
0421 13:28:29	18
0421 13:28:39	9
0421 13:28:49	35
0421 13:28:59	60

通过上述输出，我们获得到了最近一次连接数突然升高的情况出现在4月21日13点23分到28分之间，并得到了运维人员的确认。

因此，可以确认，故障与客户描述一致。

需要继续往下分析。

将上述连接数的原始数据制作成曲线以表示变化情况，如下所示

RAC节点1

RAC节点2

进一步分析：

数据库连接数出现如此大的变化，通常都是因为数据库在某些资源上出现了竞争或者SQL执行过程中出现了异常的等待所导致，因此，我们需要从ASH性能数据中继续分析这段时间中所出现的异常等待。

ASH报告分析

RAC节点1

从节点1的ASH报告可以看到，从13点23分到25之间出现了”gc current block congested”和”gc cr block congested”的等待。

当出现这些等待的时候，数据库的响应速度比将急剧下降。

其中gc 表示需要在RAC两个节点内存之间请求和获得数据块，congested表示拥堵。Gc有三种状态，立刻获得、busy、congested.

出现congested，表示节点2出现了严重的性能问题，导致无法及时响应节点1的请求。

因此，需要继续查看节点2的等待情况。

RAC节点2

可以看到：

13点23分到25分之间，出现的等待事件主要是”log file sync”和”CPU + wait for CPU”

log file sync 表示当前台进程commit时，必须等待数据库后台lgwr进程将log buffer中的redo刷到磁盘的在线重做日志文件当中，如果commit太频繁、lgwr进程无法获得CPU时间片或者磁盘写入的比较慢，都可能出现等待。

“CPU + wait for CPU” 表示正在消耗CPU或等待获得CPU时间片

这些等待事件同时出现，往往意味着操作系统内存可能存在换页操作，不过还需确认。

接下来我们需要从更细粒度的数据来还原整个问题的过程。这里我们依然通过dba_hist_active_sess_history获取10秒为粒度的数据（数据库每10秒会保留一次采样数据）。

以10秒为粒度还原问题出现过程

RAC节点1

可以看到，

13:27:07/13:27:17/13:27:27/13:27:37,还还正常，分别只有1、2、2、3个会话在运行；

但是13:27:47秒的采样显示，即黄色底纹部分，由于节点2响应节点1的请求非常缓慢，继而出现gc*congested等待，于是会话个数开始急剧涨到12；下一次采样时，即13:27:57的采样时刻，会话进一步涨到29个.因此，问题就锁定在在节点2于13:27:47秒左右的性能情况。

时间	会话号	等待事件	P1	P2
20140421 13:23:07	1_914_55793		675562835	1
20140421 13:23:17	1_429_52181	db file scattered read	29	2342744
20140421 13:23:17	1_129_27287	db file sequential read	8	2214875
20140421 13:23:27	1_429_52181	db file scattered read	38	777430
20140421 13:23:27	1_2169_26989		675562835	1
20140421 13:23:37	1_429_52181	db file scattered read	40	189572
20140421 13:23:37	1_1298_47949		675562835	1
20140421 13:23:37	1_2691_49559		675562835	1
20140421 13:23:47	1_2327_54263	gc buffer busy acquire	12	825179
20140421 13:23:47	1_136_43439	gc cr block congested	26	2209472
20140421 13:23:47	1_1650_27877	gc cr block congested	41	2244405
20140421 13:23:47	1_21_44843	gc cr block congested	12	825179
20140421 13:23:47	1_429_52181	gc cr block congested	12	1642095
20140421 13:23:47	1_161_19363	gc cr grant congested	15	1740715
20140421 13:23:47	1_1572_4767	gc current block congested	17	1205179
20140421 13:23:47	1_167_13503	gc current block congested	14	473335
20140421 13:23:47	1_2054_40013	gc current block congested	39	2221558
20140421 13:23:47	1_266_62389	gc current block congested	40	1626499
20140421 13:23:47	1_380_1	library cache lock	5.04E+17	5.04E+17
20140421 13:23:47	1_1298_47949		675562835	1
20140421 13:23:57	1_2773_1	enq: CF – contention	1128660997	0
20140421 13:23:57	1_1047_27169	gc buffer busy acquire	39	2221558
20140421 13:23:57	1_1521_11677	gc buffer busy acquire	26	2209472
20140421 13:23:57	1_2327_54263	gc buffer busy acquire	12	825179
20140421 13:23:57	1_2421_17851	gc buffer busy acquire	26	2209472
20140421 13:23:57	1_2691_49559	gc buffer busy acquire	26	2209472
20140421 13:23:57	1_666_41747	gc buffer busy acquire	26	2209472
20140421 13:23:57	1_685_6751	gc buffer busy acquire	41	2244405
20140421 13:23:57	1_1158_13581	gc cr block congested	16	165697
20140421 13:23:57	1_136_43439	gc cr block congested	26	2209472
20140421 13:23:57	1_1431_45963	gc cr block congested	26	907213
20140421 13:23:57	1_1650_27877	gc cr block congested	41	2244405
20140421 13:23:57	1_1800_42233	gc cr block congested	41	335282
20140421 13:23:57	1_21_44843	gc cr block congested	12	825179
20140421 13:23:57	1_2545_38111	gc cr block congested	41	2241403
20140421 13:23:57	1_429_52181	gc cr block congested	12	1642095
20140421 13:23:57	1_519_11753	gc cr block congested	35	2542667
20140421 13:23:57	1_522_42787	gc cr block congested	17	1228281
20140421 13:23:57	1_161_19363	gc cr grant congested	15	1740715
20140421 13:23:57	1_1024_33599	gc current block congested	17	1894578
20140421 13:23:57	1_1572_4767	gc current block congested	17	1205179
20140421 13:23:57	1_167_13503	gc current block congested	14	473335
20140421 13:23:57	1_2054_40013	gc current block congested	39	2221558
20140421 13:23:57	1_266_62389	gc current block congested	40	1626499
20140421 13:23:57	1_384_34603	gc current block congested	21	2321101
20140421 13:23:57	1_398_48405	gc current block congested	17	2481977
20140421 13:23:57	1_817_62135	gc current block congested	35	2429993
20140421 13:23:57	1_2536_48381	library cache lock	5.04E+17	5.04E+17
20140421 13:23:57	1_2660_11985	log file sync	8467	2215449001

RAC节点2

根据上述分析，我们知道，节点1出现连接数急剧上升，是因为节点2出现了性能问题（数据库性能或者操作系统性能问题），导致节点2非常缓慢地响应节点1的gc请求。

接下来，我们看看，对应时段节点2的10秒为间隔的采样数据。

时间	会话号	等待事件	P1	P2
20140421 13:23:07	2_2705_39081		2	43
20140421 13:23:07	2_2451_44245		10	2073606
20140421 13:23:18	2_1312_12281		16	1273651
20140421 13:23:28	2_7_33057	db file sequential read	18	1187652
20140421 13:23:28	2_1168_44727	db file sequential read	21	52088
20140421 13:23:28	2_1782_62969		28	2011437
注意：这里缺少了23分38秒一次采样意味着这一刻数据库或者操作系统出现了严重的性能问题采样丢失、延迟
20140421 13:23:48	2_1666_49667	db file scattered read	38	2002368
20140421 13:23:48	2_380_1	enq: CO – master slave det	1129250822	0
20140421 13:23:48	2_400_41067	gc current block 2-way	14	1711942
20140421 13:23:48	2_2404_1021	gc current grant busy	13	1102632
20140421 13:23:48	2_915_6217	library cache pin	5.04E+17	5.04E+17
20140421 13:23:48	2_2773_1		100	0
20140421 13:23:48	2_2396_29		5.04E+17	5.04E+17
20140421 13:23:48	2_1639_1		3	0
20140421 13:23:48	2_1513_1		80	0
20140421 13:23:48	2_1387_1		0	3
20140421 13:23:48	2_1262_1		0	0
20140421 13:23:48	2_1261_1		1	1
20140421 13:23:48	2_1036_45191		500	0
注意：这里缺少了23分58秒和24分08秒的两次采样，下面一行却显示是24分13秒，而不是24分08秒，说明数据库或者操作系统出现了性能问题导致采样丢失、延迟
20140421 13:24:13	2_1666_49667	gc cr multi block request	40	1460683
20140421 13:24:13	2_400_41067	gc current block 2-way	14	1711942
……

从节点2的下表数据，我们可以看到一次更严重的性能问题

时间	活动会话个数
0421 13:23:07	2
0421 13:23:18	1
0421 13:23:28	3
正常10秒有一次采样，这么有10秒左右挂起了,直接跳到23分48秒
0421 13:23:48	13
正常10秒有一次采样，这么有20秒左右挂起了,直接跳到24分13秒
0421 13:24:13	27
0421 13:24:23	32
0421 13:24:34	43
0421 13:24:44	53
0421 13:24:55	96
0421 13:25:05	157
0421 13:25:16	195
正常10秒有一次采样，这么有1分30秒左右挂起了
0421 13:26:48	364
0421 13:26:58	380
0421 13:27:08	350
0421 13:27:19	310
0421 13:27:29	295
0421 13:27:39	168
0421 13:27:49	88

可以看到：

正常来说，10秒一次采样，但是却少了23分38秒、23分58秒、24分08秒的采样，并且

25分16秒到26分48秒之间有1分半钟的时间完全没有采样到数据，说明数据库或者操作系统出现了性能问题导致没有采样或采样延迟。

判断是数据库还是操作系统出现短暂挂起

从上述分析可知，数据库中缺少多个采样、采样延迟，这可能是数据库出现挂起，也可能是操作系统出现性能问题导致。需要确认大方向

在故障时点，数据库alter日志无任何异常信息。

尝试多种手段获取4月21日的操作系统性能数据，例如OS内存换页的情况。遗憾的是没有获得4月21日操作系统的任何性能数据。因此无法直接证明是操作系统的问题。

换个角度，如果操作系统级的命令也出现延迟或者响应慢的情况，那么我们就可以排除数据库挂起的情况，因为操作系统级的命令是独立于数据库之外执行的。

数据库有一个RAC两个节点互相发包ping对方以检测对方性能的机制，见下图。

可以看到，500字节的ping包从节点2发送到节点1，平均延时52毫秒，典型的延迟达到了723毫秒。在操作系统性能正常的情况下，这两个延迟都在1毫秒以下。

因此，可以判断，节点2的操作系统性能在13点23分到28分之间出现了不间断的性能问题。

检查操作系统性能数据

我们从上面分析知道，10秒前的性能还正常，但下一个10秒，操作系统就突然出现了非常严重的性能问题。能导致这样情况的，只有内存出现换页，即pi/po操作。

一旦内存被置换到了换页空间即磁盘上，程序（包括操作系统本身）的运行速度将急剧下降，因为磁盘的速度要比内存慢非常非常多。

检查当前的内存换页情况，可以看到，换页空间达到了18%，即36864* 0.18=6.5G,这说明过去的某个时间点确实由于内存不足，导致程序的内存被置换到了磁盘的换页空间。当以后有程序需要用到这些磁盘中数据时，程序将变得异常缓慢。

换页空间部分，主要是被4K的小页面内存占据，大概1207231* 4K=4.6G,64K页占了换页空间中的1.6G左右（26387*64K）；

另外，clnt类型即文件系统cache占用的内存是475297*4=2.8G,很小，而work/size=10778465/11861984=90%,达到了很高的比例，说明系统内存不足.

再看ORACLE用户的总情况，换页空间中包含了573142*4K=2.2G被换出的ORACLE内存。

综上分析，这是比较典型的机器内存不足导致换页继而引发性能问题的情况。

这种情况与我们前面看到的短暂挂起的现象是吻合的。因此，我们需要使得内存配置合理，从而保证操作系统不会出现内存换页的情况。要么，为机器增加内存，要么减少ORACLE SGA、PGA对内存的占用。

建议

在AIX操作系统上的ORACLE 11G RAC，如何设置内存，我们总结了一个最佳实践，即一个通用的公式，该公式已在多套生产系统得到充分的验证。

物理内存X*0.6=SGA+PGA+ORACLE进程数*7M+GRID用户内存约6G

这里乘以0.6是因为操作系统kernel inodeCache最多可能占到40%，可能你会觉得有些多，但事实上，我们处理过多起由于inodecache占较多导致内存换页的case.

操作系统40%的阀值不可控制，因此，除非可以确定该OS上几乎没有文件系统特别是大文件的读、写、压缩操作，否则需要按照该公式来。

7M表示ORACLE 11G单个服务进程在OS上所消耗的内存。

以该系统为例，出现阻塞异常时，并发进程数500个，当前SGA配置为24G，

PGA虽然参数配置为6G，但是下图可以看到,PGA最多用到过13.9G,我们取一个折中的PGA为10G即可

因此，机器物理内存X= (（24G+10G）+ 500* 7M + 6G ) 0.6=73G，去掉整数为70G

总结来说，该系统连接数突然升高导致数据库不可用的问题，是由于操作系统内存不足导致，我们建议，将机器从当前内存大小从46G/50G增加到70G内存，并重启操作系统释放掉换页空间中的数据。

系统其他隐患分析

获取数据库序列号sequence占据数据库整体消耗13.1%，说明sequence的cache设置不合理。

例如下图中的sequence_userloginhistory_id出现了明显的出现enq: SQ – contention 竞争，导致获取一个sequence的值需2.4秒，响应时间太慢。

该sequence的cache可以设置得更大一些，一般设置为2000，这样保证当高并发下获得数十倍的性能提升，以及出现异常时可以使得系统快速恢复正常而不是消化很长时间才恢复正常。

实例负载分析

每秒硬解析83次，太高，系统有多处应该使用绑定变量但未使用的地方，过高的硬解析不利于系统的稳定性、扩展性，存在较大隐患。后续我们将把这些应该使用绑定变量但未使用的SQL语句查找出来，以便开发进行相应修改。

每秒逻辑读15万，过大，有很大的优化空间

每秒物理读3922个BLOCK，IO过大，有很大的优化空间

具体来说，下列这些SQL我们都有很好的方式进行代码优化，通过分析SQL语句的执行计划可以使得这些SQL有数十倍的性能提升，可以极大的提升用户的使用体验，提升业务效率

数据库SGA动态调整没有关闭，数据库存在SGA动态调整导致数据库HANG的隐患，我们至少处理过20套以上的系统过由于SGA动态调整BUG导致数据库HANG的情况。

RAC DRM等功能没有关闭，当DRM同步出现超时时，数据库实例存在crash的风险。

AIX 601705版本上需要安装10个左右的小补丁，可以防范例如某个场景下使用netstat命令就可能操作操作系统宕掉的一些已知BUG。需要对当前操作系统进行补丁分析、排除隐患。还有该版本下ORACLE每个进程多消耗7M USLA heap内存的补丁，等等。

其他隐患待进一步分析。

下一步建议

针对连接数突然升高导致数据库不可用的历史故障，我们建议调整内存大小到70G，同时重启操作系统，把换页空间中的内存数据释放掉。

RAC标准配置必须要求安装ORACLE发布的Oswatcher工具，以便可以获取到CPU、内存等性能数据,安装介质可以从metalink上下载，搜索关键字为oswatcher即可，按照10秒采样，保留3天

系统存在很大的性能提升空间，存在一些隐患，需要针对性的、深入的现场分析。

原创文章，版权归本文作者所有，如需转载请注明出处

喜欢本文请长按下方的二维码订阅Oracle一体机用户组

最后修改时间：2020-01-03 09:20:58

文章转载自Oracle一体机用户组，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

某数据库接数突然升高故障分析报告

评论

相关阅读