Re: 10046 trace - unaccounted for time

Keith

  How was the OS performance during this time frame? What was the cpu queue length ? Was there any paging or swapping?   One way is to look at statistics difference at session level for short time frame. You could also dump function call stack (using oradebug dump errorstack 1) or OS utilities (pstack) every few seconds and see if there is any change in the function call stack. That might given an indication as to which function call process is spending time or stuck.

Cheers
Riyaj
The Pythian Group
blog: http://orainternals.wordpress.com

Keith Moore wrote:
> 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
> =====================
>

<snipped to avoid overquoting>

--
http://www.freelists.org/webpage/oracle-l