巧用DBA_HIST_ACTIVE_SESS_HISTORY

原创

大山123 2014-03-05 18:19:13 ©著作权

©著作权归作者所有：来自51CTO博客作者大山123的原创作品，请联系作者获取转载授权，否则将追究法律责任

dba_hist_active_sess_history这个视图功能比较强大，可以查找过去数据库信息，有几个字段比如BLOCKING_SESSION、event、sql_id、SAMPLE_TIME可以查询数据库过去时间事件，对故障处理是有作用的。

dba_hist_active_sess_history:是视图v$active_session_history的历史数据，DBA_HIST_ACTIVE_SESS_HISTORY视图默认每十秒收集一次信息储存在磁盘中，保存7天，这也是组成AWR一个重要的试图。

附一下AWR相关试图

DBA_HIST_WR_CONTROL：查看当前快照收集的相关设置
v$active_session_history:由ASH自动在内存中维护，以每秒一次的频率收集当前系统中活动session的信息
dba_hist_active_sess_history:是视图v$active_session_history的历史数据，保存在硬盘上
dba_hist_database_instance:显示数据库是实例的信息
dba_hist_snapshot:当前数据库收集到的快照信息

这里直接用案例，来说明。

先用roger一组GES死锁导致。

数据库出现故障，导致数据库HANG住。分析步骤1 查看alert.log Global Enqueue Services Deadlock detected. More info in file
/oracle/admin/cmsdb1/bdump/cmsdb11_lmd0_3705.trc

这时查看trc文件， master 0 gl owner 54111aeb8 possible pid 28756 xid 1005-005B-00009AFE bast 0 rseq 6 mseq 0 history 0x14951495
open opt KJUSERDEADLOCK。分析出为相互堵塞。及下来就要分析堵塞的SID及sqltext。

1 SQL> select SNAP_ID,to_char(BEGIN_INTERVAL_TIME,'yyyymmdd hh24:mi:ss') BEGIN_INTERVAL_TIME from WRM$_SNAPSHOT where BEGIN_INTERVAL_TIME between to_date('20101202 10','yyyymmdd hh24') and to_date('20101202 18','yyyymmdd hh24') and INSTANCE_NUMBER=1 order by 2; 其实这里不用查snap_id对应的时间，在dba_hist_active_sess_history里有一个时间字段SAMPLE_TIME，一样可以查找你想要时间里的相关内容。

2 根据快照ID 查询故障时间段内的异常等待事件

select INSTANCE_NUMBER,event,to_char(SAMPLE_TIME,'yyyymmdd hh24:mi:ss'),count(*) from DBA_HIST_ACTIVE_SESS_HISTORY
where snap_id=22549 and WAIT_CLASS<>'Idle' and event='enq: TX - row lock contention'group by INSTANCE_NUMBER,event,to_char(SAMPLE_TIME,'yyyymmdd hh24:mi:ss') order by 1,3;

3 根据等待事件查sid

select instance_number,BLOCKING_SESSION,count(*),event from DBA_HIST_ACTIVE_SESS_HISTORY where snap_id=22549 and
to_char(SAMPLE_TIME,'yyyymmdd hh24:mi:ss')='&time' and WAIT_CLASS<>'Idle' and event='enq: TX - row lock contention'
group by instance_number,BLOCKING_SESSION,event
order by 1,2;

从这里我们可以看到死锁session均来自一个节点，输入告警里面的时间，查询可的出sid为351，577为互为死锁，最多查sql便能查出来相关语句，发生死锁一般是要从开发业务做调整。

下面在是关于数据库HANG住时通过这分析DBA_HIST_ACTIVE_SESS_HISTORY

来自一米的分析

前台应用已经反映完全无法使用了
我们使用CRT远程进程操作已经很困难了几乎无法操作
因为情况比较急所以

首先查看当前系统的情况

SQL> select BLOCKING_SESSION,count(*) from DBA_HIST_ACTIVE_SESS_HISTORY where snap_id=25604 and
2 to_char(SAMPLE_TIME,'yyyymmdd hh24:mi:ss')='20100115 18:30:35' and WAIT_CLASS<>'Idle'
3 and event='enq: SQ - contention'
4 group by BLOCKING_SESSION
5 order by 2;

BLOCKING_SESSION   COUNT(*)
---------------- ----------
            6412          1
            6003          2
            6042         14
            6437         14
            5535         15
            3455        150
            3033        233

7 rows selected.

从上面我们可以看出 3455和30332个session就阻塞了差不多400个会话

下面接着查看看3455和3033 分别是被谁阻塞
SQL> select SESSION_ID,USER_ID,SQL_ID,BLOCKING_SESSION,event,SAMPLE_TIME from DBA_HIST_ACTIVE_SESS_HISTORY where snap_id=25604 and
to_char(SAMPLE_TIME,'yyyymmdd hh24:mi:ss')<'20100115 18:30:35 2 ' and WAIT_CLASS<>'Idle'
and SESSION_ID =3 3 033 order by SAMPLE_TIME desc
4 ;

SESSION_ID    USER_ID SQL_ID        BLOCKING_SESSION EVENT                               SAMPLE_TIME
---------- ---------- ------------- ---------------- ----------------------------------- ---------------------------------------------
      3033         34 2f1jw97anaudf                  row cache lock                      15-JAN-10 06.30.25.781 PM
      3033         34 2f1jw97anaudf             3358 enq: SQ - contention                15-JAN-10 06.30.15.608 PM
      3033         34 2f1jw97anaudf             4633 enq: SQ - contention                15-JAN-10 06.30.05.296 PM

通过类似的查询分析

4633 别谁堵塞。对于3045也是一样的分析，最后的出可以发现也其它语句堵塞。找到该语句就可解决。处理该问题也要查看相就的trace文件。

接下来的菜是通过DBA_HIST_ACTIVE_SESS_HISTORY 来分析出来一个数据库bug

该文章来自天堂向左，DBA向右的文章

今天遇到个问题，客户说某天的11:45开始，系统遇到了大量的cursor pin s wait on X，经历一个小时后自动消失，需要查找原因。

这报错一般是某个会话需要申请S模式的mutex，而mutex被其他会话以X模式占有了。查holder也很容易，11g版本前看p2raw的前8位，将16进制转换成10进制即为holder的sid，在11g之后只需直接看blocking_session即可。

在11g中，我们有ash，这个很方便能查到过去发生的一切。

（1）根据客户反馈的情况，cursor pin S wait on X最严重的一个时间段为12:25~12:35，取这个时间段为例。发现cursor: pin S wait on X的进程都被sid为2的进程堵塞。

SQL> selectevent,blocking_session,sql_id,count(*)fromdba_hist_active_sess_historyash
2wheresample_time>=to_timestamp('2013-06-24 12:25:00','yyyy-mm-dd hh24:mi:ss')
3andsample_time<=to_timestamp('2013-06-24 12:35:00','yyyy-mm-dd hh24:mi:ss')
4andevent='cursor: pin S wait on X'
5groupbyevent,blocking_session,sql_id
6 /

EVENTBLOCKING_SESSIONSQL_IDCOUNT(*)
---------------------------------------------------------------- ---------------- ------------- ----------
cursor: pinSwaitonX28duehra3kdx621050

--cursor: pinSwaitonX的SQL为：
SQL> selectsql_textfromv$sqlwheresql_id='8duehra3kdx62';

SQL_TEXT
--------------------------------------------------------------------------------
insert into mytable_a1_p1_h1 select * from mytable_a2_p2_h2

（2）SID为2的进程被sid为1129的进程堵塞：

（3）sid为1129的进程被sid 951的堵塞：

SQL> selectevent,blocking_session,sql_id,count(*)fromdba_hist_active_sess_historyash
2wheresample_time>=to_timestamp('2013-06-24 12:25:00','yyyy-mm-dd hh24:mi:ss')
3andsample_time<=to_timestamp('2013-06-24 12:35:00','yyyy-mm-dd hh24:mi:ss')
4andash.session_id=1129
5groupbyevent,blocking_session,sql_id
6 /

EVENTBLOCKING_SESSIONSQL_IDCOUNT(*)
---------------------------------------------------------------- ---------------- ------------- ----------
rowcachelock9515nkcsttxny4wz60

SQL>
--而sid1129的sql为：
SQL> selectsql_textfromv$sqlwheresql_id='5nkcsttxny4wz';

SQL_TEXT
--------------------------------------------------------------------------------
truncate table mytable_a2_p2_h2

SQL>

（4）sid 951的进程被Wnnn的进程堵塞：

SQL> selectevent,blocking_session,sql_id,program,count(*)fromdba_hist_active_sess_historyash
2wheresample_time>=to_timestamp('2013-06-24 12:25:00','yyyy-mm-dd hh24:mi:ss')
3andsample_time<=to_timestamp('2013-06-24 12:35:00','yyyy-mm-dd hh24:mi:ss')
4andash.session_id=951
5groupbyevent,blocking_session,sql_id,program
6 /

EVENTBLOCKING_SESSIONSQL_IDPROGRAMCOUNT(*)
---------------------------------------------------------------- ---------------- ------------- ---------------------------------------------------------------- ----------
oracle@g4as1010(W004)8
logfilesequentialreadoracle@g4as1010(W004)52

（5）最终的堵塞进程为Wnnn。

Wnnn是11g新的进程，有SMCO进程spawn出来，用于主动空间的管理(It perform proactive space allocation and space reclaimation)。
从上述SQL看，由于有insert又有truncate，因此空间清理将有SMCO和Wnnn进程介入。在操作的过程中，堵塞其他的进程的操作。

到这里，我们可以有个初步的解决方案：

既然是Wnnn进程堵塞了其他进程的操作，那么我们禁用这个11g的新功能，禁用SMCO的空间管理 “Tablespace-level space（Extent）pre-allocation”，即可避免该问题的发生。

altersystemset"_ENABLE_SPACE_PREALLOCATION"=0

还原的反向操作为：

altersystemset"_ENABLE_SPACE_PREALLOCATION"=3

注：

* 0 to turn off the tbs pre-extension feature.
* 1 To enable tablespace extension.
* 2 To enable segment growth.
* 3 To enable extent growth.
* 4 To enable chunk allocation.

但是我们到这里也会问一个问题，为什么Wnnn的操作没有blocking_session，却要操作那么久的时间。这时一个不常见的等待事件映入眼帘：log file sequential read 。

log file sequential read 一般是在恢复或者logmnr的时候，才将redo log file的内容顺序的读入到内存中，此时为什么需要做log file sequential read？

根据上述的时间点，我们进一步结合alertlog看，我们发现在对应的时间点，都有关于w004的ora600的报错。

Sun Jun 23 01:45:01 2013
Errors in file /aabb/sx/kgg/data/app/oracle/diag/rdbms/kgg/kgg/trace/kgg_w007_8283.trc (incident=104227):
ORA-00600: internal error code, arguments: [ktecgsc:kcbz_objdchk], [0], [0], [1], [], [], [], [], [], [], [], []
Incident details in: /aabb/sx/kgg/data/app/oracle/diag/rdbms/kgg/kgg/incident/incdir_104227/kgg_w007_8283_i104227.trc
……

结合ora -600 [ktecgsc:kcbz_objdchk]查询MOS，我们可以定位到一个11.2.0.2的bug 10237773，并且从该bug的Rediscovery Note中，也可以看到：The problem is likely to occur in a Wnnn background process ktssupd_segment_extblks_bkg is likely to appear on the stack.

如果想看该内容可以到其本人的博客中查看，这时只想表明通过dba_hist_active_sess_history ，可以查明到会话的等待事件，其数据库中出现HNAG住还是前台某个操作过慢问题，基本都是语句问题，一个语句因为一些原因堵塞其它语句，导致其它语句发生等待，就像公路上车祸一样，有一个车横在路上，会导致整个路上排起长队，所以在分析数据库变慢情况下，一定到抓到根源，通过根源看到底是BUG，还是语句写的有问题，还是业务设计有问题。

最后也是比较有用的一个sql语句，