昨天开发的同事找到我说,生产有个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报告中发现细节来佐证自己的判断。 有时候问题排查的方向需要自己来按照合理的流程来做,有时候客户,同事提供的信息自己需要辨识,可能有些问题是他们没有意识到,但是对问题排查的方向影响还是比较大的。