Re: PL/SQL Wrapper Costs

  • From: Peter Sylvester <peters@xxxxxxxxx>
  • To: Oracle-L@xxxxxxxxxxxxx
  • Date: Mon, 18 Jun 2007 16:22:38 -0400

Mark, et al,

I have been trying to get my arms around this situation. There are a number of procedures that had high exec counts and high elapsed time, totalling about 19s ET. There is also one other problem query thats eating up another 12s but that is an obvious execution plan thing. BTW, It turns out this was done on a test system, which is single instance, not RAC, but has the full data set.

I don't have a clear understanding of the application internals, but from the quantity of calls that it makes, it seems to be reconstituting a number of complex objects, one record at a time. I also don't have the details on what was done in the test, but only a handful of records were being updated, so I don't think there is much user wait time in here (if any). Its >99% select statements within procedures.

If I dive into the raw trace file, I get a somewhat different picture than tkprof puts out (assuming I am reading it correctly). I used "gawk" to pull out lines for cursors #129 and #164 which correspond to the IDNT$U.UNIFACE_IO call, and its underlying SELECT statement against the CASE table, and I trimmed these down to (99) executions before the cursors got reused.

In looking at these (hand sampled values), the elapsed time seems roughly split between the procedure and the select. On the procedure side, the execute time dominates, roughly 5ms per call. On the select statement db_file_sequential_read dominates, at about 6ms per call. The sql*net seems to be in the noise, at less than 1ms per call, about what you would expect on a LAN. Overall it runs about 9ms per call (about 110 records/second).

Although that does not sound that bad, due to the number of calls, this adds up to about 13s of user response time on this procedure alone, and there are a number of others with similar timings in the same transaction. I am beginning to think that its the shear volume of calls thats the real killer here.

I created a zip of the raw trace, tkprof, and my "sampling" of (99) calls, if anyone would like to take a peek, and see if I am missing something obvious here. In the trace_sample file I put the line numbers from the original trace file in front of each line for reference purposes.

http://home.comcast.net/~ps8899/demos/trace_21180.zip

thanks,
Peter Sylvester


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


Other related posts: