统计信息和AUTO SQL TUNING任务重合引发的Library Cache Lock血案

一、引言

行里的短信平台，在晚上22:00的时候，突然出现卡顿，卡顿持续1分钟左右，这1分钟内，短信超过30秒才发送成功。因此，对数据库层面开展了一些分析，并且发现了些问题。

二、分析过程

1.查看22:00-22:05的ash信息会话情况，看是否有异常阻塞

select ash.event, count(*)
  from gv$active_session_history ash
 where to_char(sample_time, 'yyyymmddhh24miss') between '20240515215000' and
       '20240515220500'
 group by ash.event
 order by 2 desc;

可以看到，在这段时间内数据库内发生了大量的library cache lock事件，这明显不是一个正常的现象。

进一步查看是否可以找出阻塞源和被阻塞者：

select inst_id,sample_time,event,session_id,blocking_session
  from gv$active_session_history ash
 where to_char(sample_time, 'yyyymmddhh24miss') between '20240515220000' and
       '20240515221000'
 ORDER BY sample_time,session_id;

从这里可以看到，sid=573和sid=2272的会话之间产生了阻塞关系，而且同一时间点产生了大量的library cache lock。因此，可以判断这里可能存在问题。

进一步分析，我们可以查看library cache lock的p1,p2,p3值，其中p3值表示为100*mode+namespace(从p3text中可以看到)，但其实在这里它包含了三个信息：
1.object_id信息，即library cache lock相关的object；
2.namespace信息，即library cache lock所属的类型；
3.mode信息，表示library cache lock等待的锁模式；

select inst_id,ash.sample_time,
       ash.event,
       ash.sql_id,
       ash.session_id,
       ash.blocking_session,
       ash.P1,
       ash.P2,
       ash.P3,
       ash.P1TEXT,
       ASH.P2TEXT,
       ASH.P3TEXT
  from gv$active_session_history ash
 where to_char(sample_time, 'yyyymmddhh24miss') between '20240515220000' and
       '20240515220500'
 ORDER BY sample_time;

首先比对p3值，我们可以初步判断被阻塞产生library cache lock的对象和其他library cache的对象实际上是相同的。因此，大量的library cache lock一定是和阻塞源有关的。

通过对p3进行转换：

1.转换成16进制：
select to_char(61959198277635,'xxxxxxxxxxxxxxxxxxxxx') from dual;
SQL>385a00010003

2.高4位转换为object_id：
select to_number('385a','xxxxxxxx') object_id from dual;
SQL>14426

3.中间4位转换成namespace：
select to_number('0001','xxxxxxxx') namespace from dual;
SQL>1

4.第四位转换成mode：
select to_number('0003','xxxxxxxx') mode from dual;
SQL>3

即sid=537的会话，其实对ojbect_id为14426的对象，请求3号锁(其中3为Exclusive，其中2为share锁，1为null，namespace为1。

对于namespace，我们可以通过以下方式获取：

select distinct KGLHDNSP,KGLHDNSD from  x$kglob;

从图中可以看到namespace=1，代表了table/procedure；同理，通过object_id到dba_objects里面可以查到，锁对象即为数据库中的一张表。

2.分析阻塞关系

继续分析异常的阻塞关系：

select inst_id,ash.sample_time,
       ash.event,
       ash.sql_id,
       ash.session_id,
       ash.blocking_session,
       ash.P1,
       ash.P2,
       ash.P3,
       ash.P1TEXT,
       ASH.P2TEXT,
       ASH.P3TEXT
  from gv$active_session_history ash
 where to_char(sample_time, 'yyyymmddhh24miss') between '20240515220000' and
       '20240515220500'
 ORDER BY sample_time;

从这里，我们可以分析出以下信息：
1.sid=573和sid=2272在10点的时候调用了两个dbms_scheduler任务，任务动作是在做ORA$AT_SQ_SQL_SW_90311和ORA$AT_OS_OPT_SY_90309操作；

2.sid=573在执行ORA$AT_OS_OPT_SY_90309任务的时候，需要获取14426对象的X锁，但是被sid=2273阻塞了；

3.由于2273阻塞了573，根据时间线相当于SXSSSSS或XXSSSSS，导致产生了14426对象上的library cache lock；

那么这两个scheduler任务分别在干什么呢？此时，我们则可以从sql_id和历史任务执行情况两个层面分析：
首先，从sqlid上看：

select * from dba_hist_sqltext where sql_id in('cm4tx4a20h982','b6usrg82hwsa3');

其中，sid=573和sid=2273的会话分别执行了以下sql:

573:
call dbms_stats.gather_database_stats_job_proc();

2273:
SELECT /* DS_SVC */ /*+ dynamic_sampling(0) no_sql_tune no_monitoring optimizer_features_enable(default) opt_param('parallel_execution_enabled', 'false')  result_cache OPT_ESTIMATE(@"innerQuery", TABLE, "T", SCALE_ROWS=0.0003127696372) */ C1, C2, C3 FROM (SELECT /*+ qb_name("innerQuery") INDEX( "T" "IDX_TMSGQUEUE_M")  */ COUNT(*) AS C1, 4294967295 AS C2, COUNT(*) AS C3  FROM "TMSGQUEUE" "T" WHERE ("T"."MSGSERIAL">2499999999) AND ("T"."MSGSERIAL"<3000000000)) innerQuery

可以分析出来，573会话在执行统计信息收集任务，2273在做sql_tuning的任务；

为了证实，我们也可以从任务历史执行情况上查看：

select * from dba_autotask_job_history where job_name in('ORA$AT_SQ_SQL_SW_90311','ORA$AT_OS_OPT_SY_90309');

这里也可以明显的看到，两个任务分别是sql tuning advisor和auto optimizer stats collection，即自动统计信息收集任务和sql tuning advisor任务，且两个任务的触发时间都在晚上10:00的窗口。

从三节点的后台日志中也可以发现，在晚上10:00整的时候，启动了任务SYS_AUTO_SQL_TUNING_TASK。

三、原因描述

至此，我们就可以比较完整的追溯整个异常过程了。

在晚上10:00的时候，自动统计信息收集窗口和sql tunning advisor同时启用。此时，sql tuning advisor窗口对14426号表进行了优化测试，即sid=2272的SQL，该SQL在执行过程中会对14426号表加2号共享锁。

此时，自动统计信息收集窗口也正好也对14426号表也进行统计信息收集，此时该任务需要对表加X独占锁。

因此，两个锁相互排斥，故造成sid=2272的会话，阻塞了sid=523的会话，发生了library cache lock等待事件。又因为此时相关业务也需要对该表执行insert、select等操作，需要产生共享锁，需要等待523会话对14426号表释放独占锁后，才可以加锁使用，从而产生排队，发生了大量的library cache lock，最终导致业务在一分钟之内运行缓慢。

四、总结

Automatic SQL Tuning是11g引入的一个特性，它可以根据我们数据库的i/o、cpu等负载识别需要调优的sql。在任务设定时间内，则会对识别出的sql进行自动调优，生成sql_profile。当发现有统计信息丢失或者过期的时候，则会通知GATHER_STATS_JOB进行统计信息收集。然后对新的sql_profile进行效率测试。测试通过，则会执行新的profile
这个功能虽然看起来有助于我们对数据库进行更方便的运维，但是实际使用过程中，可能会造成很多性能突变或类似文章中提到的阻塞等问题。
对于DBA来讲，这个功能是一个比较好的辅助优化手段，但很多人也认为这是一个比较鸡肋的功能，所以在最佳实践中都会直接选择关闭该功能，具体方式如下：

begin
     dbms_auto_task_admin.disable(
          client_name => 'sql tuning advisor',
          operation => 'NULL',
          window_name => 'NULL');
end;

当然，这个功能一定程度上可以减轻优化运维工作。因此，如果想使用这个功能，我们也可以根据实际业务情况，选择在业务低峰期再启用这个功能。