问题:
用户的数据库在某个时间段出现连接数异常上涨问题,时间持续5分钟左右,并且问题期间应用无法正常连接请求数据库
从连接数的监控上可以看到数据库平常峰值不到100个连接,在问题时间段突然上涨到400以上
问题分析:
首先查询数据库当前节点的历史使用最大连接数以及process参数的配置,推算问题时间段数据库的连接数是否已经达到上限,从而导致应用无法正常连接请求数据库
---手动创建快照,确保负载数据写入历史ash
exec dbms_workload_repository.create_snapshot();
---查询process参数历史最大值
select b.instance_number,b.begin_interval_time,b.end_interval_time,a.RESOURCE_NAME,a.CURRENT_UTILIZATION,a.MAX_UTILIZATION,a.LIMIT_VALUE
from DBA_HIST_RESOURCE_LIMIT a,dba_hist_snapshot b
where a.snap_id=b.snap_id and a.dbid=b.dbid and a.resource_name in('processes','sessions') and a.instance_number=b.instance_number
and b.begin_interval_time>to_date('2023/11/27 12:00:00','yyyy/mm/dd hh24:mi:ss') and b.begin_interval_time<to_date('2023/11/27 15:30:00','yyyy/mm/dd hh24:mi:ss')
order by b.instance_number,b.begin_interval_time
;
可以看到数据库的历史最大连接数为669,数据库参数process配置为1500,alert日志页没看到ORA-00020:maximum number of processes (xxx) exceeded的报错,也就是说问题时间段数据库的连接数并没有达到上限,询问用户应用的连接池配置,得到回复是连接池最大连接为500,低于数据库的历史最大连接数为669,因此,连接数异常上涨期间应用无法正常请求连接数据库的原因应该为数据库出现连接堆积,导致应用连接池连接耗尽无法正常请求连接数据库
接下来,分析数据库连接出现堆积上涨的原因,查看问题时间段ASH里面的等等事件情况,通过等待事件评估可能的原因以及下一步的分析方向
---查看某个时间段的等待事件数量
select event,count(*)
from v$active_session_history a
where sample_time between timestamp '2023-11-27 14:20:00' and timestamp '2023-11-27 14:25:00'
group by event;
;
---查看某个等待事件的每分钟数量
select to_char(sample_time,'yyyy-mm-dd hh24:mi'),event,count(*)
from v$active_session_history a
where sample_time between timestamp '2023-11-27 14:20:00' and timestamp '2023-11-27 14:25:00' and event='library cache pin'
group by to_char(sample_time,'yyyy-mm-dd hh24:mi'),event
order by 1;
可以看到问题时间段,数据库等待事件library cache pin在5分钟内出现了54885次等待,短时间内出现这么高的等待肯定是有问题的,并且从等待事件的类型以及经验来看,极有可能是由于存储过程,函数这类PL/SQL对象被某个会话独占持有所导致
注:library cache pin等待一般是指会话在shared pool共享池里面申请对library cache库缓存对象(比如函数,存储过程,包)进行访问调用时(pin),由于该对象正在被独占访问或是有会话正在申请独占访问,这时会话需要等待独占会话的释放,期间出现的等待事件就是library cache pin等待
查看是否有直接的堵塞会话指向sid,可以看到大部份的会话的堵塞会话blocking_session都是空的,没有看到直接的堵塞源,只有出现少量的堵塞会话sid:2133,1516
select blocking_session,blocking_session_serial#,count(*)
from v$active_session_history a
where sample_time between timestamp '2023-11-27 14:20:00' and timestamp '2023-11-27 14:25:00' and event='library cache pin'
group by blocking_session,blocking_session_serial#
order by 3
查看被堵塞的会话执行的语句,分析TOP 3的语句调用情况
select sql_id,count(*)
from v$active_session_history a
where sample_time between timestamp '2023-11-27 14:20:00' and timestamp '2023-11-27 14:25:00' and event='library cache pin'
group by sql_id
order by 2;
可以看到TOP前3个语句都同时调用了包app_interface_pkg,这说明library cache pin的争用发生在包app_interface_pkg
接下来,继续分析包是否发生了修改、编译或者重建这种需要获取独占模式的操作以及执行的会话
查看包app_interface_pkg最近一次的ddl时间以及创建时间,并没有发现在问题时间段以及近期有发生过修改、编译或者重建的操作,OS:难道分析错方向?先不管,继续往下
alter session set nls_date_format='yyyy-mm-dd hh24:mi:ss';
select object_id,object_name,created,last_ddl_time
from dba_objects
where object_name='APP_INTERFACE_PKG';
查看问题时间段所有会话的操作类型,有一个重大的发现里面出现了CREATE PACKAGE创建包的独占模式操作
alter session set nls_date_format='yyyy-mm-dd hh24:mi:ss';
col machine for a20
select SQL_OPNAME,count(*)
from v$active_session_history a
where sample_time between timestamp '2023-11-27 13:20:00' and timestamp '2023-11-27 14:22:00'
group by SQL_OPNAME;
查看这个执行CREATE PACKAGE的会话,可以看到这个会话一执行,就开始出现大面积的library cache pin等待,这个会话一消失,library cache pin等待也跟着消失,并且执行的操作应该是没有成功的,因为当时正在业务高峰期,包一直被其他会话所调用,这导致从开始到结束会话一直是在等待library cache pin去获取独占模式,而等待的会话分别是我们之前查到的sid:2133,1516,这也刚好解释了为什么之前看到包最近一次的ddl时间以及创建时间都没有发生过修改
alter session set nls_date_format='yyyy-mm-dd hh24:mi:ss';
col machine for a20
select sample_time,a.SESSION_ID, sql_id,blocking_session,blocking_session_serial#,event,SQL_OPNAME
from v$active_session_history a
where sample_time between timestamp '2023-11-27 14:27:04' and timestamp '2023-11-27 14:27:06'
order by sample_time;
到这里,问题已经变得清晰,在问题时间段有会话执行了对包app_interface_pkg的CREATE PACKAGE操作,对该包的library cache申请了独占模式,导致后续调用该包的会话都出现了library cache pin等待,最终引发了数据库会话连接堆积,应用连接池连接耗尽无法正常请求连接数据库
问题解决:
虽然通过sql_id没有查到具体的执行语句文本,但从会话的执行程序pl/sql developer可以基本确认是人为执行的语句,将会话查到的机器名交给用户进行进一步的查找,后续得到确认在问题时间段应用运维人员确实是对包app_interface_pkg执行了编译的操作所导致
所以,切记!生产无小事,三思而后行。