Re: Very slowly progressing INSERT INTO SELECT statement
Date: Fri, 15 May 2020 08:27:18 +0200
Message-ID: <1d89ae6e-ecf4-9e3c-ff67-5ed37fb7871e_at_bluewin.ch>
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
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 _at_INST, USERNAME , TYPE, STATISTIC
> , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS,
> WAITS/SEC, AVERAGES
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> 642 _at_1, DW_USER_RE, STAT, session logical reads
> , 10462158, 1.01M, , ,
> , , 10.46M total buffer visits
> 642 _at_1, DW_USER_RE, STAT, cluster wait time
> , 13, 1.26, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, user I/O wait time
> , 4, .39, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, non-idle wait time
> , 15, 1.45, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, non-idle wait count
> , 284, 27.52, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, enqueue requests
> , 1, .1, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, enqueue releases
> , 1, .1, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, physical read total IO requests
> , 76, 7.36, , ,
> , , 16.38k bytes per request
> 642 _at_1, DW_USER_RE, STAT, physical read total bytes
> , 1245184, 120.64k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, cell physical IO interconnect bytes
> , 1245184, 120.64k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, gcs messages sent
> , 175, 16.96, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, gcs data block access records
> , 76, 7.36, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, gcs read-mostly lock failures
> , 76, 7.36, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, gcs affinity lock grants
> , 4, .39, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, db block gets
> , 5712026, 553.42k, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, db block gets from cache
> , 5712061, 553.42k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, db block gets from cache (fastpath)
> , 5711840, 553.4k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, consistent gets
> , 4755948, 460.79k, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, consistent gets from cache
> , 4755976, 460.79k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, consistent gets pin
> , 955, 92.53, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, consistent gets pin (fastpath)
> , 955, 92.53, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, consistent gets examination
> , 4755070, 460.7k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, consistent gets examination (fastpath)
> , 4755095, 460.7k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, logical read bytes from cache
> , 171515904000, 16.62G, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, physical reads
> , 76, 7.36, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, physical reads cache
> , 76, 7.36, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, physical read IO requests
> , 76, 7.36, , ,
> , , 16.38k bytes per request
> 642 _at_1, DW_USER_RE, STAT, physical read bytes
> , 1245184, 120.64k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, db block changes
> , 1595, 154.53, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, free buffer requested
> , 80, 7.75, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, hot buffers moved to head of LRU
> , 1, .1, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, free buffer inspected
> , 58, 5.62, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, commit cleanouts
> , 3, .29, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, commit cleanouts successfully completed
> , 3, .29, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, calls to kcmgcs
> , 4755464, 460.74k, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, calls to kcmgas
> , 1, .1, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, calls to get snapshot scn: kcmgss
> , 1, .1, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, redo entries
> , 1288, 124.79, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, redo size
> , 215520, 20.88k, , , ,
> , ~ bytes per user commit
> 642 _at_1, DW_USER_RE, STAT, file io wait time
> , 34035, 3.3k, , ,
> , , 447.83us bad guess of IO wait time per IO request
> 642 _at_1, DW_USER_RE, STAT, gc status messages received
> , 94, 9.11, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, gc local grants
> , 4, .39, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, gc remote grants
> , 104, 10.08, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, undo change vector size
> , 51280, 4.97k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, immediate (CURRENT) block cleanout
> applications , 4, .39, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, deferred (CURRENT) block cleanout
> applications , 6, .58, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, commit txn count during cleanout
> , 1, .1, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, active txn count during cleanout
> , 4755769, 460.77k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, cleanout - number of ktugct calls
> , 4755770, 460.77k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, Block Cleanout Optim referenced
> , 6, .58, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, blocks cleaned out using minact
> , 6, .58, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, ASSM gsp:get free block
> , 65, 6.3, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, ASSM gsp:get free data block
> , 64, 6.2, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, ASSM gsp:get free index block
> , 1, .1, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, ASSM cbk:blocks examined
> , 4757236, 460.91k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, ASSM cbk:blocks marked full
> , 2, .19, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, ASSM gsp:L1 bitmaps examined
> , 955601, 92.58k, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, ASSM gsp:L2 bitmaps examined
> , 950, 92.04, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, leaf node splits
> , 1, .1, , , ,
> , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, heap block compress
> , 2, .19, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, HSC Heap Segment Block Changes
> , 63, 6.1, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, Heap Segment Array Inserts
> , 63, 6.1, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, STAT, PX remote messages recv'd
> , 1, .1, , ,
> , , ~ per execution
> 642 _at_1, DW_USER_RE, TIME, background cpu time
> , 9758923, 945.51ms, 94.6%, [##########],
> , ,
> 642 _at_1, DW_USER_RE, TIME, background elapsed time
> , 9908062, 959.96ms, 96.0%, [##########],
> , , 4 % unaccounted time
> 642 _at_1, DW_USER_RE, WAIT, db file sequential read
> , 34511, 3.34ms, .3%, [ ],
> 77, 7.46, 448.19us average wait
> 642 _at_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 _at_1, DW_USER_RE, WAIT, PX Deq: Execute Reply
> , 11, 1.07us, .0%, [ ],
> 1, .1, 11us average wait
> 642 _at_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
-- http://www.freelists.org/webpage/oracle-lReceived on Fri May 15 2020 - 08:27:18 CEST