关于:v$active_session_history是oracle中一个最重要的视图之一,该视图每秒一次记录当前数据库中的活动进程相关的信息,可以用于问题的分析和诊断;同时awr还会将部分v$active_session_history中的部分记录保留到dba_hist_active_session_history(10秒一次),我们常用的ash报告就源于此。 通过v$active_session_history 视图,可以看到数据库中的活动进程在做什么操作,以及是否有发生阻塞等情况,在分析和解决问题的时候可以从中获取较多的信息。
以下案例是通过v$active_session_history分析当前某个生产库问题发生的异常。
首先是应用监控发现某个实例异常,应用服务器上有连接报错,从报错看是连接db出现的问题。
dba接到报警后,检查相关的数据库,发现当前已经恢复正常,确认应用恢复正常后,开始进行异常时间段的分析。
这个问题需要从两个方面分析:
1、是应用负载增加,已有连接无法满足,应用在不断建立新的连接
2、db中出现异常,进程出现阻塞,新的事务无法重用现有连接,导致db中不断新建连接
针对这个问题,我们首先分析了连接日志,发现异常时间段确实有大量的新建连接。
但需要进一步分析是应用导致的还是db内部异常导致的。从应用负载看,并没有明显增加,问题集中在db当时是否出现异常等待。这个时候就需要从v$active_session_history分析(通常需要在发生异常后备份一次v$active_session_history,原因是v$ash的大小有限,如果不备份的话,后续分析时可能已经无法找到对应时间点的数据)。
1、首先需要确认异常的时间段
selectcount(*),sample_id,sample_time fromv$active_session_history ash where ash.sample_time between $1 and $2 group bysample_id,sample_time order by sample_id;
COUNT(*) SAMPLE_ID SAMPLE_TIME
16 267491028 10-10月-17??01.40.01.180?下午
18 267491029 10-10月-17??01.40.02.192?下午
22 267491030 10-10月-17??01.40.03.195?下午
22 267491031 10-10月-17??01.40.04.209?下午
45 267491032 10-10月-17??01.40.05.221?下午
75 267491033 10-10月-17??01.40.06.233?下午
90 267491034 10-10月-17??01.40.07.246?下午
112 267491035 10-10月-17??01.40.08.259?下午
136 267491036 10-10月-17??01.40.09.296?下午
161 267491037 10-10月-17??01.40.10.309?下午
186 267491038 10-10月-17??01.40.11.322?下午
214 267491039 10-10月-17??01.40.12.336?下午
251 267491040 10-10月-17??01.40.13.350?下午
287 267491041 10-10月-17??01.40.14.364?下午
319 267491042 10-10月-17??01.40.15.379?下午
353 267491043 10-10月-17??01.40.16.393?下午
374 267491044 10-10月-17??01.40.17.408?下午
414 267491045 10-10月-17??01.40.18.423?下午
447 267491046 10-10月-17??01.40.19.440?下午
476 267491047 10-10月-17??01.40.20.456?下午
521 267491048 10-10月-17??01.40.21.472?下午
562 267491049 10-10月-17??01.40.22.489?下午
583 267491050 10-10月-17??01.40.23.507?下午
616 267491051 10-10月-17??01.40.24.552?下午
631 267491052 10-10月-17??01.40.25.570?下午
666 267491053 10-10月-17??01.40.26.589?下午
684 267491054 10-10月-17??01.40.27.609?下午
696 267491055 10-10月-17??01.40.28.629?下午
732 267491056 10-10月-17??01.40.29.649?下午
756 267491057 10-10月-17??01.40.30.672?下午
16 267491058 10-10月-17??01.40.31.693?下午
12 267491059 10-10月-17??01.40.32.707?下午
15 267491060 10-10月-17??01.40.33.719?下午
从面查询的信息中可以明显看到活动进程在不断的增加
2、确认异常时间段是否有异常的等待
select count(*),event
from v$active_session_history ash
where ash.sample_id between267491028 and 267491060
group by event having count(*)>100
COUNT(*) EVENT
322
10058 enq: TX - index contention
3、分析阻塞进程当前的操作(注:阻塞进程不一定都是活动进程,如果非活动进程的话,可能无法从v$active_session_history中查询)
查询4993进程在异常时间段内的操作,该进程未被其他进程阻塞(blocking_session为空),异常时间段内该进程的操作如下:
selectash.sample_id,ash.sql_id,event,current_obj#,ash.current_file#,ash.current_block#,ash.session_state,ash.time_waited
from v$active_session_history ash
where sample_id between267491028 and 267491060
and sql_id = '38t8ff3k7t6g7'
and SESSION_ID = 4993
order by time_waited;
SAMPLE_ID SQL_ID EVENT CURRENT_OBJ# CURRENT_FILE# CURRENT_BLOCK# SESSION_STATE TIME_WAITED
267491047 38t8ff3k7t6g7 224704 467 817769 ON CPU 0
267491054 38t8ff3k7t6g7 224704 490 1801532 ON CPU 0
267491050 38t8ff3k7t6g7 db file sequential read 224704 473 2058359 WAITING 222
267491034 38t8ff3k7t6g7 db file sequential read 224704 289 2561727 WAITING 229
267491037 38t8ff3k7t6g7 db file sequential read 224704 146 2872842 WAITING 244
267491052 38t8ff3k7t6g7 db file sequential read 224704 489 1789069 WAITING 259
267491043 38t8ff3k7t6g7 db file sequential read 224704 215 2928079 WAITING 260
267491035 38t8ff3k7t6g7 db file sequential read 224704 271 2630866 WAITING 282
267491046 38t8ff3k7t6g7 db file sequential read 224704 311 3216267 WAITING 1710
267491031 38t8ff3k7t6g7 db file sequential read 224704 281 2558211 WAITING 1749
267491042 38t8ff3k7t6g7 db file sequential read 224704 515 1070381 WAITING 1764
267491048 38t8ff3k7t6g7 db file sequential read 224704 822 2498767 WAITING 1778
267491039 38t8ff3k7t6g7 db file sequential read 224704 822 2512572 WAITING 1847
267491032 38t8ff3k7t6g7 db file sequential read 224704 472 2053998 WAITING 2380
从上图可以看到该语句是在做相同的insert操作,只是耗时比较久,io读取都耗费在object_id为224704的对象上,这个对象就是表T_PUB_OVER_TIME_REC的主键
SQL> select object_namefrom dba_objects where object_id=224704;
OBJECT_NAME
--------------------------------------------------------------------------------
PK_OVER_TIME_REC_ID
SQL> selecttable_name,d.uniqueness from dba_indexes d where index_name='PK_OVER_TIME_REC_ID';
TABLE_NAME UNIQUENESS
----------------------------------------
T_PUB_OVER_TIME_REC UNIQUE
4、分析异常 :为什么insert操作中会在主键索引上有如此大量的io读取呢?
首先要先了解在insert的时候为什么会需要读取索引块:一个是正常的insert到对应的索引块,另外一个就是索引分裂。
在insert操作的时候,在表和索引上的插入不是完全一致的,主要的原因就是索引的结构导致的,插入的索引值是有序的,需要从根节点开始寻找,找到对应的块再插入,这个问题后续大家可以自行研究一下,但不会耗费太多的资源。
另外一种就是可能引发异常的情况,索引分裂引发的大量的io读取,这个一般是在大量空块的索引在做分裂的时候平衡二叉树遍历空块导致的。
针对这个问题,需要去分析一下PK_OVER_TIME_REC_ID(单列索引)上是否有大量的空块,实际上我们直接比对索引和表的大小就可以得出结论,表和索引几乎已经1:1了,正常来说这种单列索引会比表小很多的,因此这个索引中空块的问题是比较严重的,详细的信息可以通过analyzee等命令去分析索引块的实际情况,但需要注意对于大索引来说会耗费比较多的时间和资源,不建议在生产库直接执行。
SQL> select bytes/1024/1024 from dba_segments wheresegment_name='T_PUB_OVER_TIME_REC';
BYTES/1024/1024
---------------
1249
SQL> select bytes/1024/1024 from dba_segments wheresegment_name='PK_OVER_TIME_REC_ID';
BYTES/1024/1024
---------------
1193