性能优化|关于数据库历史性能问题的一道面试题

JiekeXu之路 2021-04-28

4284

作者 | JiekeXu

来源 | JiekeXu DBA之路（ID: JiekeXu_IT）

大家好，我是 JiekeXu,很高兴又和大家见面了,今天和大家聊聊关于数据库历史性能问题的一道面试题，欢迎点击上方蓝字关注我，标星或置顶，更多干货第一时间到达！

前言

前几天看到微信群里讨论的一次面试题，大概意思是说如何诊断昨天过去一分钟数据库性能问题，这也不算是个很难的问题，AWR 报告搞不定了可以使用 ASH 来抓取当时一分钟内的情况。可是没想到我的面试官也问到了我类似的问题【昨天数据库 hang 了一分钟，如何诊断问题】，由于当时比较懵只简单的说了利用 ASH 来获取然后查看操作系统的资源使用情况。这样基本上已经算是送了半条命，可算真惨……

正文

一、ASH 报告

从 Oracle 10g 开始引入，ASH（Active Session History）以 v$session 为基础，每秒钟采样一次，记录活动会话等待的事件。ASH记录的信息也可以通过 v$active_session_history 视图来访问，而dba_hist_active_sess_history 是 v$active_session_history 的持久化视图，他通过 mmon 进程将 v$active_session_history 中的信息每十秒采集一次到 awr snapshot 中。可以参考下图来理解 ASH。

采样时间由内部隐含参数 “_ash_sampling_interval”决定,1000 毫秒刚好是 1 秒的时间，所以可以采集到 1 秒内的数据。

SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
FROM SYS.x$ksppi x, SYS.x$ksppcv y
WHERE x.inst_id = USERENV ('Instance')
AND y.inst_id = USERENV ('Instance')
AND x.indx = y.indx
AND x.ksppinm LIKE '%&par%'
/
复制

在很多情况下，当数据库发生性能问题的时候，基本上都会采集 ASH 报告，不管是 RAC 还是单机环境下，均可采集。不过我们一般使用的是 @?/rdbms/admin/ashrpti.sql

使用 ashrpti.sql 不同之处就是和正常的 ashrpt 中，增加了如下图末中的 Slot 槽宽度，这里我们一般都是设置 slot 为 1s，更加细粒度的查看系统当时的等待事件。

设置 slot 为 1s 后，多次回车默认即可生成 ASH 报告，

而直接使用 ASH 虽然很多部分都是一样的信息，但 Activity Over Time 这部分就可以看出区别，同样都是昨天 15 点到 15 点十分的信息，但是 slot 为 1 的报告中则更加详细，所以推荐大家使用 ashrpti.sql 来获取 ASH 报告。

ASH 报告基本信息如下，除了基本的表头信息外，还包括了 AWR 快照信息以及收集的时间和平均的活动会话信息。当然剩下的就是各种 top N 信息， Activity Over Time 则是重点关注的地方，通过 slot 槽可以观察到当时的等待事件和活动会话数（Slot Count）。

看完 ASH 报告和相应的问题后，还有可能需要查看操作系统层面的资源使用情况，这个一般都会部署 NMON 和 OSWatcher 这两款监控工具，各有利弊。在新版 Oracle 11204 及以上的版本中，OSWatcher 是已经安装好了，默认的 osw 采集间隔是 30s，数据保存时间为 48h，我们需将其修改为采集间隔 15s 或者 10s ，保存时间为 168h(也就是7天),这个也根据系统目录大小而定。

ps -ef | grep osw
/app/product/11.2.0/grid/bin/tfactl stop  oswbb
/app/product/11.2.0/grid/bin/tfactl start  oswbb  10  168
复制

二、dba_hist_active_sess_history

除了前面提到的 ASH 报告，这里在介绍一种通过 dba_hist_active_sess_history 的数据来分析问题的一种方法。在 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。下面通过一个例子来详细说明。

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 ('<time_begin>', 'YYYY-MM-DD HH24:MI:SS') and TO_TIMESTAMP ('<time_end>', '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. 确认问题发生的精确时间范围:
参考如下脚本：

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数量。

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
                 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 个。

注意:
1) 再次确认以上输出有无断档，是否有某些时间没有采样。
2) 注意那些 session_state 为 ON CPU 的输出，比较 ON CPU 的进程个数与您的 OS 物理CPU 的个数，如果接近或者超过物理 CPU 个数，那么您还需要检查 OS 当时的 CPU 资源状况，比如 OSWatcher/NMON 等工具，高的 CPU Run Queue 可能引发该问题，当然也可能是问题的结果，需要结合 OSWatcher 和 ASH 的时间顺序来验证。

5. 观察每个采样点的等待链:
其原理为通过 dba_hist_active_sess_history. blocking_session 记录的 holder 来通过 connect by 级联查询，找出最终的 holder. 在 RAC 环境中，每个节点的 ASH 采样的时间很多情况下并不是一致的，因此您可以通过将本 SQL 的第二段注释的 sample_time 稍作修改让不同节点相差1秒的采样时间可以比较(注意最好也将 partition by 中的 sample_time 做相应修改)。该输出中 isleaf=1 的都是最终 holder，而 iscycle=1 的代表死锁了(也就是在同一个采样点中a等b，b等c，而c又等a，这种情况如果持续发生，那么尤其值得关注)。采用如下查询能观察到阻塞链。

select
 level                     lv,
 connect_by_isleaf         isleaf,
 connect_by_iscycle        iscycle,
 t.dbid,
 t.sample_id,
 t.sample_time,
 t.instance_number,
 t.session_id,
 t.sql_id,
 t.session_type,
 t.event,
 t.session_state,
 t.blocking_inst_id,
 t.blocking_session,
 t.blocking_session_status
  from t_ash t
/*where sample_time >
    to_timestamp('2013-11-17 13:55:00',
                 'yyyy-mm-dd hh24:mi:ss')
and sample_time <
    to_timestamp('2013-11-17 14:10:00',
                 'yyyy-mm-dd hh24:mi:ss')*/
 start with blocking_session is not null
connect by nocycle
 prior dbid = dbid
       and prior sample_time = sample_time
          /*and ((prior sample_time) - sample_time between interval '-1'
          second and interval '1' second)*/
       and prior blocking_inst_id = instance_number
       and prior blocking_session = session_id
       and prior blocking_session_serial# = session_serial#
 order siblings by dbid, sample_time;
 
LV    ISLEAF    ISCYCLE    SAMPLE_TIME    INSTANCE_NUMBER    SESSION_ID    SQL_ID    EVENT    SESSION_STATE    BLOCKING_INST_ID    BLOCKING_SESSION    BLOCKING_SESSION_STATUS
1    0    0    22:04:32.846    1    1259    3ajt2htrmb83y    cursor:    WAITING    1    537    VALID
2    1    0    22:04:32.846    1    537    3ajt2htrmb83y    SGA:    WAITING            UNKNOWN
复制

注意为了输出便于阅读，我们将等待 event 做了简写，下同。从上面的输出可见，在相同的采样点上(22:04:32.846)，节点1 session 1259 在等待 cursor: pin S wait on X，其被节点1 session 537 阻塞，而节点 1 session 537 又在等待 SGA: allocation forcing component growth，并且 ASH 没有采集到其 holder，因此这里 cursor: pin S wait on X 只是一个表面现象，问题的原因在于 SGA: allocation forcing component growth

6. 基于第5步的原理来找出每个采样点的最终 top holder:
比如如下SQL列出了每个采样点 top 2 的 blocker session，并且计算了其最终阻塞的 session 数(参考blocking_session_count)

select t.lv,
       t.iscycle,
       t.dbid,
       t.sample_id,
       t.sample_time,
       t.instance_number,
       t.session_id,
       t.sql_id,
       t.session_type,
       t.event,
       t.seq#,
       t.session_state,
       t.blocking_inst_id,
       t.blocking_session,
       t.blocking_session_status,
       t.c blocking_session_count
  from (select t.*,
               row_number() over(partition by dbid, instance_number, sample_time order by c desc) r
          from (select t.*,
                       count(*) over(partition by dbid, instance_number, sample_time, session_id) c,
                       row_number() over(partition by dbid, instance_number, sample_time, session_id order by 1) r1
                  from (select
                         level              lv,
                         connect_by_isleaf  isleaf,
                         connect_by_iscycle iscycle,
                         t.*
                          from t_ash t
                        /*where sample_time >
                            to_timestamp('2013-11-17 13:55:00',
                                         'yyyy-mm-dd hh24:mi:ss')
                        and sample_time <
                            to_timestamp('2013-11-17 14:10:00',
                                         'yyyy-mm-dd hh24:mi:ss')*/
                         start with blocking_session is not null
                        connect by nocycle
                         prior dbid = dbid
                               and prior sample_time = sample_time
                                  /*and ((prior sample_time) - sample_time between interval '-1'
                                  second and interval '1' second)*/
                               and prior blocking_inst_id = instance_number
                               and prior blocking_session = session_id
                               and prior
                                    blocking_session_serial# = session_serial#) t
                 where t.isleaf = 1) t
         where r1 = 1) t
 where r < 3
 order by dbid, sample_time, r;
SAMPLE_TIME    INSTANCE_NUMBER    SESSION_ID    SQL_ID    EVENT    SEQ#    SESSION_STATE    BLOCKING_SESSION_STATUS    BLOCKING_SESSION_COUNT
22:03:32.116    1    1136    1p4vyw2jan43d    SGA:    1140    WAITING    UNKNOWN    82
22:03:32.116    1    413    9g51p4bt1n7kz    SGA:    7646    WAITING    UNKNOWN    2
22:03:42.226    1    1136    1p4vyw2jan43d    SGA:    1645    WAITING    UNKNOWN    154
22:03:42.226    1    537    3ajt2htrmb83y    SGA:    48412    WAITING    UNKNOWN    4
22:03:52.326    1    1136    1p4vyw2jan43d    SGA:    2150    WAITING    UNKNOWN    165
22:03:52.326    1    537    3ajt2htrmb83y    SGA:    48917    WAITING    UNKNOWN    8
22:04:02.446    1    1136    1p4vyw2jan43d    SGA:    2656    WAITING    UNKNOWN    184
22:04:02.446    1    537    3ajt2htrmb83y    SGA:    49423    WAITING    UNKNOWN    10
22:04:12.566    1    1136    1p4vyw2jan43d    SGA:    3162    WAITING    UNKNOWN    187
22:04:12.566    1    2472        SGA:    1421    WAITING    UNKNOWN    15
22:04:22.666    1    1136    1p4vyw2jan43d    SGA:    3667    WAITING    UNKNOWN    193
22:04:22.666    1    2472        SGA:    1926    WAITING    UNKNOWN    25
22:04:32.846    1    1136    1p4vyw2jan43d    SGA:    4176    WAITING    UNKNOWN    196
22:04:32.846    1    2472        SGA:    2434    WAITING    UNKNOWN    48
复制

注意:以上输出，比如第一行，代表在 22:03:32.116，节点1的 session 1136 最终阻塞了 82 个 session. 顺着时间往下看，可见节点1的 session 1136 是问题期间最严重的 holder，它在每个采样点都阻塞了100多个 session，并且它持续等待 SGA: allocation forcing component growth，注意观察其 seq# 您会发现该 event 的 seq# 在不断变化，表明该 session并未完全 hang 住，由于时间正好发生在夜间 22:00 左右,这显然是由于自动收集统计信息 job导致 shared memory resize 造成，因此可以结合 Scheduler/MMAN 的 trace 以及 dba_hist_memory_resize_ops 的输出进一步确定问题。

注意：
1) blocking_session_count 指某一个 holder 最终阻塞的 session 数，比如 a <- b<- c （a被b阻塞,b又被c阻塞），只计算c阻塞了1个 session，因为中间的b可能在不同的阻塞链中发生重复。
2) 如果最终的 holder 没有被 ash 采样(一般因为该holder处于空闲)，比如 a<- c 并且b<- c (a被c阻塞，并且b也被c阻塞)，但是c没有采样，那么以上脚本无法将c统计到最终holder里，这可能会导致一些遗漏。
3) 注意比较 blocking_session_count 的数量与第3步查询的每个采样点的总 session_count 数，如果每个采样点的 blocking_session_count 数远小于总 session_count 数，那表明大部分 session 并未记载 holder，因此本查询的结果并不能代表什么。
4) 在 Oracle 10g 中，ASH并没有 blocking_inst_id 列，在以上所有的脚本中，您只需要去掉该列即可，因此 10g 的 ASH 一般只能用于诊断单节点的问题。

其他关于 ASH 的应用

除了通过 ASH 数据来找 holder 以外，我们还能用它来获取很多信息(基于数据库版本有所不同)：
比如通过 PGA_ALLOCATED 列来计算每个采样点的最大 PGA，合计 PGA 以分析ora-4030/Memory Swap 相关问题；
通过 TEMP_SPACE_ALLOCATED 列来分析临时表空间使用情况；
通过 IN_PARSE/IN_HARD_PARSE/IN_SQL_EXECUTION 列来分析 SQL 处于 parse 还是执行阶段;
通过 CURRENT_OBJ#/CURRENT_FILE#/CURRENT_BLOCK# 来确定 I/O 相关等待发生的对象.

对于面试就先说这么多，这里先简单记录下来，分享给有需要的小伙伴们。如果此文对您有帮助，欢迎点赞、在看与转发，写作不易，举手之劳，便是对作者最大的支持。

————————————————————————————
公众号：JiekeXu DBA之路
墨天轮：https://www.modb.pro/u/4347
CSDN ：https://blog.csdn.net/JiekeXu
腾讯云：https://cloud.tencent.com/developer/user/5645107
————————————————————————————