Very slowly progressing INSERT INTO SELECT statement

From: Ilmar Kerm <ilmar.kerm_at_gmail.com>
Date: Fri, 15 May 2020 04:14:14 +0200
Message-ID: <CAKnHwtd2R-PYt+Y9vnGx352a6-yfCPL6g4yG1ky5js2-TCRDkg_at_mail.gmail.com>



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


 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
Received on Fri May 15 2020 - 04:14:14 CEST

Original text of this message