Re: Query with LONG RAW

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: Tue, 2 Mar 2010 17:32:23 -0800 (PST)
Message-ID: <001a9781-d0ae-4d42-a8f7-92a08480bcba_at_15g2000yqi.googlegroups.com>

On Mar 2, 3:46 pm, "bob123" <bob..._at_gmail.com> wrote:
> Hi,
>
> How can I speed up the query below (third party software)
> it takes 30 min to execute.
> Oracle 9.2.0.6
> LONG RAW on PFMQ_MESSAGEDATASTORAGE
>
> Thanks in advance
>
> ***************************************************************************­*****
>
> SELECT   mds.messagepartdata, ms.status, mi.ID, mi.messageguid, mi.channel,
>          ROWNUM AS messagecount
>     FROM pfmq_messagedata md,
>          pfmq_messagedatastorage mds,
>          pfmq_messageinfo mi,
>          pfmq_messagestatus ms
>    WHERE (    mi.queuename = 'CL312911032'
>           AND mi.ID = ms.ID
>           AND mi.ID = md.ID
>           AND mi.ID = mds.ID
>           AND md.ID = mds.ID
>           AND md.messageparttype = mds.messageparttype
>           AND md.messageparttype = 1
>           AND (ms.statusrevisionnumber = (SELECT MAX (statusrevisionnumber)
>                                             FROM pfmq_messagestatus ms2
>                                            WHERE ms2.ID = ms.ID)
>               )
>          )
>      AND ((ms.status = 64) AND (mi.direction = 1) AND mi.messagetype = 0)
> ORDER BY mi.sequenceordinalnumber, mi.senttime
>
> call     count       cpu    elapsed       disk      query    current
> rows
> ------- ------  -------- ---------- ---------- ---------- ----------  ----------
> Parse        1      0.00       0.00          0          0          0
> 0
> Execute      1      0.00       0.00          0          0          0
> 0
> Fetch     4321     14.56     580.31     231750     746064          0
> 64806
> ------- ------  -------- ---------- ---------- ---------- ----------  ----------
> total     4323     14.56     580.31     231750     746064          0
> 64806
>
> Misses in library cache during parse: 1
> Optimizer goal: CHOOSE
> Parsing user id: 29
>
> Rows     Row Source Operation
> -------  ---------------------------------------------------
>   64806  SORT ORDER BY (cr=681258 r=184767 w=0 time=403515790 us)
>   64806   COUNT  (cr=681258 r=184767 w=0 time=1729762996 us)
>   64806    NESTED LOOPS  (cr=681258 r=184767 w=0 time=1729717540 us)
>   64806     NESTED LOOPS  (cr=486600 r=92648 w=0 time=901417748 us)
>   64806      NESTED LOOPS  (cr=356748 r=46572 w=0 time=268980743 us)
>   64820       TABLE ACCESS BY INDEX ROWID PFMQ_MESSAGEINFO (cr=31514 r=23422
> w=0 time=44437657 us)
>  120784        INDEX RANGE SCAN AK1_PFMQ_SEQUENCENUMBER (cr=3117 r=3062 w=0
> time=10896605 us)(object id 6511)
>   64806       TABLE ACCESS BY INDEX ROWID PFMQ_MESSAGESTATUS (cr=325234
> r=23150 w=0 time=224278563 us)
>   64820        INDEX RANGE SCAN XPKPF_MESSAGESTATUS (cr=260414 r=15792 w=0
> time=208616639 us)(object id 6515)
>   64820         SORT AGGREGATE (cr=129644 r=116 w=0 time=1973822 us)
>   64820          FIRST ROW  (cr=129644 r=116 w=0 time=1810738 us)
>   64820           INDEX RANGE SCAN (MIN/MAX) XPKPF_MESSAGESTATUS (cr=129644
> r=116 w=0 time=1756030 us)(object id 6515)
>   64806      INDEX UNIQUE SCAN XPKPF_MESSAGEDATA (cr=129852 r=46076 w=0
> time=632244506 us)(object id 6505)
>   64806     TABLE ACCESS BY INDEX ROWID PFMQ_MESSAGEDATASTORAGE (cr=194658
> r=92119 w=0 time=828055493 us)
>   64806      INDEX UNIQUE SCAN XPKPF_MESSAGEDATASTORAGE (cr=129852 r=46036
> w=0 time=613528422 us)(object id 6507)
>
> ***************************************************************************­*****

I might be looking in the wrong place, but I do not see evidence of row chaining.

It appears that the execution plan is using mostly high precision indexes with the exception of the AK1_PFMQ_SEQUENCENUMBER index, where 46% of the rows identified by the index are discarded. One question that you might have is whether or not using those indexes with nested loop joins is the most appropriate method, or would a couple of hash joins thrown into the execution plan produce a more efficient execution plan. The execution plan is starting with the most logical tables, given the predicates in the WHERE clause.

Let's look at a couple of items:
There were 14.56 seconds of CPU time, where the database server's CPUs were working to determine the rows to be returned to the client. Considering that the TKPROF output shows that the elapsed time was 580.31 seconds, that *probably* means that 565.75 seconds were spent doing something other than actively burning CPU cycles - such as waiting for the completion of a disk read. There were 231,750 blocks read from disk, and considering the heavy use of indexes and nested loop joins, those blocks were likely read one at a time from disk. If that is the case, the average time to read a block from disk is 0.0024412 seconds (2.4412ms), which is considered to be very fast access times for physical reads from disk. 64,806 rows were retrieved by the client in 4,321 fetch calls - indicating that the client is array fetching just 15 rows at a time. 580.31 seconds of elapsed time is about 9.7 seconds - and not roughly 30 minutes.

• See if it is possible to configure the third party application to array fetch 100 rows, rather than 15 rows at a time.
• Verify that the server is not CPU starved - that could explain the missing 20.3 minutes.
• Verify that there is not a large network latency problem.
• Verify that there is not a lot of client-side delays.

Suggestions:
* Generate the 10046 trace at level 8, rather than level 1. That will cause the wait events to be written to the trace file. If the trace file contains a large number of long duration waits on SQL*Net type wait events, check the network with a packet sniffer (Wireshark, for example) and check the client-side activity to make certain that it is not the client application that is the source of the slow performance. If you see large unexplained gaps in the tim= values in the trace file without a corresponding long wait event in between, investigate whether the server's CPUs are over-burdened. * Check the statistics on the tables and indexes to make certain that those statistics are reasonably accurate and up to date. * Review the current optimizer related initialization parameters to make certain that silly parameters are not specified. * Most of all, determine where the missing 20.3 minutes have gone.

You will find articles on my blog that will help you with the above suggestions.

Charles Hooper
Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
http://hoopercharles.wordpress.com/
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc. Received on Tue Mar 02 2010 - 19:32:23 CST