title: Oracle 11gR2: slow insert performance, then fast insert performance
body: <p>Trying to figure out root cause of slow Oracle insert performance.  I am running the exact same SQL twice - both times selecting 1000 rows from an Oracle table and inserting back into same table.  First INSERT runs in 76 seconds.  Second INSERT (same command) runs in &lt; 1 second.  Would love to hear any ideas of what may be going on with the former.  </p>
  
  <blockquote>
    <p>INSERT INTO MY_TABLE SELECT * FROM MY_TABLE WHERE ROWNUM &lt;= 1000;</p>
  </blockquote>
  
  <p>This is not a parse issue, INSERT of 1 row (ROWNUM &lt;=1) was run immediately before first-1000-row-insert and it ran very fast.</p>
  
  <p>Let me know if there's any trace data that would help.</p>
  
  <p>(EDIT: Gah! - explored meta.stackoverflow, found advice for formatting this data from Excel into ASCII-Art, put results in between code tags as recommended... and still got this mangled mess with all newlines removed.... META-HELP please someone let me know how to format this into a readable table that does not remove newlines!)</p>
  
  <pre><code>╔════════════════════════════════════════════════╦══════════════╦═══════════════╗
  ║                    StatName                    ║ First Insert ║ Second Insert ║
  ╠════════════════════════════════════════════════╬══════════════╬═══════════════╣
  ║ active txn count during cleanout               ║           17 ║            18 ║
  ║ buffer is not pinned count                     ║            8 ║             0 ║
  ║ buffer is pinned count                         ║            0 ║             0 ║
  ║ bytes received via SQL*Net from client         ║          145 ║           145 ║
  ║ bytes sent via SQL*Net to client               ║           79 ║            79 ║
  ║ calls to get snapshot scn: kcmgss              ║            4 ║             1 ║
  ║ calls to kcmgas                                ║            4 ║            16 ║
  ║ calls to kcmgcs                                ║           49 ║            50 ║
  ║ cell physical IO interconnect bytes            ║     16080896 ║        147456 ║
  ║ change write time                              ║            0 ║             1 ║
  ║ cleanout - number of ktugct calls              ║           17 ║            18 ║
  ║ consistent gets                                ║           71 ║            68 ║
  ║ consistent gets - examination                  ║           17 ║            18 ║
  ║ consistent gets from cache                     ║           71 ║            68 ║
  ║ consistent gets from cache (fastpath)          ║           50 ║            50 ║
  ║ CPU used by this session                       ║           17 ║             3 ║
  ║ CPU used when call started                     ║            0 ║             0 ║
  ║ cursor authentications                         ║            0 ║             1 ║
  ║ db block changes                               ║         2131 ║          2124 ║
  ║ db block gets                                  ║         5166 ║          5160 ║
  ║ db block gets from cache                       ║         5166 ║          5160 ║
  ║ db block gets from cache (fastpath)            ║         1035 ║          1037 ║
  ║ DB time                                        ║         7787 ║           104 ║
  ║ deferred (CURRENT) block cleanout applications ║            2 ║             0 ║
  ║ enqueue releases                               ║           22 ║             0 ║
  ║ enqueue requests                               ║           25 ║             0 ║
  ║ execute count                                  ║            3 ║             1 ║
  ║ file io wait time                              ║     76571222 ║       1010237 ║
  ║ free buffer inspected                          ║         3026 ║            64 ║
  ║ free buffer requested                          ║         1979 ║            34 ║
  ║ Heap Segment Array Inserts                     ║           35 ║            35 ║
  ║ hot buffers moved to head of LRU               ║          631 ║             2 ║
  ║ HSC Heap Segment Block Changes                 ║           35 ║            35 ║
  ║ IMU Flushes                                    ║            1 ║             0 ║
  ║ index scans kdiixs1                            ║            0 ║             0 ║
  ║ logical read bytes from cache                  ║     42901504 ║      42827776 ║
  ║ logons cumulative                              ║            0 ║             0 ║
  ║ logons current                                 ║            0 ║             0 ║
  ║ no work - consistent read gets                 ║           22 ║            18 ║
  ║ non-idle wait count                            ║         1732 ║            19 ║
  ║ non-idle wait time                             ║         7776 ║           101 ║
  ║ opened cursors cumulative                      ║            3 ║             1 ║
  ║ opened cursors current                         ║            0 ║             0 ║
  ║ parse count (hard)                             ║            1 ║             0 ║
  ║ parse count (total)                            ║            2 ║             1 ║
  ║ physical read bytes                            ║     16080896 ║        147456 ║
  ║ physical read IO requests                      ║         1836 ║            18 ║
  ║ physical read total bytes                      ║     16080896 ║        147456 ║
  ║ physical read total IO requests                ║         1836 ║            18 ║
  ║ physical read total multi block requests       ║            1 ║             0 ║
  ║ physical reads                                 ║         1963 ║            18 ║
  ║ physical reads cache                           ║         1963 ║            18 ║
  ║ physical reads cache prefetch                  ║          253 ║             0 ║
  ║ prefetch clients - default                     ║            1 ║             1 ║
  ║ process last non-idle time                     ║            0 ║             0 ║
  ║ recursive calls                                ║           15 ║             0 ║
  ║ recursive cpu usage                            ║            0 ║             0 ║
  ║ redo entries                                   ║         1079 ║          1073 ║
  ║ redo ordering marks                            ║            4 ║            16 ║
  ║ redo size                                      ║       463216 ║        453624 ║
  ║ redo subscn max counts                         ║           18 ║            16 ║
  ║ Requests to/from client                        ║            1 ║             1 ║
  ║ session connect time                           ║            0 ║             0 ║
  ║ session cursor cache count                     ║            2 ║             0 ║
  ║ session cursor cache hits                      ║            1 ║             0 ║
  ║ session logical reads                          ║         5237 ║          5228 ║
  ║ session pga memory                             ║       393216 ║             0 ║
  ║ session pga memory max                         ║       393216 ║             0 ║
  ║ session uga memory                             ║            0 ║             0 ║
  ║ session uga memory max                         ║            0 ║             0 ║
  ║ shared hash latch upgrades - no wait           ║            0 ║             0 ║
  ║ sorts (memory)                                 ║            0 ║             0 ║
  ║ sorts (rows)                                   ║            0 ║             0 ║
  ║ SQL*Net roundtrips to/from client              ║            1 ║             1 ║
  ║ table fetch by rowid                           ║            4 ║             0 ║
  ║ table scan blocks gotten                       ║           18 ║            18 ║
  ║ table scan rows gotten                         ║         1017 ║          1017 ║
  ║ table scans (long tables)                      ║            1 ║             1 ║
  ║ table scans (short tables)                     ║            0 ║             0 ║
  ║ undo change vector size                        ║       127384 ║        126740 ║
  ║ user calls                                     ║            2 ║             2 ║
  ║ user I/O wait time                             ║         7776 ║           101 ║
  ║ workarea executions - optimal                  ║            0 ║             0 ║
  ╚════════════════════════════════════════════════╩══════════════╩═══════════════╝`
  </code></pre>