完美的执行计划导致的性能问题(r4笔记第17天)

今天现场的开发同事反馈有一个job处理数据的速度很慢,从半夜2点开始运行,结果到了早上8点还没有运行完,最后无奈kill掉了进程。等我刚到公司,他们想让我查查倒底是什么原因导致的执行速度很慢。 首先和他们简单沟通了下,问最近有什么新的变更吗,他们说没有,平时跑这个job的用户量不是很大,今天早晨调用job的时候用户量要略微大些。 了解了这些我查看了下数据库的负载,发现在问题发生的时间段,没有明显的性能抖动。

DB_NAME   BEGIN_SNAP   END_SNAP SNAPDATE                 LVL DURATION_MINS     DBTIME
--------- ---------- ---------- ----------------- ---------- ------------- ----------
XXXXX     13222      13223 16 Jan 2015 00:00          1            60         14
               13223      13224 16 Jan 2015 01:00          1            60          1
               13224      13225 16 Jan 2015 02:00          1            60          1
               13225      13226 16 Jan 2015 03:00          1            60        180
               13226      13227 16 Jan 2015 04:00          1            60        260
               13227      13228 16 Jan 2015 05:00          1            60        167
               13228      13229 16 Jan 2015 06:00          1            60        210
               13229      13230 16 Jan 2015 07:00          1            60        138
               13230      13231 16 Jan 2015 08:00          1            60        118
               13231      13232 16 Jan 2015 09:00          1            60        170
               13232      13233 16 Jan 2015 10:00          1            60        221

然后抓取了一个awr报告来看看到底是哪里出了问题。 数据库的整体负载情况如下,可以看出在问题发生的时间段,每秒的redo有2M左右,这个库的使用不是很频繁,而且数据量相对来说不是很大,所以相比来说还是比较繁忙的。

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

13226

16-Jan-15 04:00:22

255

4.3

End Snap:

13228

16-Jan-15 06:00:28

253

4.5

Elapsed:

120.11 (mins)

DB Time:

427.54 (mins)

Load Profile

Per Second

Per Transaction

Per Exec

Per Call

DB Time(s):

3.6

0.4

0.00

0.00

DB CPU(s):

0.7

0.1

0.00

0.00

Redo size:

2,840,080.5

347,986.4

Logical reads:

36,781.2

4,506.7

Block changes:

4,940.6

605.4

Physical reads:

1,502.6

184.1

Physical writes:

488.4

59.8

User calls:

7,156.8

876.9

Parses:

12.7

1.6

Hard parses:

4.1

0.5

W/A MB processed:

1.0

0.1

Logons:

0.1

0.0

Executes:

2,238.8

274.3

Rollbacks:

0.0

0.0

Transactions:

8.2

没有发现很明显的性能问题之后,直接进入等待事件和时间模型统计信息。

Top 5 Timed Foreground Events

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

db file sequential read

4,568,909

14,710

3

57.34

User I/O

DB CPU

5,316

20.72

db file parallel read

1,557,170

5,163

3

20.13

User I/O

log file sync

58,073

785

14

3.06

Commit

db file scattered read

127,236

194

2

0.75

User I/O

从等待事件来看没有lock contention相关的等待事件,说明也不大可能是锁的原因。 Time Model Statistics

Statistic Name

Time (s)

% of DB Time

sql execute elapsed time

23,044.78

89.83

DB CPU

5,316.31

20.72

从上面可以得出问题还是主要在基于IO消耗的sql上,直接进入”SQL ordered by Elapsed Time"来查看更多的细节。 可以明显得看到有一个job消耗了大量的时间,但是在两个小时的时间内还没有执行完。这个很可能就是问题所在,其它的sql占有的比例都不高。

Elapsed Time (s)

Executions

Elapsed Time per Exec (s)

%Total

%CPU

%IO

SQL Id

SQL Module

SQL Text

7,201.85

0

28.07

7.78

95.17

527mj496fz1r1

EnvelopeMT@ccbdbpr5 (TNS V1-V3)

SELECT /*+ ordered use_nl (RAT...

1,945.01

3,984

0.49

7.58

8.94

91.79

50a6wp0574z2s

EnvelopeMT@ccbdbpr5 (TNS V1-V3)

/* */ UPDATE TED_EVENT SET L...

查看“SQL ordered by Gets”, buffer gets有近133G(17,418,703*8k)。就这一个查询还是相当的庞大的消耗。

Buffer Gets

Executions

Gets per Exec

%Total

Elapsed Time (s)

%CPU

%IO

SQL Id

SQL Module

SQL Text

17,418,703

0

6.57

7,201.85

7.78

95.17

527mj496fz1r1

EnvelopeMT@ccbdbpr5 (TNS V1-V3)

SELECT /*+ ordered use_nl (RAT...

来看看是什么样的sql语句导致了如此的性能问题。 语句大体如下:

SELECT /*+ ordered use_nl (RATED_EVENT) index (RATED_EVENT
             RATED_EVENT_1UQ) */  RPR3_CUSTOMER_EX.GROUP_ID, 'USAG'
                     ||RPAD(LTRIM(RATED_EVENT.BA_NO),12)
                     .......
                     ||RPAD(NVL(TRIM(TO_CHAR(L9_DUMMY_STRING_2)),' '),10)
                     ||RPAD(0,9)
                      FROM RPR3_CUSTOMER_EX, RATED_EVENT  WHERE
             RATED_EVENT.CYCLE_CODE=:h_cycleCode AND
             RATED_EVENT.CYCLE_MONTH=:CYCLE_MONTH AND
             RATED_EVENT.SUB_PARTITION_ID=:h_subPartitionId AND
             RATED_EVENT.CUSTOMER_ID=RPR3_CUSTOMER_EX.CUSTOMER_ID AND
             RPR3_CUSTOMER_EX.CYCLE_MONTH=RATED_EVENT.CYCLE_MONTH AND
             RPR3_CUSTOMER_EX.CYCLE_CODE=RATED_EVENT.CYCLE_CODE AND
             RPR3_CUSTOMER_EX.CYCLE_YEAR=RATED_EVENT.CYCLE_YEAR AND  (
             RPR3_CUSTOMER_EX.BA_NO =-1   OR (RATED_EVENT.BA_NO=RPR3_CUSTOMER_
             EX.BA_NO )) AND  RATED_EVENT.CYCLE_YEAR=:h_cycleYear AND
             EVENT_TYPE_ID NOT IN (1110189,7790,33131,1156067) AND (
             EVENT_STATE in ('N') or EVENT_STATE is null ) and
             L9_DISPLAY_ON_BILL='Y'

其中RATED_EVENT这个表相当的大,有近5亿条数据,做了分区。而RPR3_CUSTOMER_EX这个表比较奇怪,查询数据,竟然1条数据都没有。 带着疑问,查看了执行计划,从执行的情况来看着条sql语句没有什么问题。

Plan hash value: 1180507974
--------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |                     |     1 |   344 |    18   (0)| 00:00:01 |       |       |
|   1 |  NESTED LOOPS                      |                     |       |       |            |          |       |       |
|   2 |   NESTED LOOPS                     |                     |     1 |   344 |    18   (0)| 00:00:01 |       |       |
|*  3 |    INDEX FULL SCAN                 | RPR3_CUSTOMER_EX_PK |     1 |    78 |     3   (0)| 00:00:01 |       |       |
|   4 |    PARTITION RANGE SINGLE          |                     |    12 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|*  5 |     INDEX RANGE SCAN               | RATED_EVENT_1UQ     |    12 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|*  6 |   TABLE ACCESS BY LOCAL INDEX ROWID| RATED_EVENT         |     6 |  1596 |    16   (0)| 00:00:01 |     1 |     1 |
--------------------------------------------------------------------------------------------------------------------------

但是为什么执行计划如此完美的sql,预计执行时间需要1秒,实际上却执行了两个多小时还没有执行完。 我的关注点都集中在了RPR3_CUSTOMER_EX这个表上,表里没有数据,执行计划也没有问题,但是执行时间却相差几千倍。 带着这个疑问和开发再次沟通,没有得到太多相关的细节。最后抓取了一个addm报告。 得到的一个建议和这条sql有关。

 Rationale
      The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
      This part of database time may be improved by the SQL Tuning Advisor.
   Rationale
      Database time for this SQL was divided as follows: 100% for SQL
      execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
      execution.
   Rationale
      I/O and Cluster wait for TABLE PARTITION
      "RATED_EVENT.C25_M10_S8" with object ID 672092 consumed 75% of
      the database time spent on this SQL statement.
   Rationale
      I/O and Cluster wait for INDEX PARTITION
      "RATED_EVENT_1UQ.C25_M10_S8" with object ID 672095 consumed 24%
      of the database time spent on this SQL statement.

可以看到大量的IO都在一个分区 C25_M10_S8上面,看到这个自己的第一反应是可能统计信息导致的。目前在生产环境中没隔一段时间都会收集一次统计信息。 partiton_name high_value tablespace_name LOGGING analyzed_time C25_M10_S6 25, 10, 30 DATAH01 1 YES DISABLED YES 06-DEC-14 C25_M10_S7 25, 10, 35 DATAH01 1 YES DISABLED YES 24-NOV-14 C25_M10_S8 25, 10, 40 DATAH01 1 YES DISABLED YES 16-DEC-14 C25_M10_S9 25, 10, 45 DATAH01 1 YES DISABLED YES 24-NOV-14 C25_M10_S10 25, 10, 50 DATAH01 1 YES DISABLED YES 24-NOV-14 可以看到分区的统计时间是在上个月中,查看了下这个分区中的数据情况,发现和数据字典中的统计信息基本没有差别。 SQL> set time on 12:44:45 SQL> set timing on 12:44:48 SQL> select /*+ index_ffs(RATED_EVENT,RATED_EVENT_1UQ ) parallel_index(RATED_EVENT,RATED_EVENT_1UQ,8) */ count(*) from RATED_EVENT partition(c25_m10_s8) ; 11067075 Elapsed: 00:00:02.04 所以问题又回到了原点,这个问题看似很清晰,但是又从道理上说不通。 转眼一想,那个rpr3的表可能是临时表,这样问题就能解释通了。为了简单验证,自己尝试导出这个表,然后查看对应的建表语句是下面的样子。 CREATE GLOBAL TEMPORARY TABLE "RPR3_CUSTOMER_EX" ("CUSTOMER_ID" NUMBER(9, 0) CONSTRAINT "RPR3CRE_CUSTOMER_ID_NN" NOT NULL ENABLE, "SYS_CREATION_DATE" DATE CONSTRAINT "RPR3CRE_SYS_CREATION_DATE_NN" NOT NULL ENABLE, "SYS_UPDATE_DATE" DATE, 。。。 "BA_NO" NUMBER(12, 0) CONSTRAINT "RPR3CRE_BA_NO_NN" NOT NULL ENABLE) ON COMMIT DELETE ROWS

这样的话问题,就能说通了,至于为什么查询表中的数据是0条,一下子也就明朗了。 那么至于为什么性能变化这么大呢,这个还得从表分区的统计信息来说,这个表有5亿多条记录,查询语句中的相关分区有1千5多万的数据量, 很可能是什么地方执行计划出现了某些偏差造成的。 重新审视sql语句,发现开始的Hint还是值得注意的。 SELECT /*+ ordered use_nl (RATED_EVENT) index (RATED_EVENT RATED_EVENT_1UQ) */

对于这条sql语句的调优就相对来说有针对性了。表RPR3_CUSTOMER_EX是个临时表,表中的数据可能是不固定的。和开发做了进一步的确认,这个表中的数据还是很少的。 如果记录数很少,可以按照优化器默认的执行情况来做,就不需要手工干预了。表RPR3_CUSTOMER_EX中的数据很少,就完全可以走一个全表扫描和RATED_EVENT关联即可。 使用sqlp_profile再次验证了这个想法。执行情况也要更加稳定。

2- Using SQL Profile
--------------------
Plan hash value: 2402883198
----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name             | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |                  |     1 |   344 |    18   (0)| 00:00:01 |       |       |
|*  1 |  TABLE ACCESS BY LOCAL INDEX ROWID| RATED_EVENT      |     6 |  1596 |    16   (0)| 00:00:01 |       |       |
|   2 |   NESTED LOOPS                    |                  |     1 |   344 |    18   (0)| 00:00:01 |       |       |
|*  3 |    TABLE ACCESS FULL              | RPR3_CUSTOMER_EX |     1 |    78 |     2   (0)| 00:00:01 |       |       |
|   4 |    PARTITION RANGE SINGLE         |                  |    12 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|*  5 |     INDEX RANGE SCAN              | RATED_EVENT_1UQ  |    12 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
----------------------------------------------------------------------------------------------------------------------

从这个案例来看,发现了问题,在问题解释不通的情况下,不要轻易放弃,多想想方法来佐证自己的推论才可能发现最终的问题。而且看似完美的执行计划并不能说明性能一定是好的,稳定的,需要根据具体的情况来评估。

原文发布于微信公众号 - 杨建荣的学习笔记(jianrong-notes)

原文发表时间:2015-01-16

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏数据和云

追本溯源:Oracle 只读表空间的探索实践

作者简介 ? 胡中豪 云和恩墨西区交付工程师,多年一线 DBA 经验,曾服务于运营商、电网、政府行业、银行等行业客户;擅长数据库故障处理、性能优化、实施升级 本...

30330
来自专栏杨建荣的学习笔记

SQL*Loader-805的解决(r2笔记36天)

使用sql*loader是大型项目中数据迁移的利器。如果是外部系统,其他数据库到oracle的数据迁移,使用文本式文件是最兼容的方式。 sqlldr的加载效率是...

32580
来自专栏杨建荣的学习笔记

CPU 100%负载的性能优化分析(r7笔记第40天)

今天收到报警邮件,提示在短时间内DB time有了很大的抖动。报警邮件如下: ZABBIX-监控系统: ------------------------...

37140
来自专栏乐沙弥的世界

ORA-01652: unable to extend temp segment by 8192...

      最近在rebuild index时提示unable to extend temp segment by 8192 in tablespace..的错...

20410
来自专栏乐沙弥的世界

对比 PL/SQL profiler 剖析结果

      使用PL/SQL PROFILER 剖析PL/SQL代码是快速定位PL/SQL代码段最有效的方法。在上一篇文章使用PL/SQL PROFILER 定...

14210
来自专栏杨建荣的学习笔记

物化视图相关的性能改进 (r7笔记第58天)

今天早上开发的一个同事找到我说他早上做了一个统计查询,但是感觉速度很慢,已经过了一个小时了还没有反应。想让我看看是什么情况。 我通过v$session查到有一个...

34850
来自专栏Hadoop数据仓库

HAWQ技术解析(七) —— 存储分布

        在HAWQ中创建一个表时,应该预先对数据如何分布、表的存储选项、数据导入导出方式和其它HAWQ特性做出选择,这些都将对数据库性能有极大影响。理解...

492100
来自专栏杨建荣的学习笔记

海量数据迁移之外部表切分(r2笔记52天)

在前几篇中讨论过海量数据的并行加载,基本思路就是针对每一个物理表都会有一个对应的外部表,在做数据迁移的时候,如果表有上百G的时候,一个物理表对应一个外部表性能上...

31070
来自专栏数据库新发现

字符集问题的初步探讨(二)

原文发表于itpub技术丛书《Oracle数据库DBA专题技术精粹》,未经许可,严禁转载本文.

14520
来自专栏杨建荣的学习笔记

一条运行了3天的"简单"的sql(r2笔记82天)

早上刚到公司,查看系统的负载,就马上看到一个进程的执行时间已经有3天了。 而且cpu的消耗极高。 Tasks: 2374 total, 19 running,...

33550

扫码关注云+社区

领取腾讯云代金券