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