## 背景

### 背景
```
在很多情况下，当数据库发生性能问题的时候，我们并没有机会来收集足够的诊断信息，
比如system state dump或者hang analyze，甚至问题发生的时候DBA根本不在场。这给我们诊断问题带来很大的困难。
那么在这种情况下，我们是否能在事后收集一些信息来分析问题的原因呢？
在Oracle 10G或者更高版本上，答案是肯定的。本文我们将介绍一种通过 dba_hist_active_sess_history 的数据来分析问题的一种方法。
```
### 适用于
```
Oracle 10G或更高版本的单机或rac，本文适用于任何平台。
```
### 详情
```
Active Session: on the CPU or was waiting for an event that didn't belong to the Idle wait class
在Oracle 10G中，我们引入了AWR和ASH采样机制，有一个视图gv$active_session_history会每秒钟将数据库所有节点的Active Session采样一次，
而dba_hist_active_sess_history则会将gv$active_session_history里的数据每10秒采样一次并持久化保存。
基于这个特征，我们可以通过分析dba_hist_active_sess_history的Session采样情况，来定位问题发生的准确时间范围，并且可以观察每个采样点的top event和top holder。
下面通过一个例子来详细说明。
```
### dba_hist_active_sess_history
#### 1. Dump出问题期间的ASH数据：
```
为了不影响系统，我们可以将问题大概期间的ASH数据export出来在测试机上分析。
基于dba_hist_active_sess_history创建一个新表t_ash，然后将其通过exp/imp导入到测试机。在发生问题的数据库上执行exp:
SQL> conn user/passwd
SQL> create table t_ash as select * from dba_hist_active_sess_history where SAMPLE_TIME between TO_TIMESTAMP ('2015-03-01 10:20:00', 'YYYY-MM-DD HH24:MI:SS') and TO_TIMESTAMP ('2015-03-01 12:20:00', 'YYYY-MM-DD HH24:MI:SS');

$ exp user/passwd file=t_ash.dmp tables=(t_ash) log=t_ash.exp.log

然后导入到测试机：
$ imp user/passwd file=t_ash.dmp log=t_ash.imp.log
```
#### 2. 验证导出的ASH时间范围:
```
建议采用Oracle SQL Developer来查询以防止输出结果折行不便于观察。

set line 200 pages 1000
col sample_time for a25
col event for a40
alter session set nls_timestamp_format='yyyy-mm-dd hh24:mi:ss.ff';

select
t.dbid, t.instance_number, min(sample_time), max(sample_time), count(*) session_count
from t_ash t
group by t.dbid, t.instance_number
order by dbid, instance_number;

INSTANCE_NUMBER MIN(SAMPLE_TIME) MAX(SAMPLE_TIME) SESSION_COUNT
1 2015-03-26 21:00:04.278 2015-03-26 22:59:48.387 2171
2 2015-03-26 21:02:12.047 2015-03-26 22:59:42.584 36

```
**从以上输出可知该数据库共2个节点，采样时间共2小时，节点1的采样比节点2要多很多，
问题可能发生在节点1上。

#### 3. 确认问题发生的精确时间范围:
```
参考如下脚本：
col event for a35
set lines 222
set pages 9999
select
dbid, instance_number, sample_id, sample_time, count(*) session_count
from t_ash t
group by dbid, instance_number, sample_id, sample_time
order by dbid, instance_number, sample_time;

INSTANCE_NUMBER SAMPLE_ID SAMPLE_TIME SESSION_COUNT
1 36402900 2015-03-26 22:02:50.985 4
1 36402910 2015-03-26 22:03:01.095 1
1 36402920 2015-03-26 22:03:11.195 1
1 36402930 2015-03-26 22:03:21.966 21
1 36402940 2015-03-26 22:03:32.116 102
1 36402950 2015-03-26 22:03:42.226 181
1 36402960 2015-03-26 22:03:52.326 200
1 36402970 2015-03-26 22:04:02.446 227
1 36402980 2015-03-26 22:04:12.566 242
1 36402990 2015-03-26 22:04:22.666 259
1 36403000 2015-03-26 22:04:32.846 289
1 36403010 2015-03-26 22:04:42.966 147
1 36403020 2015-03-26 22:04:53.076 2
1 36403030 2015-03-26 22:05:03.186 4
1 36403040 2015-03-26 22:05:13.296 1
1 36403050 2015-03-26 22:05:23.398 1
```
**注意观察以上输出的每个采样点的active session的数量，数量突然变多往往意味着问题发生了。
从以上输出可以确定问题发生的精确时间在2015-03-26 22:03:21 ~ 22:04:42，问题持续了大约1.5分钟。
注意: 观察以上的输出有无断档，比如某些时间没有采样。

#### 4. 确定每个采样点的top n event:
```
在这里我们指定的是top 2 event 并且注掉了采样时间以观察所有采样点的情况。如果数据量较多，您也可以通过开启sample_time的注释来观察某个时间段的情况。
注意最后一列session_count指的是该采样点上的等待该event的session数量。
col event for a35
set lines 1000
set pages 9999
select t.dbid,
t.sample_id,
t.sample_time,
t.instance_number,
t.event,
t.session_state,
t.c session_count
from (select t.*,
rank() over(partition by dbid, instance_number, sample_time order by c desc) r
from (select /*+ parallel 2 */
t.*,
count(*) over(partition by dbid, instance_number, sample_time, event) c,
row_number() over(partition by dbid, instance_number, sample_time, event order by 1) r1
from t_ash t
/*where sample_time >
to_timestamp('2013-11-17 13:59:00',
'yyyy-mm-dd hh24:mi:ss')
and sample_time <
to_timestamp('2013-11-17 14:10:00',
'yyyy-mm-dd hh24:mi:ss')*/
) t
where r1 = 1) t
where r < 3
order by dbid, instance_number, sample_time, r;

SAMPLE_ID SAMPLE_TIME INSTANCE_NUMBER EVENT SESSION_STATE SESSION_COUNT
36402900 22:02:50.985 1 ON CPU 3
36402900 22:02:50.985 1 db file sequential read WAITING 1
36402910 22:03:01.095 1 ON CPU 1
36402920 22:03:11.195 1 db file parallel read WAITING 1
36402930 22:03:21.966 1 cursor: pin S wait on X WAITING 11
36402930 22:03:21.966 1 latch: shared pool WAITING 4
36402940 22:03:32.116 1 cursor: pin S wait on X WAITING 83
36402940 22:03:32.116 1 SGA: allocation forcing component growth WAITING 16
36402950 22:03:42.226 1 cursor: pin S wait on X WAITING 161
36402950 22:03:42.226 1 SGA: allocation forcing component growth WAITING 17
36402960 22:03:52.326 1 cursor: pin S wait on X WAITING 177
36402960 22:03:52.326 1 SGA: allocation forcing component growth WAITING 20
36402970 22:04:02.446 1 cursor: pin S wait on X WAITING 204
36402970 22:04:02.446 1 SGA: allocation forcing component growth WAITING 20
36402980 22:04:12.566 1 cursor: pin S wait on X WAITING 219
36402980 22:04:12.566 1 SGA: allocation forcing component growth WAITING 20
36402990 22:04:22.666 1 cursor: pin S wait on X WAITING 236
36402990 22:04:22.666 1 SGA: allocation forcing component growth WAITING 20
36403000 22:04:32.846 1 cursor: pin S wait on X WAITING 265
36403000 22:04:32.846 1 SGA: allocation forcing component growth WAITING 20
36403010 22:04:42.966 1 enq: US - contention WAITING 69
36403010 22:04:42.966 1 latch: row cache objects WAITING 56
36403020 22:04:53.076 1 db file scattered read WAITING 1
36403020 22:04:53.076 1 db file sequential read WAITING 1
```
**从以上输出我们可以发现问题期间最严重的等待为cursor: pin S wait on X，高峰期等待该event的session数达到了265个，
其次为SGA: allocation forcing component growth，高峰期session为20个。