从数据库的负载来看，负载倒不高。
| 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秒以内，性能算是不错的了。
|
Elapsed Time (s) |
Executions |
Elapsed Time per Exec (s) |
%Total |
%CPU |
%IO |
SQL Id |
SQL Module |
SQL Text |
|
898.97 |
14,042 |
0.06 |
12.58 |
99.81 |
0.00 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
/* */ select count (1) from RP... |
|
|
775.20 |
1,671,968 |
0.00 |
10.85 |
23.36 |
79.06 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
/* */ SELECT CYCLE_CODE, CYCLE... |
|
|
722.13 |
1,167,005 |
0.00 |
10.10 |
12.88 |
91.02 |
MF1ppMD@ccbdbpr1 (TNS V1-V3) |
select L9_SPLIT_PERIOD into :b... |
|
|
717.11 |
14,042 |
0.05 |
10.03 |
99.84 |
0.00 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
/* */ select count (1) from RP... |
|
|
478.57 |
368,271 |
0.00 |
6.70 |
7.07 |
95.56 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
/* */ SELECT SUBSCRIBER_ID, EF... |
|
|
394.40 |
1,167,196 |
0.00 |
5.52 |
39.54 |
63.55 |
MF1ppMD@ccbdbpr1 (TNS V1-V3) |
select sk.rowid , sk.subscribe... |
|
|
338.74 |
12,793 |
0.03 |
4.74 |
14.76 |
86.26 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
INSERT INTO RATED_EVENT (L3_NE... |
|
|
236.40 |
1 |
236.40 |
3.31 |
81.22 |
9.47 |
oracle@ccbstbpr2 (TNS V1-V3) |
SELECT "A1"."TABLE_ISSUE_CODE"... |
|
|
228.46 |
1 |
228.46 |
3.20 |
83.76 |
6.67 |
oracle@ccbstbpr2 (TNS V1-V3) |
SELECT "A1"."TABLE_ISSUE_CODE"... |
|
|
198.10 |
1 |
198.10 |
2.77 |
79.23 |
10.20 |
TOAD 9.6.0.27 |
select*from ac1_control_hist w... |
|
|
197.33 |
368,304 |
0.00 |
2.76 |
11.04 |
91.58 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
/* */ SELECT SUBSCRIBER_ID, DY... |
|
|
136.72 |
1,166,948 |
0.00 |
1.91 |
34.69 |
67.32 |
MF1ppMD@ccbdbpr1 (TNS V1-V3) |
select ROWID , BAN , COMPANY_C... |
|
|
85.23 |
555,724 |
0.00 |
1.19 |
53.23 |
49.46 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
/* */ Update RPR1_SUBS_RERATE ... |
|
|
80.38 |
196,631 |
0.00 |
1.12 |
22.43 |
79.87 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
/* */ SELECT SUBSCRIBER_ID, OF... |
|
|
72.03 |
4,448 |
0.02 |
1.01 |
29.52 |
71.04 |
MF1ppMD@ccbdbpr1 (TNS V1-V3) |
insert into MF1_DUPCHECK_KEYS ... |
从系统优化的角度来说，ppMD的性能问题还是比较奇怪的。
继续查看其它的指标类型，一边注意ppMD相关的job，一边留意是否是其它的原因导致的。
当我看到Sql Order by Executions的时候。注意到一个奇怪的地方，执行频率最高的正是ppMD这个job
|
Executions |
Rows Processed |
Rows per Exec |
Elapsed Time (s) |
%CPU |
%IO |
SQL Id |
SQL Module |
SQL Text |
|
2,333,806 |
0 |
0.00 |
43.03 |
106.28 |
0.00 |
MF1ppMD@ccbdbpr1 (TNS V1-V3) |
select ROWID , PRIM_RESOURCE_T... |
|
|
1,671,968 |
1,664,009 |
1.00 |
775.20 |
23.36 |
79.06 |
pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3) |
/* */ SELECT CYCLE_CODE, CYCLE... |
|
|
1,167,196 |
1,166,977 |
1.00 |
394.40 |
39.54 |
63.55 |
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报告中发现细节来佐证自己的判断。
有时候问题排查的方向需要自己来按照合理的流程来做，有时候客户，同事提供的信息自己需要辨识，可能有些问题是他们没有意识到，但是对问题排查的方向影响还是比较大的。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/8494287/viewspace-1422007/ ，如需转载，请注明出处，否则将追究法律责任。
