Home
> Performance > Insert All and 11gr2
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
Categories: Performance
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…
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