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