RE: PL/SQL Wrapper Costs

From: Mark W. Farnham <mwf_at_rsiz.com>
Date: Thu, 14 Jun 2007 13:18:58 -0400
Message-ID: <00d801c7aea8$18e15db0$1100a8c0@rsiz.com>

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_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Peter Sylvester
Sent: Wednesday, June 13, 2007 7:38 PM
To: Oracle-L_at_freelists.org
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>

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

Received on Thu Jun 14 2007 - 12:18:58 CDT