RE: PL/SQL Wrapper Costs
- From: "Mark W. Farnham" <mwf@xxxxxxxx>
- To: <peters@xxxxxxxxx>, <Oracle-L@xxxxxxxxxxxxx>
- Date: Thu, 14 Jun 2007 13:18:58 -0400
If your scoping was correct, then a single wait for a client turn around was
over half the elapsed time. Even if there were zero more outliers and we
average the rest of the time, you're only talking about 22 ten-thousandths
of a second per call (the additional 1418 executions total 3.13 seconds).
If you're getting user response complaints based on this, you have a tough
audience. Of course we're talking about 7.39 seconds of elapsed time out of
ten minutes. So what else was going on? From a user initiated request were
the client program and Oracle shaking hands on a row by row basis to
accumulate results and ultimately reply to the user sitting there? That is,
are these trace results completely divorced from the user experience? From
what you've given us it seems like the user would have to have been annoyed
by one wait of about 4 seconds and all the other waits totaling about 3
seconds. What was the 3.86 seconds? Could it have been user think time, or
were we in the "machines handshaking" phase at that point? Was the client a
single cpu desktop busy doing something else for a while? I don't think we
can really tell from what you've sent us.
Probably I am missing something.
Regards,
mwf
_____
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Peter Sylvester
Sent: Wednesday, June 13, 2007 7:38 PM
To: Oracle-L@xxxxxxxxxxxxx
Subject: PL/SQL Wrapper Costs
<snip>
Oh, and these procedures typically get called many 1000s of times an hour.
The trace file represents about 10 minutes of activity on a particular
transaction in one session.
Here are some clips from the trace file:
The procedure call:
<snip>
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 3 0.00 0.00 0 0 0
0
Execute 1419 4.61 7.39 80 5676 0
1419
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 1422 4.61 7.39 80 5676 0
1419
<snip>
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
SQL*Net message to client 1425 0.00
0.00
SQL*Net message from client 1425 3.86
6.99
latch: library cache 37 0.00
0.06
latch: shared pool 12 0.00
0.04
****************************************************************************
****
<snip>
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 8 0.00 0.00 0 0 0
0
Execute 1419 0.39 0.46 0 0 0
0
Fetch 1419 0.13 0.76 80 5676 0
1419
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2846 0.52 1.23 80 5676 0
1419
<snip>
Other related posts:
