job处理缓慢的性能问题排查与分析

昨天开发的同事找到我说，生产有个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秒以内，性能算是不错的了。

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	06pyusmmaz7bn	pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)	/* */ 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 CYCLE_CODE, CYCLE...
722.13	1,167,005	0.00	10.10	12.88	91.02	4pk0rrvtwzks1	MF1ppMD@ccbdbpr1 (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 count (1) from RP...
478.57	368,271	0.00	6.70	7.07	95.56	bxvj6kvn4nauu	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)	select sk.rowid , sk.subscribe...
338.74	12,793	0.03	4.74	14.76	86.26	9a9f4faqznrup	pm1EnvelopeMT@ccbdbpr2 (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"...
228.46	1	228.46	3.20	83.76	6.67	5tj257zw2nkgf	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*from ac1_control_hist w...
197.33	368,304	0.00	2.76	11.04	91.58	48ssma1266cjj	pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)	/* */ SELECT SUBSCRIBER_ID, DY...
136.72	1,166,948	0.00	1.91	34.69	67.32	7p5kmytfrygy2	MF1ppMD@ccbdbpr1 (TNS V1-V3)	select ROWID , BAN , COMPANY_C...
85.23	555,724	0.00	1.19	53.23	49.46	busdr4jzj494w	pm1EnvelopeMT@ccbdbpr2 (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)	/* */ SELECT SUBSCRIBER_ID, OF...
72.03	4,448	0.02	1.01	29.52	71.04	fdjwyd97srn8k	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	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报告中发现细节来佐证自己的判断。
有时候问题排查的方向需要自己来按照合理的流程来做，有时候客户，同事提供的信息自己需要辨识，可能有些问题是他们没有意识到，但是对问题排查的方向影响还是比较大的。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/23718752/viewspace-1405481/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/23718752/viewspace-1405481/