Re: 10046 trace - unaccounted for time

  • From: Riyaj Shamsudeen <riyaj.shamsudeen@xxxxxxxxx>
  • To: kmoore@xxxxxxxxxxxx
  • Date: Wed, 06 Aug 2008 15:10:11 -0500

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>
--
//www.freelists.org/webpage/oracle-l

Other related posts:

  1. Home
  2. oracle-l
  3. Archive
  4. 08-2008