分类： Oracle
2008-04-24 20:55:36
版本10gR2;使用alter system set events ‘10046 trace name context forever,level 8’可得到所有QC和Slaves进程的分析文件。
执行
Create index tidx on t(object_id…..) parallel 2;
SQL> select dfo_number,tq_id,server_type,num_rows,bytes,process from v$pq_tqstat order by tq_id,server_type;
DFO_NUMBER TQ_ID SERVER_TYP NUM_ROWS BYTES PROCESS
---------- ---------- ---------- ---------- ---------- ----------
1 0 Consumer 764597 29115663 P000
1 0 Consumer 704203 28047985 P001
1 0 Producer 737012 28685709 P002
1 0 Producer 735066 28606187 P003
1 0 Ranger 2 128248 QC
1 1 Consumer 2 644 QC
1 1 Producer 1 322 P001
1 1 Producer 1 322 P000
首先QC扮演Ranger角色，分配具体的SQL和数据给进程P002，P003由这2个进程扮演Producer角色，读取表数据传递给扮演Consumer角色的进程P000，P001；并有进程P000，P001对数据排序，并且组织索引结构，将索引段数据写此盘。然后进程P000，P001再扮演Producer角色，通知扮演Consumer角色的QC，“索引数据已经写完毕”。
下面一一察看各个进程在创建索引过程中产生的等待事件，由此可以知道在各个步骤中，每个进程都作了什么。
下面为QC进程的跟踪文件
WAIT #0: nam='SQL*Net message from client' ela= 3000128 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=4939100853084 等待客户端命令
WAIT #1: nam='reliable message' ela= 686 channel context=16277437840 channel handle=16213913536 broadcast message=16278114152 obj#=-1 tim=4939100920830
WAIT #1: nam='enq: KO - fast object checkpoint' ela= 27675 name|mode=1263468550 2=65550 0=1 obj#=-1 tim=4939100948815等待完成Object Checkpoint
WAIT #1: nam='PX Deq: Join ACK' ela= 3273 sleeptime/senderid=268500992 passes=1 p3=0 obj#=-1 tim=4939100953792 联系可用的Slave 进程
WAIT #1: nam='PX Deq: Join ACK' ela= 7 sleeptime/senderid=268500994 passes=1 p3=0 obj#=-1 tim=4939100954806
WAIT #1: nam='PX Deq: Join ACK' ela= 9679 sleeptime/senderid=268500994 passes=2 p3=0 obj#=-1 tim=4939100964619
WAIT #1: nam='PX Deq: Join ACK' ela= 129 sleeptime/senderid=268500995 passes=1 p3=0 obj#=-1 tim=4939100964891
WAIT #1: nam='PX Deq: Parse Reply' ela= 4224 sleeptime/senderid=200 passes=1 p3=0 obj#=-1 tim=4939100970343 分析SQL并将计划告知给Slave进程
WAIT #1: nam='PX Deq: Parse Reply' ela= 7 sleeptime/senderid=200 passes=1 p3=0 obj#=-1 tim=4939100970656
WAIT #1: nam='PX Deq: Execute Reply' ela= 828 sleeptime/senderid=200 passes=2 等待Slave进程返回结果
WAIT #1: nam='PX Deq: Execute Reply' ela= 122969 sleeptime/senderid=200 passes=3 p3=0 obj#=-1 tim=4939112096501
WAIT #1: nam='PX Deq: Execute Reply' ela= 1962562 sleeptime/senderid=200 passes=9 p3=0 obj#=-1 tim=4939135645092
WAIT #1: nam='PX Deq: Execute Reply' ela= 1962415 sleeptime/senderid=200 passes=10 p3=0 obj#=-1 tim=4939137607768
WAIT #1: nam='PX Deq: Table Q qref' ela= 581 sleeptime/senderid=268500992 passes=1 p3=0 obj#=-1 tim=4939137666543
WAIT #1: nam='db file sequential read' ela= 287 file#=4 block#=38882 blocks=1 obj#=19494 tim=4939137668994 读取刚建立好的索引
WAIT #1: nam='db file scattered read' ela= 796 file#=4 block#=38395 blocks=14 obj#=19494 tim=4939137670433
WAIT #1: nam='db file scattered read' ela= 908 file#=4 block#=45081 blocks=15 obj#=19494 tim=4939137672128
WAIT #1: nam='control file sequential read' ela= 153 file#=0 block#=1 blocks=1 obj#=19494 tim=4939137685305 有四次读取控制文件
WAIT #1: nam='control file sequential read' ela= 672 file#=1 block#=1 blocks=1 obj#=19494 tim=4939137686152
WAIT #1: nam='control file sequential read' ela= 143 file#=0 block#=8 blocks=1 obj#=19494 tim=4939137686502
WAIT #1: nam='control file sequential read' ela= 149 file#=0 block#=10 blocks=1 obj#=19494 tim=4939137686812
WAIT #1: nam='rdbms ipc reply' ela= 37558 from_process=7 timeout=21474836 p3=0 obj#=19494 tim=4939137740580 等待CKPT进程完成某个工作
WAIT #1: nam='PX Deq: Execute Reply' ela= 12290 sleeptime/senderid=200 passes=1 p3=0 obj#=19494 tim=4939137799169
WAIT #1: nam='log file sync' ela= 5250 buffer#=4377 p2=0 p3=0 obj#=19494 tim=4939137804721
WAIT #1: nam='PX Deq: Execute Reply' ela= 456 sleeptime/senderid=200 passes=1 p3=0 obj#=19494 tim=4939137805402
WAIT #1: nam='PX Deq: Signal ACK' ela= 6472 sleeptime/senderid=200 passes=1 p3=0 obj#=19494 tim=4939137813128 通知Slave进程工作完毕
WAIT #1: nam='PX Deq: Signal ACK' ela= 7 sleeptime/senderid=200 passes=1 p3=0 obj#=19494 tim=4939137813739
WAIT #1: nam='PX Deq: Signal ACK' ela= 2687 sleeptime/senderid=200 passes=2 p3=0 obj#=19494 tim=4939137816548
WAIT #1: nam='enq: PS - contention' ela= 5 name|mode=1347616774 instance=1 slave ID=3 obj#=19494 tim=4939137817015 PS表示 Parallel Slave Synchronization
WAIT #1: nam='enq: PS - contention' ela= 772 name|mode=1347616774 instance=1 slave ID=3 obj#=19494 tim=4939137817902
WAIT #1: nam='SQL*Net message to client' ela= 11 driver id=1650815232 #bytes=1 p3=0 obj#=19494 tim=4939137819217 索引建立完毕
---------------------------------------------------------------------
下面是进程P002和P003进程的跟踪文件，两个进程负责读取表数据。
WAIT #0: nam='PX Deq: Execution Msg' ela= 1934 sleeptime/senderid=268566527 passes=1 p3=0 obj#=-1 tim=4938978694075 等待QC分配工作的消息
PARSING IN CURSOR #1 len=69 dep=1 uid=34 oct=9 lid=34 tim=4938978732817 hv=2198914594 ad='944f5348'
create index tidx on t(object_id,object_type,owner,status) parallel 2
END OF STMT
PARSE #1:c=0,e=1405,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=4938978732749
WAIT #1: nam='PX Deq: Execution Msg' ela= 9 sleeptime/senderid=268566527 passes=1 p3=0 obj#=-1 tim=4938978735678
WAIT #1: nam='PX Deq Credit: need buffer' ela= 6 sleeptime/senderid=268566527 passes=1 qref=0 obj#=-1 tim=4938978745977
WAIT #1: nam='buffer busy waits' ela= 97 file#=4 block#=28898 class#=1 obj#=19415 tim=4938978747615 不知道为什么要读取基表
WAIT #1: nam='PX Deq Credit: send blkd' ela= 492 sleeptime/senderid=268566527 passes=1 qref=0 obj#=19415 tim=4938978758987
WAIT #1: nam='PX Deq Credit: send blkd' ela= 1349 sleeptime/senderid=268566527 passes=1 qref=0 obj#=19415 tim=4938978779703
WAIT #1: nam='PX Deq: Table Q Get Keys' ela= 2734 sleeptime/senderid=200 passes=1 p3=0 obj#=19415 tim=4938978789796
WAIT #1: nam='direct path read' ela= 68616 file number=4 first dba=1801 block cnt=119 obj#=19415 tim=4938978885268 使用direct path读取表数据
WAIT #1: nam='PX Deq Credit: need buffer' ela= 6 sleeptime/senderid=268500992 passes=1 qref=0 obj#=19415 tim=4938978886476
WAIT #1: nam='PX Deq Credit: need buffer' ela= 302 sleeptime/senderid=268500992 passes=2 qref=0 obj#=19415 tim=4938978893074
WAIT #1: nam='PX qref latch' ela= 5 function=1 sleeptime=16269027808 qref=0 obj#=19415 tim=4938978908789
WAIT #1: nam='PX Deq Credit: need buffer' ela= 4 sleeptime/senderid=268500993 passes=1 qref=0 obj#=19415 tim=4938978909247
WAIT #1: nam='PX Deq Credit: send blkd' ela= 74 sleeptime/senderid=268500993 passes=1 qref=0 obj#=19415 tim=4938978921998
WAIT #1: nam='PX Deq: Execution Msg' ela= 13 sleeptime/senderid=268566527 passes=1 p3=0 obj#=19415 tim=4939119043759
XCTEND rlbk=0, rd_only=1 一个Slave的事务结束
WAIT #0: nam='PX Deq: Execution Msg' ela= 6 sleeptime/senderid=268566527 passes=1 p3=0 obj#=19415 tim=4939119044755
WAIT #0: nam='PX Deq: Execution Msg' ela= 1106563 sleeptime/senderid=268566527 passes=11 p3=0 obj#=19415 tim=4939137806646 表示分配的工作完成，等待QC的下次通知；
然后下面是执行计划。
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='PX COORDINATOR (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=0 op='PX SEND QC (ORDER) :TQ10001 (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=3 cnt=0 pid=2 pos=1 obj=0 op='INDEX BUILD NON UNIQUE TIDX (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=4 cnt=0 pid=3 pos=1 obj=0 op='SORT CREATE INDEX (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=5 cnt=0 pid=4 pos=1 obj=0 op='PX RECEIVE (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=6 cnt=0 pid=5 pos=1 obj=0 op='PX SEND RANGE :TQ10000 (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=7 cnt=737012 pid=6 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=9833 pr=9347 pw=0 time=11857142 us)'
STAT #1 id=8 cnt=737012 pid=7 pos=1 obj=19415 op='TABLE ACCESS FULL T (cr=9833 pr=9347 pw=0 time=10559888 us)'
----------------------------------------------------------------
然后是进程P000和P001的跟踪文件，这2个进程负责接收数据，并且排序，且将排序结果以索引形式写回磁盘。
WAIT #1: nam='PX Deq: Execution Msg' ela= 10 sleeptime/senderid=268566527 passes=1 p3=0 obj#=-1 tim=4938978733764 等待工作
WAIT #1: nam='PX Deq: Table Q Normal' ela= 5 sleeptime/senderid=10 passes=1 p3=0 obj#=-1 tim=4938978740144 接收Producer发过来的数据
WAIT #1: nam='PX Deq: Table Q Normal' ela= 5 sleeptime/senderid=200 passes=1 p3=0 obj#=-1 tim=4938979574135
WAIT #1: nam='PX qref latch' ela= 5 function=1 sleeptime=16269030976 qref=0 obj#=-1 tim=4938979575655
WAIT #1: nam='direct path write temp' ela= 6 file number=201 first dba=3302 block cnt=31 obj#=-1 tim=4938995300650 进行磁盘排序 文件；201为临时文件
WAIT #1: nam='direct path write temp' ela= 2 file number=201 first dba=3333 block cnt=4 obj#=-1 tim=4938995323781
WAIT #1: nam='local write wait' ela= 8 file#=201 block#=2 p3=0 obj#=-1 tim=4938995447962
WAIT #1: nam='local write wait' ela= 5572 file#=201 block#=2 p3=0 obj#=-1 tim=4938995599975
WAIT #1: nam='direct path write temp' ela= 2 file number=201 first dba=358 block cnt=31 obj#=-1 tim=4938995643198
WAIT #1: nam='direct path read temp' ela= 5 file number=201 first dba=5912 block cnt=7 obj#=-1 tim=4939000648104
WAIT #1: nam='direct path write' ela= 3 file number=4 first dba=38695 block cnt=2 obj#=-1 tim=4939000721038 使用direct path方式将数据以索引结构写磁盘
WAIT #1: nam='direct path write' ela= 4 file number=4 first dba=38716 block cnt=7 obj#=-1 tim=4939000734343
WAIT #1: nam='direct path read temp' ela= 5 file number=201 first dba=5912 block cnt=7 obj#=-1 tim=4939000648104 从临时文件中读取已排序地记录
WAIT #1: nam='direct path write' ela= 3 file number=4 first dba=38695 block cnt=2 obj#=-1 tim=4939000721038 使用direct path方式将数据以索引结构写磁盘
WAIT #1: nam='direct path write' ela= 4 file number=4 first dba=38716 block cnt=7 obj#=-1 tim=4939000734343
WAIT #1: nam='direct path write' ela= 87 file number=4 first dba=45086 block cnt=4 obj#=-1 tim=4939137645363
WAIT #1: nam='rdbms ipc reply' ela= 257 from_process=7 timeout=21474836 p3=0 obj#=-1 tim=4939137646110 等待CKPT进程
WAIT #1: nam='control file sequential read' ela= 288 file#=0 block#=1 blocks=1 obj#=-1 tim=4939137648537
WAIT #1: nam='control file sequential read' ela= 111 file#=1 block#=1 blocks=1 obj#=-1 tim=4939137648800
WAIT #1: nam='control file sequential read' ela= 119 file#=0 block#=8 blocks=1 obj#=-1 tim=4939137649094
WAIT #1: nam='control file sequential read' ela= 121 file#=0 block#=10 blocks=1 obj#=-1 tim=4939137649352
WAIT #1: nam='direct path write' ela= 1 file number=4 first dba=45090 block cnt=3 obj#=-1 tim=4939137650558
WAIT #1: nam='direct path write' ela= 1 file number=4 first dba=45090 block cnt=3 obj#=-1 tim=4939137656987
WAIT #1: nam='db file sequential read' ela= 84 file#=4 block#=45096 blocks=1 obj#=-1 tim=4939137665103 将一个block读取到Buffer Cache
WAIT #1: nam='PX Deq: Execution Msg' ela= 206 sleeptime/senderid=268566527 passes=1 p3=0 obj#=-1 tim=4939137665831
WAIT #0: nam='PX Deq: Execution Msg' ela= 67085 sleeptime/senderid=268566527 passes=1 p3=0 obj#=-1 tim=4939137786827
WAIT #0: nam='log file sync' ela= 11662 buffer#=4367 p2=0 p3=0 obj#=-1 tim=4939137798968
下面是执行计划
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='PX COORDINATOR (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=0 op='PX SEND QC (ORDER) :TQ10001 (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=3 cnt=1 pid=2 pos=1 obj=0 op='INDEX BUILD NON UNIQUE TIDX (cr=2202 pr=4063 pw=7564 time=36691169 us)'
STAT #1 id=4 cnt=764597 pid=3 pos=1 obj=0 op='SORT CREATE INDEX (cr=7 pr=4062 pw=4062 time=22691462 us)'
STAT #1 id=5 cnt=764597 pid=4 pos=1 obj=0 op='PX RECEIVE (cr=0 pr=0 pw=0 time=5425415 us)'
STAT #1 id=6 cnt=0 pid=5 pos=1 obj=0 op='PX SEND RANGE :TQ10000 (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=7 cnt=0 pid=6 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=8 cnt=0 pid=7 pos=1 obj=19415 op='TABLE ACCESS FULL T (cr=0 pr=0 pw=0 time=0 us)'
需要说明的是，进程P000和P001都可以接受进程P002，P003的数据；P000和P001对各自的数据进行排序后，直接将数据按照索引的结构写回磁盘。
