Oracle FAQ Your Portal to the Oracle Knowledge Grid

Home -> Community -> Usenet -> c.d.o.server -> Re: Application, session and performance.

Re: Application, session and performance.

From: Charles Hooper <>
Date: 24 Mar 2007 18:41:02 -0700
Message-ID: <>

On Mar 24, 7:08 pm, wrote:
> On 24 mar, 22:46, "Charles Hooper" <> wrote:
> > While the performance monitoring capabilities have been enhanced with
> > each release, many of the capabilities that you need have existed for
> > more than a decade. The 10g capabilities that you may be thinking of
> > are additional cost add-ons that can be added to the Enterprise
> > Edition of Oracle.
> > A good overview of performance monitoring:
> > Time between two commits is a bit more difficult to determine. At the
> > system level, you can track the number of COMMITs executed like this:
> > NAME,
> > FROM
> > NAME='user commits';
> > A similar query to track at the session level:
> > SS.SID,
> > SN.NAME,
> > FROM
> > SN.NAME='user commits'
> > The above does not actually indicate the time between COMMITs. To
> > obtain that information, you likely will need to turn to a 10046
> > trace. After the trace file is generated, look for lines that contain
> > "XCTEND". If the line contains RLBK=0, then the session issued a
> > COMMIT, if it contains RLBK=1, then the session issued a rollback.
> > Use the tim= values in the trace file to determine the time delta
> > between each XCTEND line.
> > The 10046 trace can also be used to determine long running operations,
> > but those trace files likely will not be the starting point for
> > investigation. The various session level performance views provide a
> > great deal of information to determine which session has used the
> > greatest amount of the server resources. V$SQL also provides a lot of
> > information needed to track down long running queries.
> > Charles Hooper
> > PC Support Specialist
> > K&M Machine-Fabricating, Inc.- Ocultar texto de la cita -
> > - Mostrar texto de la cita -- Hide quoted text -
> - Show quoted text -
> Hello,
> Many thanks for the nice response. I will try to explain a little
> more what I need.
> From a pure functional standpoint, the application consists of
> several queries between commits that forms a business step. For
> instance:
> Start
> Query1
> Query2
> Query3
> Commit
> Start
> Query4
> Query1
> Commit
> What I really need is to identify time each session (or, lets say
> the 5 longest running executing sessions each 1 minute) spend in each
> one of the business process. Of course, the best option is to
> instrument the application, but I may consider the imposibility of
> changing the application itself.
> So basically,what I need to capture can be based on queries or
> time between commits for each one of the users. This would lead me,
> with some tweaking on the data, to the result I need.
> Regarding the 10046 trace... How expensive is it from the
> performance perspective?. It sounds like a good idea...
> Iván.

A 10046 trace can output wait events that are associated with the individual SQL statements between each COMMIT. This level of detail will likely be more useful to you when performance tuning the application than would the time deltas between the COMMITs. The wait events will tell you, for instance, if the delays are caused by client side processing, writing to the temp tablespace, index or table access (down to the file number and block, which may be used to determine the actual object causing the delay), etc. Each SQL statement will also include the total elapsed processing time and server CPU that was consumed.

It takes some practice learning how to read 10046 trace files. Cary Millsap's "Optimizing Oracle Performance" is quite possibly the best resource for decoding 10046 trace files, but there are also a couple good articles on Metalink. While TKPROF can analyze 10046 trace files, much of the useful data contained in the trace file is either lost or reported out of scope. The 10046 trace file may report information like this:
PARSING IN CURSOR #2 len=259 dep=0 uid=32 oct=3 lid=32 tim=20019968464 hv=3571426001 ad='509f8a14'
  (SQL statement deleted)
#2:c=124801,e=556036,p=0,cr=121,cu=0,mis=1,r=0,dep=0,og=1,tim=20019968457 EXEC #2:c=0,e=141,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=20019968953 FETCH
#2:c=5631636,e=5562750,p=0,cr=6818,cu=0,mis=0,r=0,dep=0,og=1,tim=20025531842 WAIT #2: nam='SQL*Net message from client' ela= 73768512 driver id=1413697536 #bytes=1 p3=0 obj#=14786 tim=20099300611 STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='FILTER (cr=6818 pr=0 pw=0 time=5562816 us)'
STAT #2 id=2 cnt=1497257 pid=1 pos=1 obj=0 op='HASH GROUP BY (cr=6818 pr=0 pw=0 time=10349366 us)'
STAT #2 id=3 cnt=2064509 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=6818 pr=0 pw=0 time=18580687 us)'

STAT #2 id=4 cnt=73 pid=3 pos=1 obj=14766 op='TABLE ACCESS BY INDEX
ROWID T1 (cr=77 pr=0 pw=0 time=1943 us)'
STAT #2 id=5 cnt=73 pid=4 pos=1 obj=14776 op='INDEX RANGE SCAN
T1_INDEX1 (cr=4 pr=0 pw=0 time=480 us)'

STAT #2 id=6 cnt=2064509 pid=3 pos=2 obj=14786 op='INDEX RANGE SCAN T1_INDEX3 (cr=6741 pr=0 pw=0 time=8260306 us)'

With proper scoping, and accurate time calculations, the above can be translated like this:
Execute at 0.555570 (Parse to Exec 0.000489),CPU Time 0.000000,Elapsed Time 0.000141,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,Goal=ALL_ROWS
  Fetch at 6.118459 (Parse to Fetch 5.563378),CPU Time 5.631636,Elapsed Time 5.562750,Rows Retrievd 0,Blks from Buff 6818,Blks from Disk 0

       (Rows 0)   FILTER  (cr=6818 pr=0 pw=0 time=5562816 us)
 (Rows 1497257)    HASH GROUP BY (cr=6818 pr=0 pw=0 time=10349366 us)
 (Rows 2064509)     NESTED LOOPS  (cr=6818 pr=0 pw=0 time=18580687 us)
      (Rows 73)      TABLE ACCESS BY INDEX ROWID T1 (cr=77 pr=0 pw=0
time=1943 us)
      (Rows 73)       INDEX RANGE SCAN T1_INDEX1 (cr=4 pr=0 pw=0
time=480 us)
 (Rows 2064509)      INDEX RANGE SCAN T1_INDEX3 (cr=6741 pr=0 pw=0
time=8260306 us)

>From this, we can tell that 0.5 seconds into the trace file that a SQL
statement was parse, a very short time later an execute was called that required a but more than 5.5 seconds of server CPU time. Once the results of the SQL statement were sent back to the client, the client did not send another database call for 73.768 seconds. The SQL execute plan is also dumped to the trace file when the cursor closes. Wait event might lead someone to determine that the performance problem is client-side if this behavior occurs frequently. Such level of detail would likely be lost when using other methods for tracking performance problems.

10046 traces can cause a performance hit, especially if it is enabled at the system level (for all sessions). When enabled for a small number of sessions, the performance hit is minimal.

Charles Hooper
PC Support Specialist
K&M Machine-Fabricating, Inc. Received on Sat Mar 24 2007 - 20:41:02 CDT

Original text of this message