12.1.0.2
SQL> show parameter parallel
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
fast_start_parallel_rollback string LOW
parallel_adaptive_multi_user boolean TRUE
parallel_automatic_tuning boolean FALSE
parallel_degree_level integer 100
parallel_degree_limit string CPU
parallel_degree_policy string MANUAL
parallel_execution_message_size integer 16384
parallel_force_local boolean FALSE
parallel_instance_group string
parallel_io_cap_enabled boolean FALSE
parallel_max_servers integer 640
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
parallel_min_percent integer 0
parallel_min_servers integer 64
parallel_min_time_threshold string AUTO
parallel_server boolean TRUE
parallel_server_instances integer 2
parallel_servers_target integer 256
parallel_threads_per_cpu integer 2
recovery_parallelism integer 0
SQL>
Trying to speed up an insert from an external table. Was using parallel settings and noticed something Im hoping someone can explain.
External file has 700k rows. About 300mb in size.
No logging on table
Either alter session enable parallel dml or use the new parallel hint to do same
truncate table load_test ;
-- make sure no table parallel is on
alter table XT_700KROWS noparallel;
alter session set tracefile_identifier = "PX_NOLOG_PX_HINT_TABLE4";
alter session set events '10046 trace name context forever, level 12';
set tim on timi on
set autotrace traceonly
insert /*+ enable_parallel_dml */ into load_test a
( col1, col2, col3, col4, col5, col6, col7, col8, col9 )
select col1, col2, col3, col4, col5, col6, col7, col8, col9 from V$SLATTERY.XT_700krows b;
Elapsed: 00:00:13.14
Execution Plan
----------------------------------------------------------
ERROR:
ORA-12838: cannot read/modify an object after modifying it in parallel
SP2-0612: Error generating AUTOTRACE EXPLAIN report
Statistics
----------------------------------------------------------
191 recursive calls
126 db block gets
931 consistent gets
0 physical reads
18308 redo size
744 bytes sent via SQL*Net to client
1370 bytes received via SQL*Net from client
4 SQL*Net roundtrips to/from client
7 sorts (memory)
0 sorts (disk)
700001 rows processed
alter session set events '10046 trace name context off';
tkprof the trace
********************************************************************************
insert /*+ enable_parallel_dml */ into load_test a
( col1, col2, col3, col4, col5, col6, col7, col8, col9 )
select col1, col2, col3, col4, col5, col6, col7, col8, col9 from XT_700krows b
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 630 0 0
Execute 1 0.17 13.08 0 38 35 700001
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.18 13.10 0 668 35 700001
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 867
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
64 64 64 PX COORDINATOR (cr=135 pr=0 pw=0 time=12402795 us)
0 0 0 PX SEND QC (RANDOM) :TQ10001 (cr=0 pr=0 pw=0 time=0 us cost=102 size=1984824 card=8168)
0 0 0 LOAD AS SELECT (HYBRID TSM/HWMB) (cr=0 pr=0 pw=0 time=0 us)
0 0 0 OPTIMIZER STATISTICS GATHERING (cr=0 pr=0 pw=0 time=0 us cost=102 size=1984824 card=8168)
0 0 0 PX RECEIVE (cr=0 pr=0 pw=0 time=0 us cost=102 size=1984824 card=8168)
0 0 0 PX SEND ROUND-ROBIN :TQ10000 (cr=0 pr=0 pw=0 time=0 us cost=102 size=1984824 card=8168)
0 0 0 PX SELECTOR (cr=0 pr=0 pw=0 time=0 us)
0 0 0 EXTERNAL TABLE ACCESS FULL XT_700KROWS (cr=0 pr=0 pw=0 time=0 us cost=102 size=1984824 card=8168)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PX Deq: Join ACK 121 0.00 0.00
log file sync 1 0.00 0.00
PX Deq: Parse Reply 64 0.00 0.00
name-service call wait 1 0.06 0.06
PX Deq: Execute Reply 988 11.92 12.74
PX Deq: Signal ACK RSG 64 0.03 0.05
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
So " PX Deq: Execute Reply 988 11.92 12.74" is what I'm concerned about. 11.92 seconds is one wait and that pretty much accounts for the 13 seconds. Same behaviour every time whether I use the session hint or the "alter session enable parallel dml"
However, if we use table parallel hint, we dont see these wait, same behaviour if I dont add hint but "alter table x parallel 7"
truncate table load_test ;
-- make sure no table parallel is on table
alter table XT_700KROWS noparallel;
alter session set tracefile_identifier = "PX_NOLOG_PX_7";
alter session set events '10046 trace name context forever, level 12';
set tim on timi on
set autotrace traceonly
insert /*+ parallel (7) enable_parallel_dml */ into load_test a
( col1, col2, col3, col4, col5, col6, col7, col8, col9 )
select col1, col2, col3, col4, col5, col6, col7, col8, col9 from XT_700krows b;
700001 rows created.
Elapsed: 00:00:03.58
Execution Plan
----------------------------------------------------------
ERROR:
ORA-12838: cannot read/modify an object after modifying it in parallel
SP2-0612: Error generating AUTOTRACE EXPLAIN report
Statistics
----------------------------------------------------------
452 recursive calls
102 db block gets
1875 consistent gets
0 physical reads
18196 redo size
744 bytes sent via SQL*Net to client
1372 bytes received via SQL*Net from client
4 SQL*Net roundtrips to/from client
4 sorts (memory)
0 sorts (disk)
700001 rows processed
alter session set events '10046 trace name context off';
and check 10046 output and we dont see the long PX execute waits max waited is .97 second.
********************************************************************************
insert /*+ parallel (7) enable_parallel_dml */ into load_test a
( col1, col2, col3, col4, col5, col6, col7, col8, col9 )
select col1, col2, col3, col4, col5, col6, col7, col8, col9 from XT_700krows b
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 990 0 0
Execute 1 0.08 3.52 0 38 10 700001
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.09 3.53 0 1028 10 700001
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 867
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
14 14 14 PX COORDINATOR (cr=705 pr=0 pw=0 time=3087434 us)
0 0 0 PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us cost=16 size=1984824 card=8168)
0 0 0 LOAD AS SELECT (HYBRID TSM/HWMB) (cr=0 pr=0 pw=0 time=0 us)
0 0 0 OPTIMIZER STATISTICS GATHERING (cr=0 pr=0 pw=0 time=0 us cost=16 size=1984824 card=8168)
0 0 0 PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us cost=16 size=1984824 card=8168)
0 0 0 EXTERNAL TABLE ACCESS FULL XT_700KROWS (cr=0 pr=0 pw=0 time=0 us cost=16 size=1984824 card=8168)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PX Deq: Join ACK 14 0.00 0.00
log file sync 1 0.00 0.00
PX Deq: Parse Reply 7 0.01 0.02
name-service call wait 1 0.03 0.03
PX Deq: Execute Reply 367 0.97 3.38
PX Deq: Signal ACK RSG 7 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
the same behaviour reproduces every time.