完美的执行计划导致的性能问题

今天现场的开发同事反馈有一个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 |
----------------------------------------------------------------------------------------------------------------------
从这个案例来看，发现了问题，在问题解释不通的情况下，不要轻易放弃，多想想方法来佐证自己的推论才可能发现最终的问题。而且看似完美的执行计划并不能说明性能一定是好的，稳定的，需要根据具体的情况来评估。

时间： 2024-10-23 05:22:40

完美的执行计划导致的性能问题的相关文章

SQLServer中的执行计划缓存由于长时间缓存对性能造成的干扰

原文:SQLServer中的执行计划缓存由于长时间缓存对性能造成的干扰   本文出处:http://www.cnblogs.com/wy123/p/7190785.html  (保留出处并非什么原创作品权利,本人拙作还远远达不到,仅仅是为了链接到原文,因为后续对可能存在的一些错误进行修正或补充,无他)   先抛出一个性能问题,前几天遇到一个生产环境性能极其低下的存储过程,开发人员根据具体的业务逻辑和返回的数据量,猜测到这个存储过程的执行应该不会有这么慢.当时意识到可能是执行计划缓存的问题,因为当

《Oracle高性能SQL引擎剖析：SQL优化与调优机制详解》一2.5　执行计划中其他信息的含义

2.5 执行计划中其他信息的含义 通过DBMS_XPLAN输出执行计划,除了计划本身外,还可以获得一些其他信息帮助我们进一步分析执行计划及语句性能. 2.5.1 查询块和对象别名 在使用DBMS_XPLAN显示执行计划时,选择'ADVANCED'预定义格式作为参数或者加入'ALIAS'控制字符串,可以在输出中看到以下内容: Query Block Name / Object Alias (identified by operation id): -------------------------

RDS SQL Server - 专题分享 - 巧用执行计划缓存之Single-used plans

背景引入 执行计划缓存是SQL Server内存管理中非常重要的特性,这篇系列文章我们探讨执行计划缓存设计中遇到的single-used plans问题,以及如何发现.如何定性和定量分析single-used plans带来的影响,最后我们使用两种方法来解决这个问题. 什么是Single-used Plans 要解释清楚什么是Single-used Plans,首先需要解释SQL语句执行计划缓存是什么?SQL Server执行每一条SQL语句之前,会从执行计划缓存内存中查看是否存在本条语句的执行

SQL Server 执行计划缓存

原文:SQL Server 执行计划缓存 标签:SQL SERVER/MSSQL SERVER/数据库/DBA/内存池/缓冲区 概述   了解执行计划对数据库性能分析很重要,其中涉及到了语句性能分析与存储,这也是写这篇文章的目的,在了解执行计划之前先要了解一些基础知识,所以文章前面会讲一些概念,学起来会比较枯燥,但是这些基础知识非常重要.   目录  概述  基础概念  怎样缓存执行计划  SQL Server自动删除执行计划  重新编译执行计划  测试  执行计划相关系统视图  手动清空缓存执

RDS SQL Server - 专题分享 - 巧用执行计划缓存之执行计划编译

背景引入 执行计划缓存是SQL Server内存管理中非常重要的特性,这篇文章是巧用执行计划缓存系列文章之五,探讨如何从执行计划缓存中获取查询语句执行计划编译的性能消耗,比如: 编译时间消耗 编译CPU消耗 编译内存消耗 缓存大小消耗 等等一系列非常有价值的统计信息. 什么是执行计划编译 SQL查询语句在提交到SQL Server主机服务之后,数据查询访问动作发生之前,SQL Server的编译器需要将查询语句进行编译,然后查询优化器生成最优执行计划.而这个编译和最优执行计划选择的过程,

《Oracle高性能SQL引擎剖析：SQL优化与调优机制详解》一1.2　显示执行计划

1.2 显示执行计划 我们现在知道,有三个途径可以获取查询计划:v$sql_plan.dba_hist_sql_plan和PLAN_TABLE.如果需要读取一条SQL语句的执行计划,就需要知道该条语句的SQL_ID,如果该语句存在多个游标或者执行计划,则还需要知道游标的CHILD_NUMBER或计划的哈希值(可选).而无论我们通过哪个途径来获取执行计划,显示方式主要是两种:语句查询和包DBMS_XPLAN显示. 1.2.1 通过查询语句显示计划 通过查询语句从一些视图里读出执行计划并作格式化输出

11g改变了DELETE语句的执行计划

在11.2中,如果DELETE的时候没有限制条件,且表上存在主键的话,执行计划会变为索引全扫.     在和600聊天的时候听说了这个现象,开始的时候还不是很相信.当时600特意验证了一下,事实确实如此. 于是特意自己也做了个简单的例子: SQL> select * from v$version; BANNER -------------------------------------------------------------------------------- Oracle Datab

SQL SERVER 2012 执行计划走嵌套循环导致性能问题的案例

  开发人员遇到一个及其诡异的的SQL性能问题,这段完整SQL语句如下所示: declare @UserId             INT declare @PSANo              VARCHAR(200) declare @ShipMode           VARCHAR(10) declare @CY_FLAG            VARCHAR(1) declare @PO                 VARCHAR(20) declare @BuyerName 

执行计划中的COLLECTION ITERATOR PICKLER FETCH导致的性能问题

今天开发的同事找到我,让我评估一个sql语句.因为这条语句被应用监控组给抓取出来了,需要尽快进行性能调优. sql语句比较长,是由几个Union连接起来的子查询. xxxxx UNION   SELECT /*+ leading (ar1_creditid_tab ar1_unapplied_credit) use_nl (ar1_creditid_tab ar1_unapplied_credit) */            UNIQUE            0,            MA