在客户处遇到个问题,客户昨晚清理数据,删除一些表的分区,第一个表跑了20多分钟,但是差不多数据量的另外一个表,跑了好几个小时才完成。为何类似的数据在drop 分区的时候,有那么大的差异?
检查了改删除分区的语句,发现是update了global索引,并且,还用到了parallel 8的并行。
虽然时间已经过去了一个晚上,但是根据当晚操作人员提供的信息,结合在测试库上的测试,我们还是能从已知的信息中获取一些可能导致当时运行缓慢的一些线索:
(1) 从测试库的测试看到,正常执行是有并发的PX类型的等待的。
(2) 从DBA反馈得知,当晚没有看到并发子进程,只看到单个进程。
(3) 测试有并发和没并发的drop分区,在10046的trace中行为有很大不同,有并发的主要是PX、direct path read、db file scattered read等待,没并发主要是db file sequential read等待。
(4) 设置parallel max servers为4,先运行4个并发的脚本占据并发度,再运行并发drop分区的脚本,从10046的trace看,后面执行的并发drop分区没有并发子进程,且大部分是db file sequential read等待。
执行上述的drop partition时,我们能看到相关并发进程的等待事件:
--主进程是PX Deq Credit: send blkd,表示在等待处理来自各个子进程的消息。
--这个过程一直到17:59分左右
TO_CHAR(SYSDATE,'YYYY-MM-DDHH2 EVENT SADDR SID
------------------------------ ---------------------------------------------------------------- ---------------- ----------
2014-01-15 17:06:52 local write wait 000000046F17D928 201
2014-01-15 17:06:52 PX Deq Credit: send blkd 000000046D17AEC8 239
2014-01-15 17:06:52 PX Deq: Execution Msg 000000046F171078 87
2014-01-15 17:06:52 PX Deq: Execution Msg 000000046C160510 96
2014-01-15 17:06:52 PX Deq: Execution Msg 000000046F173028 105
2014-01-15 17:06:52 PX Deq: Execution Msg 000000046B211EE8 205
2014-01-15 17:06:52 PX Deq: Execution Msg 000000046F17AEE8 177
2014-01-15 17:06:52 PX Deq: Execution Msg 000000046C179670 324
2014-01-15 17:06:52 PX Deq: Execution Msg 000000046A1780A0 326
2014-01-15 17:06:52 PX Deq: Execution Msg 000000046F181888 237
2014-01-15 17:06:52 PX Deq: Table Q Normal 000000046C16A380 186
2014-01-15 17:06:52 PX Deq: Table Q Normal 000000046A16B7F0 212
2014-01-15 17:06:52 PX Deq: Table Q Normal 000000046C17AB90 336
2014-01-15 17:06:52 PX Deq: Table Q Normal 000000046A17A050 344
2014-01-15 17:06:52 PX Deq: Table Q Normal 000000046C178150 312
2014-01-15 17:06:52 PX Deq: Table Q Normal 000000046E1720C0 214
2014-01-15 17:06:52 PX Deq: Table Q Normal 000000046D176F68 203
17 rows selected
SQL>
……
--从17:59分开始,也一直是在并发处理,主进程开始出现db file scattered read。且和PX Deq Credit: send blkd交替出现,
--重复检查该脚本的等待事件,一直到18:49分,发现该脚本交替处于db file scattered read和PX Deq Credit: send blkd。
SQL> /
TO_CHAR(SYSDATE,'YYYY-MM-DDHH2 EVENT SADDR SID
------------------------------ ---------------------------------------------------------------- ---------------- ---------- --
2014-01-15 17:59:20 db file scattered read 000000046D17AEC8 239
2014-01-15 17:59:20 PX Deq: Execution Msg 000000046F171078 87
2014-01-15 17:59:20 PX Deq: Execution Msg 000000046C160510 96
2014-01-15 17:59:20 PX Deq: Execution Msg 000000046F173028 105
2014-01-15 17:59:20 PX Deq: Execution Msg 000000046F181888 237
2014-01-15 17:59:20 PX Deq: Execution Msg 000000046F17AEE8 177
2014-01-15 17:59:20 PX Deq: Execution Msg 000000046B211EE8 205
2014-01-15 17:59:20 PX Deq: Execution Msg 000000046C179670 324
2014-01-15 17:59:20 PX Deq: Execution Msg 000000046A1780A0 326
2014-01-15 17:59:20 PX Deq: Table Q Normal 000000046C16A380 186
2014-01-15 17:59:20 PX Deq: Table Q Normal 000000046F17D928 201
2014-01-15 17:59:20 PX Deq: Table Q Normal 000000046A16B7F0 212
2014-01-15 17:59:20 PX Deq: Table Q Normal 000000046C17AB90 336
2014-01-15 17:59:20 PX Deq: Table Q Normal 000000046A17A050 344
2014-01-15 17:59:20 PX Deq: Table Q Normal 000000046C178150 312
2014-01-15 17:59:20 PX Deq: Table Q Normal 000000046E1720C0 214
2014-01-15 17:59:20 PX Deq: Table Q Normal 000000046D176F68 203
17 rows selected
……
从上面,我们可以看出,脚本在执行的时候,应该是会有并发进程出现,如果按照username=’MYTEST’查询,应该可以看得到PX的session等待。但是和当晚操作人员的沟通中得知,当天晚上,他观察到的现象是没有看到并发的进程,只看到一个进程长时间处于db file sequential read的等待,该进程是在执行4094517213的语句。
从当晚的V$SESSION_WAIT snapshot记录进一步检查, 检查db file sequential read所对应的file id和block id,都是在操作PK_MY_TEST_TABLE_OWN_BY_ORA:
------------------------------ ------------------ --------------------------------------------------------------------------------
MYOWNER_1 INDEX PK_MY_TEST_TABLE_OWN_BY_ORA
另外,我在我的测试库中测试了用并发和不用并发,drop 500万数据的partition:
********************************************************************************
insert /*+ RELATIONAL(T) APPEND PARALLEL(T,8) */ into "TEST"."T" partition
("T6") select /*+ RELATIONAL(T) */ * from "TEST"."T" partition ("T6")
delete global indexes
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.02 0 0 0 0
Execute 2 4.29 1592.97 37244 28910 1648 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 4.29 1592.99 37244 28910 1648 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 INDEX MAINTENANCE (object id 0)
0 LOAD AS SELECT
0 TABLE ACCESS FULL T PARTITION: 6 6
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.01 0.01<<<<<<<4. 处于sequentialread的很少
dbfileparallelread 2 0.37 0.48
processstartup 9 0.00 0.01
PXDeq:JoinACK 8 0.00 0.00
PXDeq:ExecuteReply 1958 1.96 1509.03<<<<<<2. 其次是在PX上
PXDeqCredit:sendblkd 602 1.95 11.10
PXDeq:ParseReply 1 0.00 0.00
PXDeqCredit:needbuffer 1065 0.47 2.22
dbfilescatteredread 919 1.39 29.27<<<<<<<<3. 另外也有部分是在dbfilescatteredread
directpathwrite 8 0.00 0.00
directpathread 2666 0.00 0.00<<<<<<<1. 主要的等待是在directpath
PXDeq:SignalACK 1 0.00 0.00
********************************************************************************
********************************************************************************
insert /*+ RELATIONAL(T) APPEND PARALLEL(T,1) */ into "TEST"."T" partition
("T6") select /*+ RELATIONAL(T) */ * from "TEST"."T" partition ("T6")
delete global indexes
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 9.01 144.04 54992 49158 130178 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 9.01 144.04 54992 49158 130178 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 LOAD AS SELECT
1276637 TABLE ACCESS FULL OBJ#(7017) PARTITION: 6 6
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
control file sequential read 1600 0.00 0.00
db file scattered read 902 0.00 0.05<<<<<<<<<<2. 除了更新控制文件的读,第二位就是dbfilescatteredread。
dbfilesequentialread 21778 0.24 0.41<<<<<<1. 主要的等待是在dbfilesequentialread上,且没有看到PX的等待。
dbfileparallelread 3 0.00 0.00
localwritewait 469 0.42 1.43
dbfilesinglewrite 132 0.79 9.75
controlfileparallelwrite 264 1.10 4.66
logfileswitchcompletion 86 0.97 32.70
directpathwrite 4 0.00 0.00
directpathread 178 0.00 0.00<<<<<<<<2.Directpathread的等待也远远小于dbfilesequentialread。
logbufferspace 79 0.97 41.94
asyncdiskIO 101 0.00 0.00
rdbmsipcreply 10 0.02 0.06
enqueue 8 1.66 1.72
********************************************************************************
再结合我们V$SESSION_WAIT snapshot记录,我们看到,语句发起时,开始的行为吻合并发时的行为,而后面从1:58分之后,行为就变成了像拿不到并发,变成了串行的执行,于是出现大量的db file sequential read的等待。
……
因此从DBA反馈的当晚的情况看,和测试的现象看,应该是当晚执行的时候,没有拿到并发,导致语句虽然带有并发参数,但是实际执行的时候没有并发。由于串行,所以执行的时间很长。
至于为什么没有拿到并行,我们目前对于9i库没有更多的信息来证明这个问题,没有session hist的记录或者别的记录。但是根据以往的经验,当数据库中有多个程序都是并发执行时,抢光了parallel_max_servers,后续有并发的进程就不能用并发进程。且哪怕占用并发度的进程结束后,没有拿到并发度的进程还在执行,此时依旧还是会按照串行的方式继续进行下去,一直到sql执行结束。
因此,我测试了设置paralle max server为4,先用并发度为4的drop partition语句占用这4个并发度,再运行并发度为8的语句drop 另外一个表的partition,后面运行的这个sql在拿不到并发度之后,会和我们当晚的情况非常一致,会长期处于db file sequential read的等待:
********************************************************************************
insert /*+ RELATIONAL(T2) APPEND PARALLEL(T2,4) */ into "TEST"."T2" partition
("T1") select /*+ RELATIONAL(T2) */ * from "TEST"."T2" partition ("T1")
delete global indexes
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.77 169.47 9363 17660 8 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.77 169.48 9363 17660 8 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 INDEX MAINTENANCE (object id 0)
0 LOAD AS SELECT
0 TABLE ACCESS FULL T2 PARTITION: 1 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 17 0.00 0.00<<<<<<2.dbfilesequential很少
dbfileparallelread 1 0.00 0.00
PXDeq:JoinACK 4 0.00 0.00
PXDeq:ExecuteReply 1651 1.98 150.10<<<<<1. 主要是并发等待
PXDeq:ParseReply 3 0.00 0.00
PXDeqCredit:sendblkd 3734 1.95 8.44<<<<<1. 主要是并发等待
PXDeqCredit:needbuffer 1182 1.49 4.30<<<<<1. 主要是并发等待
dbfilescatteredread 597 0.00 0.02
freebufferwaits 3 0.97 1.84
directpathwrite 4 0.00 0.00
directpathread 23 0.00 0.00
PXDeq:SignalACK 2 0.00 0.00
********************************************************************************
********************************************************************************
insert /*+ RELATIONAL(T) APPEND PARALLEL(T,8) */ into "TEST"."T" partition
("T5") select /*+ RELATIONAL(T) */ * from "TEST"."T" partition ("T5")
delete global indexes
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 8 0 0
Execute 1 18.97 412.85 156193 85127 410116 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 18.97 412.85 156193 85135 410116 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 INDEX MAINTENANCE (object id 0)
1 LOAD AS SELECT
4500000 TABLE ACCESS FULL T PARTITION: 5 5
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 57681 0.00 0.38<<<<<<<1. 虽然是并发度为8,但是没有拿到并发度,大量的sequentialread
dbfileparallelread 2 0.00 0.00
controlfilesequentialread 8 0.00 0.00
dbfilescatteredread 893 0.01 0.08
freebufferwaits 124 0.98 58.25
logfileswitchcompletion 189 0.97 72.27
logbufferspace 188 0.98 99.21
directpathwrite 8 0.00 0.00
directpathread 5450 0.00 0.01
bufferbusywaits 1 0.00 0.00
undosegmentextension 19027 0.16 0.32
********************************************************************************
建议:
1. 目前该数据库的并发度为48(parallel_max_servers = 48),可适当加大。
2. 拿不到并发度,可能是在凌晨12点左右有大量job或者其他占用并发的作业启动,建议错峰执行,如提早2小时执行。
3. 执行前判定剩余并发度,如果不能获得足够的并发度,就暂缓执行。
由 udpwork.com 聚合
|
评论: 0
|
要! 要! 即刻! Now!