Re: Strange query behavior

Re-run your test (if necessary) then

select * from table(dbms_xplan.display_cursor('{the sql id from the trace file}',null,format=>'outline'));

You've got a FILTER operation at the start of the plan, and it looks like it's a "conditional SQL"*** filter that results in Oracle not executing the rest of the plan.
The obvious guess for this is that you've got a security predicate being generated for this query which ensures that only the correct users can see the data. Using dbms_xplan.display_cursor we'll see all the predicates, and the predicate on the FILTER operation may be something as simple as "1=0".

• See https://jonathanlewis.wordpress.com/2007/01/09/conditional-sql/

Regards
Jonathan Lewis

On Fri, 13 Aug 2021 at 04:17, Hameed, Amir <amir.hameed_at_sleepnumber.com> wrote:

> Hi,
>
> The database is a three-node 11.2.0.4 RAC and the OS is Solaris 11. This
> is an Oracle EBS applications environment and the code in question is
> standard Oracle code. We ran a concurrent job with tracing enabled as part
> of troubleshooting performance issues with that job. The query in question
> looks pretty bad because of the way it ran:
>
>
>
> SELECT DECODE(NVL(CCH.TRANSACTION_AMOUNT, 0),0, CCL.COMMISSION_RATE,
>
> ROUND(CCL.COMMISSION_AMOUNT/CCH.TRANSACTION_AMOUNT, 7))
>
> FROM
>
> CN_COMMISSION_HEADERS CCH, CN_COMMISSION_LINES CCL WHERE
>
> CCH.COMMISSION_HEADER_ID = CCL.COMMISSION_HEADER_ID AND
> CCH.SOURCE_TRX_ID =
>
> :B12 AND CCH.SOURCE_TRX_LINE_ID = :B11 AND CCL.CREDITED_SALESREP_ID =
> :B10
>
> AND CCL.QUOTA_ID IN (:B9 ,:B8 ,:B7 ,:B6 ,:B5 ,:B4 ,:B3 ,:B2 ) AND
>
> CCL.STATUS = :B1
>
>
>
>
>
> call count cpu elapsed disk query
> current rows
>
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
>
> Parse 11 0.00 0.00 0 0
> 0 0
>
> Execute 3832 0.13 0.13 0 0
> 0 0
>
> Fetch 3832 78354.13 137942.64 2415515000 2418912980
> 0 3793
>
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
>
> total 7675 78354.27 137942.78 2415515000 2418912980
> 0 3793
>
>
>
> Rows (1st) Rows (avg) Rows (max) Row Source Operation
>
> ---------- ---------- ----------
> ---------------------------------------------------
>
> 1 1 1 NESTED LOOPS (cr=631072 pr=630185 pw=0
> time=704520 us cost=179182 size=58 card=1)
>
> 3 2 10 NESTED LOOPS (cr=630896 pr=630016 pw=0
> time=125749 us cost=179182 size=58 card=2)
>
> 1 1 5 TABLE ACCESS FULL
> CN_COMMISSION_HEADERS_ALL (cr=630892 pr=630015 pw=0 time=618482 us
> cost=179177 size=26 card=1)
>
> 3 2 10 INDEX RANGE SCAN
> CN_COMMISSION_LINES_N10 (cr=4 pr=0 pw=0 time=4556 us cost=3 size=0
> card=2)(object id 384194)
>
> 1 1 1 TABLE ACCESS BY INDEX ROWID
> CN_COMMISSION_LINES_ALL (cr=7 pr=1 pw=0 time=9561 us cost=5 size=32 card=1)
>
>
>
>
>
> Elapsed times include waiting on following events:
>
> Event waited on Times Max. Wait Total
> Waited
>
> ---------------------------------------- Waited ----------
> ------------
>
> library cache lock 1 0.00
> 0.00
>
> library cache pin 1 0.00
> 0.00
>
> db file sequential read 6136 0.08
> 52.33
>
> enq: KO - fast object checkpoint 9900 0.31
> 15.96
>
> reliable message 3832 0.55
> 12.97
>
> direct path read 93230079 0.12
> 61862.37
>
> Disk file operations I/O 776 0.04
> 1.03
>
> latch: cache buffers chains 1 0.00
> 0.00
>
> read by other session 173 0.01
> 1.16
>
> gc cr grant 2-way 1836 0.00
> 0.73
>
> KJC: Wait for msg sends to complete 43 0.00
> 0.00
>
> latch free 14 0.00
> 0.00
>
> gc buffer busy acquire 2 0.00
> 0.00
>
> kfk: async disk IO 1 0.00
> 0.00
>
> gc current grant 2-way 1 0.00
> 0.00
>
>
> ********************************************************************************
>
>
>
>
>
> I pulled variables of this statement from V$SQL_BIND_CAPTURE, defined them
> in a script, and manually ran the statement with event 10046 at level 8:
>
>
>
> SELECT DECODE(NVL(CCH.TRANSACTION_AMOUNT, 0),0, CCL.COMMISSION_RATE,
>
> ROUND(CCL.COMMISSION_AMOUNT/CCH.TRANSACTION_AMOUNT, 7))
>
> FROM
>
> CN_COMMISSION_HEADERS CCH, CN_COMMISSION_LINES CCL WHERE
>
> CCH.COMMISSION_HEADER_ID = CCL.COMMISSION_HEADER_ID AND
> CCH.SOURCE_TRX_ID =
>
> 5920213 AND CCH.SOURCE_TRX_LINE_ID = 33025874 AND
> CCL.CREDITED_SALESREP_ID = 100089722
>
> AND CCL.QUOTA_ID IN (1441 ,1587 ,1461 ,1588 ,1481 ,1592 ,1201 ,1593 ) AND
>
> CCL.STATUS = 'CALC'
>
>
>
> call count cpu elapsed disk query
> current rows
>
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
>
> Parse 1 0.14 0.15 0 0
> 0 0
>
> Execute 1 0.00 0.00 0 0
> 0 0
>
> Fetch 1 0.00 0.00 0 0
> 0 0
>
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
>
> total 3 0.14 0.15 0 0
> 0 0
>
>
>
> Rows (1st) Rows (avg) Rows (max) Row Source Operation
>
> ---------- ---------- ----------
> ---------------------------------------------------
>
> 0 0 0 FILTER (cr=0 pr=0 pw=0 time=1 us)
>
> 0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us
> cost=179182 size=52 card=1)
>
> 0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0
> us cost=179182 size=52 card=2)
>
> 0 0 0 TABLE ACCESS FULL
> CN_COMMISSION_HEADERS_ALL (cr=0 pr=0 pw=0 time=0 us cost=179177 size=23
> card=1)
>
> 0 0 0 INDEX RANGE SCAN
> CN_COMMISSION_LINES_N10 (cr=0 pr=0 pw=0 time=0 us cost=3 size=0
> card=2)(object id 384194)
>
> 0 0 0 TABLE ACCESS BY INDEX ROWID
> CN_COMMISSION_LINES_ALL (cr=0 pr=0 pw=0 time=0 us cost=5 size=29 card=1)
>
>
>
> The statement ran very quickly. The two plans look the same. The one
> difference is that in the second plan, FTS on table
> CN_COMMISSION_HEADERS_ALL performed zero physical reads (pr=0) which is
> baffling because the table has over 10M rows. In the first plan, FTS was
> done using DIRECT PATH READS and therefore, the data couldn’t possibly have
> been cached in the Buffer Cache. I flushed the Buffer Cache just to see if
> that would make any difference but it didn’t, as expected.
>
>
>
> I am trying to understand when the statement was run manually and it did
> do FTS of the table, why there were no physical reads reported.
>
>
>
> Thanks,
>
> Amir
>
>
>

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