Hi Ilmar,
Quote /"Parallel DML is not enabled,"/.
My first idea: Why on earth? Enable parallel dml and throw in an append
hint.
It is not the first time I see the insert step taking most of the time
when parallel processing gets queued on the QC.
Other than that you could query ash for planline 1 and group by event,
current object.
Regards
Lothar
Am 15.05.2020 um 04:14 schrieb Ilmar Kerm:
Hi
Version 19.3.0, RAC.
We have currently running one insert-select statement:
INSERT /*+ PARALLEL(12 1) */ INTO target (column list) SELECT column list, including some analytics FROM source LOG ERRORS INTO ERR$_TARGET(:B1 ) REJECT LIMIT 3000;
Parallel DML is not enabled, only the SELECT part is run in parallel.
And it is progressing very slowly (currently have run over 20 hours, and processed only 18M rows so far). Much slower than usual, execution plan has not changed.
Process in pretty much fully running on CPU, other wait events are negligible.
From ASH I see that all the time is being spent on plan line 1 - operation LOAD TABLE CONVENTIONAL.
Here is full snapper sample:
Sampling SID 642 with interval 10 seconds, taking 5 snapshots...
-- Session Snapper v4.30 - by Tanel Poder ( http://blog.tanelpoder.com/snapper ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SID @INST, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS, WAITS/SEC, AVERAGES
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
642 @1, DW_USER_RE, STAT, session logical reads , 10462158, 1.01M, , , , , 10.46M total buffer visits
642 @1, DW_USER_RE, STAT, cluster wait time , 13, 1.26, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, user I/O wait time , 4, .39, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, non-idle wait time , 15, 1.45, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, non-idle wait count , 284, 27.52, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, enqueue requests , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, enqueue releases , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, physical read total IO requests , 76, 7.36, , , , , 16.38k bytes per request
642 @1, DW_USER_RE, STAT, physical read total bytes , 1245184, 120.64k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, cell physical IO interconnect bytes , 1245184, 120.64k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, gcs messages sent , 175, 16.96, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, gcs data block access records , 76, 7.36, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, gcs read-mostly lock failures , 76, 7.36, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, gcs affinity lock grants , 4, .39, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, db block gets , 5712026, 553.42k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, db block gets from cache , 5712061, 553.42k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, db block gets from cache (fastpath) , 5711840, 553.4k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, consistent gets , 4755948, 460.79k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, consistent gets from cache , 4755976, 460.79k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, consistent gets pin , 955, 92.53, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, consistent gets pin (fastpath) , 955, 92.53, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, consistent gets examination , 4755070, 460.7k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, consistent gets examination (fastpath) , 4755095, 460.7k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, logical read bytes from cache , 171515904000, 16.62G, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, physical reads , 76, 7.36, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, physical reads cache , 76, 7.36, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, physical read IO requests , 76, 7.36, , , , , 16.38k bytes per request
642 @1, DW_USER_RE, STAT, physical read bytes , 1245184, 120.64k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, db block changes , 1595, 154.53, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, free buffer requested , 80, 7.75, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, hot buffers moved to head of LRU , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, free buffer inspected , 58, 5.62, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, commit cleanouts , 3, .29, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, commit cleanouts successfully completed , 3, .29, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, calls to kcmgcs , 4755464, 460.74k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, calls to kcmgas , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, calls to get snapshot scn: kcmgss , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, redo entries , 1288, 124.79, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, redo size , 215520, 20.88k, , , , , ~ bytes per user commit
642 @1, DW_USER_RE, STAT, file io wait time , 34035, 3.3k, , , , , 447.83us bad guess of IO wait time per IO request
642 @1, DW_USER_RE, STAT, gc status messages received , 94, 9.11, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, gc local grants , 4, .39, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, gc remote grants , 104, 10.08, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, undo change vector size , 51280, 4.97k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, immediate (CURRENT) block cleanout applications , 4, .39, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, deferred (CURRENT) block cleanout applications , 6, .58, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, commit txn count during cleanout , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, active txn count during cleanout , 4755769, 460.77k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, cleanout - number of ktugct calls , 4755770, 460.77k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, Block Cleanout Optim referenced , 6, .58, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, blocks cleaned out using minact , 6, .58, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, ASSM gsp:get free block , 65, 6.3, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, ASSM gsp:get free data block , 64, 6.2, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, ASSM gsp:get free index block , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, ASSM cbk:blocks examined , 4757236, 460.91k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, ASSM cbk:blocks marked full , 2, .19, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, ASSM gsp:L1 bitmaps examined , 955601, 92.58k, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, ASSM gsp:L2 bitmaps examined , 950, 92.04, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, leaf node splits , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, heap block compress , 2, .19, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, HSC Heap Segment Block Changes , 63, 6.1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, Heap Segment Array Inserts , 63, 6.1, , , , , ~ per execution
642 @1, DW_USER_RE, STAT, PX remote messages recv'd , 1, .1, , , , , ~ per execution
642 @1, DW_USER_RE, TIME, background cpu time , 9758923, 945.51ms, 94.6%, [##########], , ,
642 @1, DW_USER_RE, TIME, background elapsed time , 9908062, 959.96ms, 96.0%, [##########], , , 4 % unaccounted time
642 @1, DW_USER_RE, WAIT, db file sequential read , 34511, 3.34ms, .3%, [ ], 77, 7.46, 448.19us average wait
642 @1, DW_USER_RE, WAIT, gc current grant read-mostly invalidation , 127630, 12.37ms, 1.2%, [W ], 106, 10.27, 1.2ms average wait
642 @1, DW_USER_RE, WAIT, PX Deq: Execute Reply , 11, 1.07us, .0%, [ ], 1, .1, 11us average wait
642 @1, DW_USER_RE, WAIT, events in waitclass Other , 5, .48us, .0%, [ ], 1, .1, 5us average wait
-- End of Stats snap 1, end=2020-05-15 02:43:40, seconds=10.3
---------------------------------------------------------------------------------------------------------------
ActSes %Thread | INST | SQL_ID | SQL_CHILD | EVENT | WAIT_CLASS
---------------------------------------------------------------------------------------------------------------
.95 (95%) | 1 | xxxxxxxxxxxxx | 0 | ON CPU | ON CPU
.05 (5%) | 1 | xxxxxxxxxxxxx | 0 | db file sequential read | User I/O
-- End of ASH snap 1, end=2020-05-15 02:43:40, seconds=10, samples_taken=19, AAS=1
Here I see that there is heavy reading going on - logical read bytes from cache = 16.6GB/s
Other very active statistics that catch my eye: "active txn count during cleanout" and "cleanout - number of ktugct calls". And "ASSM cbk:blocks examined". Hard to find much information about these statistics.
At the same time "db block changes" is quite low - it is INSERT statement spending its time on "LOAD TABLE CONVENTIONAL" after all.
Database uses 16k block size.
Trying to understand what could be going on here. Some form of delayed block cleanout?
--
Ilmar Kerm
