完美的执行计划导致的性能问题(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 |
----------------------------------------------------------------------------------------------------------------------
从这个案例来看,发现了问题,在问题解释不通的情况下,不要轻易放弃,多想想方法来佐证自己的推论才可能发现最终的问题。而且看似完美的执行计划并不能说明性能一定是好的,稳定的,需要根据具体的情况来评估。
- Selenium2+python自动化35-获取元素属性
- 2016广东工业大学新生杯决赛网络同步赛暨全国新生邀请赛 题解&源码
- 深入浅出MongoDB复制
- Selenium2+python自动化34-获取输入框联想词
- 分解质因子(个人模版)
- 高斯混合聚类(GMM)及代码实现
- 预处理素数(个人模版)
- Cnm%(个人模版)
- Selenium2+python自动化33-文件上传(send_keys)
- hive的partition的作用和使用方法
- 线段树,最大值查询位子(个人模版)
- set使用实例1+lower_bound(val)(个人模版)
- Selenium2+python自动化29-js处理多窗口
- 谷歌「机弦」有何玄机?
- JavaScript 教程
- JavaScript 编辑工具
- JavaScript 与HTML
- JavaScript 与Java
- JavaScript 数据结构
- JavaScript 基本数据类型
- JavaScript 特殊数据类型
- JavaScript 运算符
- JavaScript typeof 运算符
- JavaScript 表达式
- JavaScript 类型转换
- JavaScript 基本语法
- JavaScript 注释
- Javascript 基本处理流程
- Javascript 选择结构
- Javascript if 语句
- Javascript if 语句的嵌套
- Javascript switch 语句
- Javascript 循环结构
- Javascript 循环结构实例
- Javascript 跳转语句
- Javascript 控制语句总结
- Javascript 函数介绍
- Javascript 函数的定义
- Javascript 函数调用
- Javascript 几种特殊的函数
- JavaScript 内置函数简介
- Javascript eval() 函数
- Javascript isFinite() 函数
- Javascript isNaN() 函数
- parseInt() 与 parseFloat()
- escape() 与 unescape()
- Javascript 字符串介绍
- Javascript length属性
- javascript 字符串函数
- Javascript 日期对象简介
- Javascript 日期对象用途
- Date 对象属性和方法
- Javascript 数组是什么
- Javascript 创建数组
- Javascript 数组赋值与取值
- Javascript 数组属性和方法
- Linux基础第二课——系统架构
- Day13.继承&多态
- Linux第三课——目录操作
- Linux基础第四课——文件操作
- Linux基础第五课——用户管理
- Linux基础第六课——grep|awk|sort|uniq
- Python向上取整,向下取整以及四舍五入函数
- 使用requests模块post payload请求
- 解决HTTP status code is not handled or not allowed
- Day8.函数那些事儿
- mac下更改Jupyter notebook工作目录
- Scrapy中将item字段转为简体or繁体
- Mac OS 安装Fiddler
- Python requests模块解析XML
- python requests提示警告InsecureRequestWarning