| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Usenet -> c.d.o.server -> Re: Application, session and performance.
On Mar 24, 7:08 pm, gxchrist..._at_yahoo.co.uk wrote:
> On 24 mar, 22:46, "Charles Hooper" <hooperc2..._at_yahoo.com> 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:http://download-west.oracle.com/docs/cd/B19306_01/server.102/b14211/i...
>
> > 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:
> > SELECT
> > NAME,
> > VALUE
> > FROM
> > V$SYSSTAT
> > WHERE
> > NAME='user commits';
>
> > A similar query to track at the session level:
> > SELECT
> > SS.SID,
> > SN.NAME,
> > SS.VALUE
> > FROM
> > V$SESSTAT SS,
> > V$STATNAME SN
> > WHERE
> > SN.NAME='user commits'
> > AND SN.STATISTIC#=SS.STATISTIC#;
>
> > 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)
END OF STMT
PARSE
#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)'
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
 |
 |