帮助解释: parallel query时cost减少，但逻辑读增加

Yong Huang

> Yong Huang有没有考虑过这其中可能有比较大一部分是因为recursive call产生的？

You mean the extra consistent gets by the parallel query compared to the serial query? Of course. Parallel slaves are considered recursive calls. If you enable SQL trace, their trace files will be in bdump instead of udump. But the question still remains. Why does the sum of all PX slaves' CR gets exceed the serial scan's CR gets? For example, I just did a test in a 10.2.0.1 database on my laptop (not the one I used the other day). In my p000 trace file (note dep=1):

PARSE #1:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=283736309754
...
STAT #1 id=5 cnt=54969 pid=4 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=519 pr=379 pw=0 time=631169 us)'
STAT #1 id=6 cnt=54969 pid=5 pos=1 obj=56282 op='TABLE ACCESS FULL T (cr=519 pr=379 pw=0 time=389675 us)'

and in p001:

STAT #1 id=5 cnt=45031 pid=4 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=510 pr=360 pw=0 time=523131 us)'
STAT #1 id=6 cnt=45031 pid=5 pos=1 obj=56282 op='TABLE ACCESS FULL T (cr=510 pr=360 pw=0 time=342196 us)'

So the total (I only have two slaves) is 519+510=1029. But in my serial query's trace file:

STAT #14 id=2 cnt=100000 pid=1 pos=1 obj=56282 op='TABLE ACCESS FULL T (cr=751 pr=0 pw=0 time=400060 us)'

It's 1029-751=278 less. The table T has 18 extents. My last theory that the extra gets could be 3 times number of extents is wrong, not only numerically, but also because reading extent headers (if done) would be more likely current mode gets, not CR gets.

Let's wait till kl911's SR has an answer. But any new research is very welcome.

Yong Huang

huanhuanlove

深夜解答。。。钦佩。。。。  又学到不少

anlinew

t3 12个block的数据， two extents

SQL> select file_id,block_id,blocks from dba_extents where segment_name='T3' order by block_id;

   FILE_ID   BLOCK_ID     BLOCKS
---------- ---------- ----------
         6     233041          8
         6     233049          8

QC：
select /*+ parallel (t3 2)*/ count(*) from t3
END OF STMT
PARSE #3:c=156250,e=1073926,p=31,cr=536,cu=5,mis=1,r=0,dep=0,og=1,tim=711357469728
BINDS #3:
WAIT #3: nam='db file sequential read' ela= 9256 file#=6 block#=233043 blocks=1 obj#=18628 tim=711357482247
WAIT #3: nam='os thread startup' ela= 9853 p1=0 p2=0 p3=0 obj#=18628 tim=711357492512
WAIT #3: nam='os thread startup' ela= 10887 p1=0 p2=0 p3=0 obj#=18628 tim=711357503552

P001：

select /*+ parallel (t3 2)*/ count(*) from t3
END OF STMT
PARSE #1:c=0,e=90,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=711357584931
BINDS #1:
WAIT #1: nam='PX Deq: Execution Msg' ela= 1178 sleeptime/senderid=268566527 passes=1 p3=0 obj#=-1 tim=711357622732
WAIT #1: nam='db file scattered read' ela= 545 file#=6 block#=233045 blocks=4 obj#=18628 tim=711357635570
WAIT #1: nam='PX Deq: Execution Msg' ela= 3332 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357649251
WAIT #1: nam='PX Deq: Execution Msg' ela= 528 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357657533
WAIT #1: nam='db file sequential read' ela= 249 file#=6 block#=233049 blocks=1 obj#=18628 tim=711357661585
WAIT #1: nam='PX Deq: Execution Msg' ela= 22 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357668032
WAIT #1: nam='PX Deq: Execution Msg' ela= 366 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357683140
WAIT #1: nam='PX qref latch' ela= 7 function=1 sleeptime=1538078108 qref=0 obj#=18628 tim=711357686992
WAIT #1: nam='PX qref latch' ela= 9 function=2 sleeptime=1538078108 qref=0 obj#=18628 tim=711357691354
WAIT #1: nam='PX Deq: Execution Msg' ela= 355 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357710975
WAIT #1: nam='PX qref latch' ela= 7 function=1 sleeptime=1538078108 qref=0 obj#=18628 tim=711357715000
WAIT #1: nam='PX qref latch' ela= 7 function=2 sleeptime=1538078108 qref=0 obj#=18628 tim=711357718729
WAIT #1: nam='PX Deq: Execution Msg' ela= 11273 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357755927
WAIT #1: nam='PX qref latch' ela= 7 function=1 sleeptime=1538078108 qref=0 obj#=18628 tim=711357759947
EXEC #1:c=0,e=157675,p=5,cr=25,cu=0,mis=0,r=0,dep=1,og=1,tim=711357768599

P000：
select /*+ parallel (t3 2)*/ count(*) from t3
END OF STMT
PARSE #1:c=0,e=98,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=711357554810
BINDS #1:
WAIT #1: nam='PX Deq: Execution Msg' ela= 8178 sleeptime/senderid=268566527 passes=1 p3=0 obj#=-1 tim=711357613853
WAIT #1: nam='db file sequential read' ela= 5443 file#=6 block#=233044 blocks=1 obj#=18628 tim=711357626956
WAIT #1: nam='PX Deq: Execution Msg' ela= 418 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357631761
WAIT #1: nam='read by other session' ela= 10477 file#=6 block#=233046 class#=14 obj#=18628 tim=711357645320
WAIT #1: nam='PX Deq: Execution Msg' ela= 3035 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357652248
WAIT #1: nam='PX Deq: Execution Msg' ela= 4011 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357661417
WAIT #1: nam='db file scattered read' ela= 710 file#=6 block#=233050 blocks=7 obj#=18628 tim=711357668575
WAIT #1: nam='PX Deq: Execution Msg' ela= 3049 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357675011
WAIT #1: nam='PX Deq: Execution Msg' ela= 8708 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357691557
WAIT #1: nam='PX qref latch' ela= 7 function=1 sleeptime=1538078472 qref=0 obj#=18628 tim=711357698442
WAIT #1: nam='PX qref latch' ela= 11 function=2 sleeptime=1538078472 qref=0 obj#=18628 tim=711357704469
WAIT #1: nam='PX Deq: Execution Msg' ela= 12561 sleeptime/senderid=268566527 passes=1 p3=0 obj#=18628 tim=711357723336
WAIT #1: nam='PX qref latch' ela= 7 function=1 sleeptime=1538078472 qref=0 obj#=18628 tim=711357727087
WAIT #1: nam='PX qref latch' ela= 6 function=2 sleeptime=1538078472 qref=0 obj#=18628 tim=711357730756
WAIT #1: nam='PX qref latch' ela= 7 function=3 sleeptime=1538078472 qref=0 obj#=18628 tim=711357734475
WAIT #1: nam='PX qref latch' ela= 8 function=4 sleeptime=1538078472 qref=0 obj#=18628 tim=711357738492
WAIT #1: nam='PX qref latch' ela= 2583 function=5 sleeptime=1538078472 qref=0 obj#=18628 tim=711357744927
EXEC #1:c=15625,e=146254,p=8,cr=25,cu=0,mis=0,r=0,dep=1,og=1,tim=711357749203

1+25+25=51

统计信息
----------------------------------------------------------
          6  recursive calls
          0  db block gets
         51  consistent gets

无并行：
select count(*) from nc_jlf.t3
END OF STMT
PARSE #17:c=109375,e=1040924,p=32,cr=531,cu=0,mis=1,r=0,dep=0,og=1,tim=712069891128
BINDS #17:
EXEC #17:c=0,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=712069891243
WAIT #17: nam='SQL*Net message to client' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=0 tim=712069891282
WAIT #17: nam='db file sequential read' ela= 15208 file#=6 block#=233043 blocks=1 obj#=18628 tim=712069906563
WAIT #17: nam='db file scattered read' ela= 845 file#=6 block#=233044 blocks=5 obj#=18628 tim=712069907572
WAIT #17: nam='db file scattered read' ela= 1315 file#=6 block#=233049 blocks=7 obj#=18628 tim=712069908978
FETCH #17:c=0,e=17766,p=13,cr=16,cu=0,mis=0,r=1,dep=0,og=1,tim=712069909081


[ 本帖最后由 anlinew 于 2009-9-14 14:08 编辑 ]

kl911

呵呵，刚刚update的 ? 刚才看到的都是file=1, 正准备提出问题。。。

kl911

从这里看对parallel query cr=25, 对non_parallel query cr=16. 这也就是问题所在。我已经开了SR，但可能因为周末，那边还没有回复。

anlinew

原帖由 kl911 于 2009-9-14 14:01 发表
呵呵，刚刚update的 ? 刚才看到的都是file=1, 正准备提出问题。。。

换成另一个表，看起来清楚点儿

anlinew

原帖由 kl911 于 2009-9-14 14:04 发表
从这里看对parallel query cr=25, 对non_parallel query cr=16. 这也就是问题所在。我已经开了SR，但可能因为周末，那边还没有回复。

parallel 下光一个子查询就25了。。。。

anlinew

空表的情况：
非并行3  consistent gets，这很好理解
并行下：5  consistent gets（其实没有真正的并行）

WAIT #7: nam='db file sequential read' ela= 9975 file#=1 block#=33969 blocks=1 obj#=18626 tim=716547292575
EXEC #7:c=0,e=10241,p=1,cr=2,cu=0,mis=0,r=0,dep=0,og=1,tim=716547292746
WAIT #7: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=18626 tim=716547292797
FETCH #7:c=0,e=122,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=716547292953
WAIT #7: nam='SQL*Net message from client' ela= 238 driver id=1111838976 #bytes=1 p3=0 obj#=18626 tim=716547293273
FETCH #7:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=716547293309
WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1111838976 #bytes=1 p3=0 obj#=18626 tim=716547293336
*** 2009-09-14 15:04:22.500
WAIT #7: nam='SQL*Net message from client' ela= 227911669 driver id=1111838976 #bytes=1 p3=0 obj#=18626 tim=716775205034
STAT #7 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=5 pr=1 pw=0 time=10301 us)'
STAT #7 id=2 cnt=1 pid=1 pos=1 obj=0 op='PX COORDINATOR  (cr=5 pr=1 pw=0 time=10267 us)'
STAT #7 id=3 cnt=1 pid=2 pos=1 obj=0 op='PX SEND QC (RANDOM) :TQ10000 (cr=3 pr=0 pw=0 time=119 us)'
STAT #7 id=4 cnt=1 pid=3 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=0 pw=0 time=99 us)'
STAT #7 id=5 cnt=0 pid=4 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=3 pr=0 pw=0 time=63 us)'
STAT #7 id=6 cnt=0 pid=5 pos=1 obj=18626 op='TABLE ACCESS FULL T2 (cr=3 pr=0 pw=0 time=36 us)'


[ 本帖最后由 anlinew 于 2009-9-14 15:11 编辑 ]

kl911

---- Serail
PARSING IN CURSOR #11 len=26 dep=0 uid=64 oct=3 lid=64 tim=1223548106178446 hv=4031377848 ad='266032fc'
select count(*) from t1313
END OF STMT
PARSE #11:c=6999,e=55622,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1223548106178423
BINDS #11:
EXEC #11:c=0,e=599,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1223548106179152
WAIT #11: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548106179397
FETCH #11:c=0,e=671,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=1223548106180142
WAIT #11: nam='SQL*Net message from client' ela= 1006 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548106181452
FETCH #11:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1223548106181511
WAIT #11: nam='SQL*Net message to client' ela= 125 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548106182259
WAIT #11: nam='SQL*Net message from client' ela= 2922 driver id=141369753  

WAIT #15: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548106186474
EXEC #15:c=1000,e=499,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1223548106186515
WAIT #15: nam='SQL*Net message from client' ela= 770 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548106187942
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548106188225
WAIT #0: nam='SQL*Net message from client' ela= 647 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548106188906
STAT #11 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=0 pw=0 time=1183 us)'
STAT #11 id=2 cnt=0 pid=1 pos=1 obj=53801 op='TABLE ACCESS FULL T1313 (cr=3 pr=0 pw=0 time=636 us)'
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548106189292
*** 2009-09-14 15:27:53.751

---- Parallel
PARSING IN CURSOR #11 len=26 dep=0 uid=64 oct=3 lid=64 tim=1223548319881245 hv=4031377848 ad='266032fc'
select count(*) from t1313
END OF STMT
PARSE #11:c=35995,e=126865,p=0,cr=11,cu=3,mis=1,r=0,dep=0,og=1,tim=1223548319881235
BINDS #11:
EXEC #11:c=1000,e=971,p=0,cr=2,cu=0,mis=0,r=0,dep=0,og=1,tim=1223548319882320
WAIT #11: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548319883046
FETCH #11:c=0,e=243,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=1223548319883334
WAIT #11: nam='SQL*Net message from client' ela= 927 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548319885068
FETCH #11:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1223548319885133
WAIT #11: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548319885195
WAIT #11: nam='SQL*Net message from client' ela= 5695 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548319890926

WAIT #12: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548319892999
EXEC #12:c=1000,e=1223,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1223548319893049
WAIT #12: nam='SQL*Net message from client' ela= 258 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548319894048
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548319894820
WAIT #0: nam='SQL*Net message from client' ela= 134 driver id=1413697536 #bytes=1 p3=0 obj#=46213 tim=1223548319894986
STAT #11 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=5 pr=0 pw=0 time=542 us)'
STAT #11 id=2 cnt=1 pid=1 pos=1 obj=0 op='PX COORDINATOR  (cr=5 pr=0 pw=0 time=441 us)'
STAT #11 id=3 cnt=1 pid=2 pos=1 obj=0 op='PX SEND QC (RANDOM) :TQ10000 (cr=3 pr=0 pw=0 time=241 us)'
STAT #11 id=4 cnt=1 pid=3 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=0 pw=0 time=203 us)'
STAT #11 id=5 cnt=0 pid=4 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=3 pr=0 pw=0 time=160 us)'
STAT #11 id=6 cnt=0 pid=5 pos=1 obj=53801 op='TABLE ACCESS FULL T1313 (cr=3 pr=0 pw=0 time=118 us)'

从上面的trace来看，“STAT #11 id=2 cnt=1 pid=1 pos=1 obj=0 op='PX COORDINATOR  (cr=5 pr=0 pw=0 time=441 us)'“ PX COORDINATOR 的cr是5-3=2， 可以这么理解吗，PX COORDINATOR 这个值由什么来决定？

[ 本帖最后由 kl911 于 2009-9-14 16:37 编辑 ]

Yong Huang

原帖由 kl911 于 2009-9-14 02:33 发表
...
STAT #11 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=5 pr=0 pw=0 time=542 us)'
STAT #11 id=2 cnt=1 pid=1 pos=1 obj=0 op='PX COORDINATOR  (cr=5 pr=0 pw=0 time=441 us)'
STAT #11 id=3 cnt=1 pid=2 pos=1 obj=0 op='PX SEND QC (RANDOM) :TQ10000 (cr=3 pr=0 pw=0 time=241 us)'
STAT #11 id=4 cnt=1 pid=3 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=0 pw=0 time=203 us)'
STAT #11 id=5 cnt=0 pid=4 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=3 pr=0 pw=0 time=160 us)'
STAT #11 id=6 cnt=0 pid=5 pos=1 obj=53801 op='TABLE ACCESS FULL T1313 (cr=3 pr=0 pw=0 time=118 us)'

从上面的trace来看，“STAT #11 id=2 cnt=1 pid=1 pos=1 obj=0 op='PX COORDINATOR  (cr=5 pr=0 pw=0 time=441 us)'“ PX COORDINATOR 的cr是5-3=2， 可以这么理解吗，PX COORDINATOR 这个值由什么来决定？

Oracle version is always helpful!!

This may be version dependent. In my 10.2.0.1 test, PX COORDINATOR is showing 0 cr gets:

EXEC #1:c=15625,e=197656,p=379,cr=519,cu=0,mis=0,r=0,dep=1,og=1,tim=283736927519
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=0 op='PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=3 cnt=0 pid=2 pos=1 obj=0 op='PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=4 cnt=1 pid=3 pos=1 obj=0 op='SORT AGGREGATE (cr=519 pr=379 pw=0 time=197479 us)'
STAT #1 id=5 cnt=54969 pid=4 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=519 pr=379 pw=0 time=611928 us)'
STAT #1 id=6 cnt=54969 pid=5 pos=1 obj=56282 op='TABLE ACCESS FULL T (cr=519 pr=379 pw=0 time=370583 us)'

But the EXEC line has the same cr value as the slave's cr.

Yong Huang