Re: Very slowly progressing INSERT INTO SELECT statement

This looks like a case of the ASSM bitmaps getting into a state that confuses your session (and that means the /*+ append */ strategy will bypass the problem since it will handle only bitmaps that are current FREE or UNFORMATTED.

Things like this aren't supposed to happen in 19.3, but the statistics suggest the session is looking in bitmap blocks for free space, and finding a bltmap that says "block X has space" - so the session visits block X and finds that it can't use it so it goes back to the bitmap and checks another "bit" and goes through the cycle again.

I've written a couple of notes about what can make this happen, and one of the notes raised the problem of 16KB blocks with lots of migrated rows and a full ITL - but the problems I've blogged about should have been fixed by 19.3 (unless the fix for the ITL overlooked a detail of the 16KB / ITL problem).

I am a little curious that the CPU usage is reported as "background cpu time" - I had assumed that you'd be showing us the session doing the insert. Is this the case, or is 642 really a background process (maybe one of the Wnnn processes).

(Tanel Poder and I got into a discussion about ASSM behaviour a couple of days ago - this looks like something on the same theme)

Regards
Jonathan Lewis

On Fri, May 15, 2020 at 3:15 AM Ilmar Kerm <ilmar.kerm_at_gmail.com> wrote:

> 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-l