Re: 10046 trace - unaccounted for time
From: Daniel Fink <daniel.fink_at_optimaldba.com>
Date: Wed, 06 Aug 2008 14:00:15 -0600
Message-ID: <489A02CF.8030401@optimaldba.com>
Date: Wed, 06 Aug 2008 14:00:15 -0600
Message-ID: <489A02CF.8030401@optimaldba.com>
What is the text for CURSOR #10?
-- Daniel Fink Help me support The Children's Hospital of Denver! I'm riding in the 2008 Courage Classic - 157 miles in 3 days Help me reach my goal of $2,500.00 in donations. Visit my Personal Rider Page http://www.couragetours.com/2008/danielwfink to donate OptimalDBA.com - Oracle Performance, Diagnosis, Data Recovery and Training OptimalDBA http://www.optimaldba.com Oracle Blog http://optimaldba.blogspot.com Lost Data? http://www.ora600.be/ Keith Moore wrote:Received on Wed Aug 06 2008 - 15:00:15 CDT
> It's actually an insert that is causing the problems. From tkprof output you
> can see the total cpu is only .03 seconds for 19 inserts. Below that is the
> raw trace information that shows 78 seconds of unaccounted for time during one
> of the inserts.
>
> We are setting up some tests on a non-production database and I will try to
> get more information and run queries during the actual hang.
>
> BTW, the first column is a unique ID and the 2nd column is a clob but usually
> small (less than 1K bytes).
>
> Keith
>
> INSERT INTO PWRLINE.LSCHANNELCUTDATA(UIDCHANNELCUT, VALUECODES)
> VALUES
> (:1,:2) RETURNING "VALUECODES" INTO :3
>
>
> call count cpu elapsed disk query current rows
> ------- ------ -------- ---------- ---------- ---------- ---------- ----------
> Parse 19 0.00 0.00 0 0 0 0
> Execute 19 0.03 0.01 0 19 133 19
> Fetch 0 0.00 0.00 0 0 0 0
> ------- ------ -------- ---------- ---------- ---------- ---------- ----------
> total 38 0.03 0.01 0 19 133 19
>
> =====================
> PARSING IN CURSOR #3 len=109 dep=0 uid=19 oct=2 lid=19 tim=16059356779862
> hv=1757063019 ad='13f277e0'
> INSERT INTO PWRLINE.LSCHANNELCUTDATA(UIDCHANNELCUT, VALUECODES) VALUES(:1,:2)
> RETURNING "VALUECODES"
> INTO :3
> END OF STMT
> PARSE #3:c=0,e=169,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=16059356779856
> WAIT #3: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
> EXEC #3:c=0,e=700,p=0,cr=1,cu=7,mis=0,r=1,dep=0,og=4,tim=16059356780754
> WAIT #3: nam='SQL*Net message from client' ela= 1270 p1=1413697536 p2=1 p3=0
> *** 2008-08-03 23:26:47.196
> WAIT #10: nam='latch free' ela= 12 p1=16764539576 p2=98 p3=0
> *** 2008-08-03 23:27:05.703
> WAIT #10: nam='db file sequential read' ela= 15214 p1=121 p2=125734 p3=1
> WAIT #10: nam='latch free' ela= 12 p1=16796726312 p2=98 p3=0
> *** 2008-08-03 23:28:05.067
> WAIT #10: nam='db file sequential read' ela= 44241 p1=232 p2=112428 p3=1
> WAIT #10: nam='SQL*Net more data from client' ela= 148 p1=1413697536 p2=120 p3=0
> WAIT #10: nam='SQL*Net more data from client' ela= 38 p1=1413697536 p2=131 p3=0
> WAIT #10: nam='SQL*Net more data from client' ela= 23 p1=1413697536 p2=142 p3=0
> WAIT #10: nam='direct path write (lob)' ela= 2578 p1=113 p2=43160 p3=1
> WAIT #0: nam='SQL*Net message to client' ela= 6 p1=1413697536 p2=1 p3=0
> WAIT #0: nam='SQL*Net message from client' ela= 13420 p1=1413697536 p2=1 p3=0
> WAIT #0: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
> WAIT #0: nam='SQL*Net message from client' ela= 1652 p1=1413697536 p2=1 p3=0
> WAIT #0: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
> WAIT #0: nam='SQL*Net message from client' ela= 906 p1=1413697536 p2=1 p3=0
> WAIT #0: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
> WAIT #0: nam='SQL*Net more data to client' ela= 148 p1=1413697536 p2=2002 p3=0
> WAIT #0: nam='SQL*Net message from client' ela= 4457 p1=1413697536 p2=1 p3=0
> =====================
>
-- http://www.freelists.org/webpage/oracle-l