job处理缓慢的性能问题排查与分析（r4笔记第18天)
公众号：杨建荣的学习笔记 · 作者：r4笔记第18天 · 发布：2015-01-17 22:34:28 · 原文链接
昨天开发的同事找到我说，生产有个job处理数据的速度很慢，想让我帮忙看看是怎么回事，最近碰到这种问题相对比较多了，但是问题的原因也是五花八门。我还是大体找他们了解了下情况，说有一个Job是处理文件传输的，但是从目前的运行情况来看，处理速度很慢，基本没什么进展，我向他们确认这几天是否有数据变更的操作，他们说没有。得到这个确认查看问题的方向就有明显的不同，我还是照例查看了一下数据库负载，锁情况。但是么有发现什么信息。
从数据库的负载来看，负载倒不高。
| Snap Id | Snap Time | Sessions | Cursors/Session | |
|---|---|---|---|---|
| Begin Snap: | 17844 | 16-Jan-15 12:00:37 | 303 | 4.2 |
| End Snap: | 17845 | 16-Jan-15 13:00:40 | 303 | 4.4 |
| Elapsed: | 60.04 (mins) | |||
| DB Time: | 119.10 (mins) |
Load Profile
| Per Second | Per Transaction | Per Exec | Per Call | |
|---|---|---|---|---|
| DB Time(s): | 2.0 | 0.1 | 0.00 | 0.00 |
| DB CPU(s): | 1.2 | 0.1 | 0.00 | 0.00 |
| Redo size: | 1,222,354.8 | 56,665.6 | ||
| Logical reads: | 54,092.4 | 2,507.6 | ||
| Block changes: | 4,395.0 | 203.7 | ||
| Physical reads: | 5,172.7 | 239.8 | ||
| Physical writes: | 273.2 | 12.7 | ||
| User calls: | 4,952.3 | 229.6 | ||
| Parses: | 12.9 | 0.6 | ||
| Hard parses: | 1.1 | 0.1 | ||
| W/A MB processed: | 1.0 | 0.1 | ||
| Logons: | 0.1 | 0.0 | ||
| Executes: | 3,000.2 | 139.1 | ||
| Rollbacks: | 0.0 | 0.0 | ||
| Transactions: | 21.6 |
接下来看看等待事件，还是没有发发现特殊之处。
Top 5 Timed Foreground Events
| Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
|---|---|---|---|---|---|
| DB CPU | 4,204 | 58.83 | |||
| db file sequential read | 1,539,592 | 3,003 | 2 | 42.03 | User I/O |
| log file sync | 79,884 | 164 | 2 | 2.30 | Commit |
| direct path read | 14,973 | 68 | 5 | 0.95 | User I/O |
| control file sequential read | 43,790 | 18 | 0 | 0.25 | System I/O |
从时间模型的情况来看，资源消耗还在在I/O上。
| Statistic Name | Time (s) | % of DB Time |
|---|---|---|
| sql execute elapsed time | 6,440.43 | 90.12 |
| DB CPU | 4,204.39 | 58.83 |
| RMAN cpu time (backup/restore) | 88.32 | 1.24 |
这个时候和开发做一个简短的沟通，最起码得明确一些信息，要不大海捞针的查问题还是针对性不强，他们说Job处理速度慢，是哪个job呢，他们反馈说是MF1ppMD的job
我从Sql Order by Elapsed time中查得MFppMD的相关top sql有几个，但是这几个语句执行时间都很短，都在0.01秒以内，性能算是不错的了。
| Executions | %Total | %IO | SQL Module | /* */ select count (1) from RP… | ||||
| 775.20 | 1,671,968 | 0.00 | 10.85 | 23.36 | 79.06 | gqy0gxb05ycg4 | pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) | select L9_SPLIT_PERIOD into :b… |
| 717.11 | 14,042 | 0.05 | 10.03 | 99.84 | 0.00 | b91t3s9kz9fg8 | pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) | /* */ SELECT SUBSCRIBER_ID, EF… |
| 394.40 | 1,167,196 | 0.00 | 5.52 | 39.54 | 63.55 | dm1d93bw2jdzc | MF1ppMD@ccbdbpr1 (TNS V1-V3) | INSERT INTO RATED_EVENT (L3_NE… |
| 236.40 | 1 | 236.40 | 3.31 | 81.22 | 9.47 | 477uum1qjcpqh | oracle@ccbstbpr2 (TNS V1-V3) | SELECT “A1”.”TABLE_ISSUE_CODE”… |
| 198.10 | 1 | 198.10 | 2.77 | 79.23 | 10.20 | 4uddwupn9fw9b | TOAD 9.6.0.27 | /* */ SELECT SUBSCRIBER_ID, DY… |
| 136.72 | 1,166,948 | 0.00 | 1.91 | 34.69 | 67.32 | 7p5kmytfrygy2 | MF1ppMD@ccbdbpr1 (TNS V1-V3) | /* */ Update RPR1_SUBS_RERATE … |
| 80.38 | 196,631 | 0.00 | 1.12 | 22.43 | 79.87 | 7x26ag6bsacb3 | pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) | insert into MF1_DUPCHECK_KEYS … |
从系统优化的角度来说，ppMD的性能问题还是比较奇怪的。
继续查看其它的指标类型，一边注意ppMD相关的job，一边留意是否是其它的原因导致的。
当我看到Sql Order by Executions的时候。注意到一个奇怪的地方，执行频率最高的正是ppMD这个job
| Rows Processed | Elapsed Time (s) | %IO | SQL Module | <span color:white;”=”” style=”word-wrap: break-word;font-size: 11px”>SQL Text | ||||
| 2,333,806 | 0 | 0.00 | 43.03 | 106.28 | 0.00 | a69bnysapnrt5 | MF1ppMD@ccbdbpr1 (TNS V1-V3) | select ROWID , PRIM_RESOURCE_T… |
| 1,671,968 | 1,664,009 | 1.00 | 775.20 | 23.36 | 79.06 | gqy0gxb05ycg4 | pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) | /* */ SELECT CYCLE_CODE, CYCLE… |
| 1,167,196 | 1,166,977 | 1.00 | 394.40 | 39.54 | 63.55 | dm1d93bw2jdzc | MF1ppMD@ccbdbpr1 (TNS V1-V3) | select sk.rowid , sk.subscribe… |
但是仔细查看会发现一个奇怪的现象， Rows Processed却是0.这是一个比较特殊的情况，这个参数代表的意思是SQL在快照时间内累计执行所处理的总行数。代表0说明执行了几百万次，但是没有任何数据处理，相当于空跑。
来看看执行的sql语句是什么。
select ROWID,
PRIM_RESOURCE_TP,
PRIM_RESOURCE_VAL,
TO_CHAR(EFFECTIVE_DATE, ‘YYYYMMDDHH24MISS’),
TO_CHAR(EXPIRATION_DATE, ‘YYYYMMDDHH24MISS’),
TO_CHAR(SYS_CREATION_DATE, ‘YYYYMMDDHH24MISS’),
TO_CHAR(SYS_UPDATE_DATE, ‘YYYYMMDDHH24MISS’),
OPERATOR_ID,
APPLICATION_ID,
DL_SERVICE_CODE,
DL_UPDATE_STAMP,
FUTURE_1,
FUTURE_2,
FUTURE_3
into :b0 :b1,
:b2 :b3,
:b4 :b5,
:b6 :b7,
:b8 :b9,
:b10 :b11,
:b12 :b13,
:b14 :b15,
:b16 :b17,
:b18 :b19,
:b20 :b21,
:b22 :b23,
:b24 :b25,
:b26 :b27
from MI9_PAID_SUBSCR
where (((PRIM_RESOURCE_TP = :b2 and PRIM_RESOURCE_VAL = :b4) and
EFFECTIVE_DATE <= TO_DATE(:b6, ‘YYYYMMDDHH24MISS’)) and
(EXPIRATION_DATE is null or
EXPIRATION_DATE > TO_DATE(:b6, ‘YYYYMMDDHH24MISS’)))
这是一个很简单的查询，一看这个表，我就恍然大悟了，这个表是在这两天才做的变更，在最新的需求中需要创建这个表，从目前的需求来看，这个表需要同步一些数据，但是数据的同步机制还没有达成共识，所以最后临时决定先把这个表创建好，让job在校验的时候不出错，但是表里面没有数据，暂时先按照dummy表来处理。但是在升级中没有包含这个变更,只是提供了临时的补丁做了修复。
看来这个dummy表还是对数据的处理造成了严重的影响，导致了Job空跑。开发有时候提供的信息还是需要斟酌的，不一定都是正确的。需要我们在特定的问题情况下去确认。
最后和开发做了沟通，他们在做了进一步的分析之后确认是这个新表导致的问题，需要进一步讨论技术实现细节。
最后小结一下。
可能有些问题的处理和诊断，不一定是IO,CPU等异常导致的，很可能是业务层出现的问题，需要我们从awr报告中发现细节来佐证自己的判断。
有时候问题排查的方向需要自己来按照合理的流程来做，有时候客户，同事提供的信息自己需要辨识，可能有些问题是他们没有意识到，但是对问题排查的方向影响还是比较大的。