Insert All and 11gr2

If you have many single insert statements then you can wrap into insert all which can reduce parsing and thus loading of that many single insert would be much faster. But, sometime back i saw some slowness in this particularly in 11gr2 and today again that thing bother me. So, though to publish this information see someone might have insight on this. Oh, Sorry to mention who else then Mr. Tanel i think off.

 Here is the test case

  


TARAL> @wait print 101 e123 10000
                                                                                                                  % Total  Total Event   Distinct   Avg time
    SID STATE   EVENT                               P1                         P2              P3            SEQ#    Time      Time ms     Events   ms/Event
------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
    101 WORKING On CPU / runqueue                                                                                  100.00      150.000          1    150.000

TARAL> @wait print 101 e123 10000
                                                                                                                  % Total  Total Event   Distinct   Avg time
    SID STATE   EVENT                               P1                         P2              P3            SEQ#    Time      Time ms     Events   ms/Event
------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
    101 WORKING On CPU / runqueue                                                                                  100.00      150.000          1    150.000

TARAL> @wait print 101 e123 20000
                                                                                                                  % Total  Total Event   Distinct   Avg time
    SID STATE   EVENT                               P1                         P2              P3            SEQ#    Time      Time ms     Events   ms/Event
------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
    101 WORKING On CPU / runqueue                                                                                  100.00      300.000          1    300.000

TARAL> @wait print 101 e123 20000
                                                                                                                  % Total  Total Event   Distinct   Avg time
    SID STATE   EVENT                               P1                         P2              P3            SEQ#    Time      Time ms     Events   ms/Event
------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
    101 WORKING On CPU / runqueue                                                                                  100.00      310.000          1    310.000

----------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                               ,         DELTA, HDELTA/SEC,    %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------
    101, TARAL, STAT, opened cursors cumulative               ,             6,         .3,
    101, TARAL, STAT, recursive calls                         ,            85,       4.25,
    101, TARAL, STAT, session logical reads                   ,            13,        .65,
    101, TARAL, STAT, CPU used by this session                ,         18561,     928.05,
    101, TARAL, STAT, session pga memory                      ,      19267584,    963.38k,
    101, TARAL, STAT, consistent gets                         ,            13,        .65,
    101, TARAL, STAT, consistent gets from cache              ,            13,        .65,
    101, TARAL, STAT, consistent gets from cache (fastpath)   ,             6,         .3,
    101, TARAL, STAT, consistent gets - examination           ,             6,         .3,
    101, TARAL, STAT, shared hash latch upgrades - no wait    ,             1,        .05,
    101, TARAL, STAT, calls to get snapshot scn: kcmgss       ,             6,         .3,
    101, TARAL, STAT, no work - consistent read gets          ,             6,         .3,
    101, TARAL, STAT, index scans kdiixs1                     ,             7,        .35,
    101, TARAL, STAT, sql area evicted                        ,            20,          1,
    101, TARAL, STAT, session cursor cache hits               ,             2,         .1,
    101, TARAL, STAT, session cursor cache count              ,            -1,       -.05,
    101, TARAL, STAT, buffer is not pinned count              ,             7,        .35,
    101, TARAL, STAT, parse time elapsed                      ,             1,        .05,
    101, TARAL, STAT, parse count (total)                     ,             4,         .2,
    101, TARAL, STAT, execute count                           ,             6,         .3,
    101, TARAL, STAT, sorts (memory)                          ,             3,        .15,
    101, TARAL, TIME, hard parse elapsed time                 ,     185463811,      9.27s,   927.3%, |@@@@@@@@@@|
    101, TARAL, TIME, repeated bind elapsed time              ,             4,       .2us,      .0%, |          |
    101, TARAL, TIME, parse time elapsed                      ,     185477232,      9.27s,   927.4%, |@@@@@@@@@@|
    101, TARAL, TIME, DB CPU                                  ,     185430000,      9.27s,   927.2%, |@@@@@@@@@@|
    101, TARAL, TIME, sql execute elapsed time                ,           453,    22.65us,      .0%, |          |
    101, TARAL, TIME, DB time                                 ,     185655283,      9.28s,   928.3%, |@@@@@@@@@@|
--  End of snap 1, end=2010-10-13 15:46:53, seconds=20

--- Here are some output from trace which confirms above

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1     19.64      19.64          0          0          0           0
Execute      1      0.04       0.04          0        406       1225         406
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     19.68      19.68          0        406       1225         406

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 147

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  MULTI-TABLE INSERT  (cr=406 pr=0 pw=0 time=0 us)
      1   FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1     59.50      59.51          0          0          0           0
Execute      1      0.05       0.04          0        493       1488         493
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     59.55      59.56          0        493       1488         493

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 147

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1     66.20      66.21          0          0          0           0
Execute      1      0.07       0.07          0        697       2100         696
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     66.27      66.28          0        697       2100         696

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 147

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  MULTI-TABLE INSERT  (cr=697 pr=0 pw=0 time=0 us)
      1   FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)

Here is the interesting part

   <-audRegFro()+200<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300
   <-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300
   <-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300
   <-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300
   <-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-audRegFro()+300<-kkmpfcbk()+56
   <-qcsprfro()+992<-qcsprfro_tree()+324<-qcsprfro_tree()+400<-qcspqbDescendents()+292<-qcspqb()+324<-kkmdrv()+292
   <-opiSem()+2200<-opiDeferredSem()+420<-opitca()+236<-kksFullTypeCheck()+16<-rpiswu2()+656<-kksLoadChild()+10056
   <-kxsGetRuntimeLock()+1804<-kksfbc()+7408<-kkspsc0()+1512<-kksParseCursor()+176
   <-opiosq0()+2388<-kpooprx()+196<-kpoal8()+588<-opiodr()+1424<-ttcpip()+1056<-opitsk()+1512<-opiino()+1000<-opiodr()+1424
   <-opidrv()+1096<-sou2o()+92<-opimai_real()+304<-ssthrdmain()+240<-main()+308<-_start()+380

After turning off auditing it went as expected

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.21       0.21          0          0          0           0
Execute      1      0.04       0.03          2        406       1227         406
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.25       0.25          2        406       1227         406

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 147

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  MULTI-TABLE INSERT  (cr=406 pr=2 pw=0 time=0 us)
      1   FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.53       0.54          0          0          0           0
Execute      1      0.06       0.06          3        697       2103         696
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.59       0.61          3        697       2103         696
Advertisements

About Taral
I am Rookie to Oracle Technology so let's see where it goes

2 Responses to Insert All and 11gr2

  1. Tanel Poder says:

    It’s got to be a bug, no SQL should be parsing for that long (the “parse time elapsed” and “DB CPU” metrics in Snapper).

    Looking into stack traces in such cases (100% CPU usage, especially when all is for parsing) is a good thing to do next. I would take the top functions and put them into metalink (and search for bug descriptions too). That should reveal which bug it is, if someone has filed that bug already. If you don’t find anything, then it’s time to send this info to Oracle Support…

    • Taral says:

      Thank You Sir for all the information. I even tried with 11.2.0.2 and it’s same thing happening there. I will create ticket with oracle and will update you. Again, thank you for the information

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: