Re: [EXTERNAL] Re: Strange query behavior

Look back at how you started
Question: "why did the tablescan do no physical reads?"

Answer - because it didn't happen, because the two plans you showed are NOT the same, one of them has a filter operation that stops the rest of the plan from executing.

   "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."

• See https://jonathanlewis.wordpress.com/2007/01/09/conditional-sql/ <https://nam10.safelinks.protection.outlook.com/?url=https%3A%2F%2Fjonathanlewis.wordpress.com%2F2007%2F01%2F09%2Fconditional-sql%2F&data=04%7C01%7Camir.hameed%40sleepnumber.com%7C584c1abdb4fc4fc101b808d95e2b8b2f%7Ced8aabd514de49829fb6d6528851af5e%7C0%7C0%7C637644363378771323%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&sdata=ESQx6wthVrtAwUiEhQ%2BsUTakBk5ggQupMwiBaKIwiMQ%3D&reserved=0>

"First child first" applies for each individual query block - but that doesn't mean every operation in the query block has to execute. IF the filter operation evaluates to true then the tablescan would be the first operation to produce a rowsource.

Regards
Jonathan Lewis

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

> Thanks, Jonathan. I will check it out in your book, *Practical Oracle 8i*.
> I have a few follow-up questions though:
>
> 1. When following the *first-child-first* logic while reading this
> plan, it is my understanding that the operation on line# 4 would be
> read first where an FTS is being performed on table
> CN_COMMISSION_HEADERS_ALL. If my understanding is correct, shouldn’t the
> FILTER operation be executed at the end and, therefore, the operation on
> line# 4 should produce a row-set which would be filtered by operation on
> line# 1?
> 2. Is there a way to rewrite this query to negate the impact of
> predicate NULL IS NOT NULL?
>
>
>
> Thanks,
> Amir
>
> *From:* oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> *On
> Behalf Of *Jonathan Lewis
> *Sent:* Friday, August 13, 2021 11:57 AM
> *To:* ORACLE-L (oracle-l_at_freelists.org) <oracle-l_at_freelists.org>
> *Subject:* Re: [EXTERNAL] Re: Strange query behavior
>
>
>
> Amir,
>
>
>
> Note the "null is not null" predicate on the FILTER operation.
>
> This is how Oracle rewrites any "always false" predicate in recent times -
> so could be the 1=0 type of security predicate I suggested.
>
>
>
> If you set event 10730 (trace name context forever' you may see in the
> trace file the effect of any security predicates on your query. It's been
> at least 12 years since I last did this so the event may have changed
> purpose, though. (I think it's mentioned in Practical Oracle 8i).
>
>
>
> Regards
>
> Jonathan Lewis
>
>
>
>
>
>
>
>
>
> On Fri, 13 Aug 2021 at 15:38, Hameed, Amir <amir.hameed_at_sleepnumber.com>
> wrote:
>
> Thanks, Jonathan. Please see the output below. The Oracle EBS sometimes
> does set settings (like the ORG ID, etc) under the hood at the time of
> executing a job. I was hoping to see some evidence of that in trace files
> generated from the concurrent job run but haven’t found any yet.
>
>
>
>
>
> SQL> select * from
> table(dbms_xplan.display_cursor('651b80h255jx4',null,format=>'outline'));
>
>
>
> PLAN_TABLE_OUTPUT
>
>
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> SQL_ID 651b80h255jx4, child number 0
>
> -------------------------------------
>
> 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'
>
>
>
> Plan hash value: 141884393
>
>
>
>
> -----------------------------------------------------------------------------------------------------------
>
> | Id | Operation | Name | Rows
> | Bytes | Cost (%CPU)| Time |
>
>
> -----------------------------------------------------------------------------------------------------------
>
> | 0 | SELECT STATEMENT | |
> | | 1 (100)| |
>
> |* 1 | FILTER | |
> | | | |
>
> | 2 | NESTED LOOPS | | 1
> | 52 | 179K (5)| 00:35:51 |
>
> | 3 | NESTED LOOPS | | 2
> | 52 | 179K (5)| 00:35:51 |
>
> |* 4 | TABLE ACCESS FULL | CN_COMMISSION_HEADERS_ALL | 1
> | 23 | 179K (5)| 00:35:51 |
>
> |* 5 | INDEX RANGE SCAN | CN_COMMISSION_LINES_N10 | 2
> | | 3 (0)| 00:00:01 |
>
> |* 6 | TABLE ACCESS BY INDEX ROWID| CN_COMMISSION_LINES_ALL | 1
> | 29 | 5 (0)| 00:00:01 |
>
>
> -----------------------------------------------------------------------------------------------------------
>
>
>
> Outline Data
>
> -------------
>
>
>
> /*+
>
> BEGIN_OUTLINE_DATA
>
> IGNORE_OPTIM_EMBEDDED_HINTS
>
> OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
>
> DB_VERSION('11.2.0.4')
>
> OPT_PARAM('_b_tree_bitmap_plans' 'false')
>
> OPT_PARAM('_fast_full_scan_enabled' 'false')
>
> ALL_ROWS
>
> OUTLINE_LEAF(_at_"SEL$573A9BEE")
>
> MERGE(_at_"SEL$335DD26A")
>
> MERGE(_at_"SEL$7286615E")
>
> OUTLINE(_at_"SEL$1")
>
> OUTLINE(_at_"SEL$335DD26A")
>
> MERGE(_at_"SEL$3")
>
> OUTLINE(_at_"SEL$7286615E")
>
> MERGE(_at_"SEL$5")
>
> OUTLINE(_at_"SEL$2")
>
> OUTLINE(_at_"SEL$3")
>
> OUTLINE(_at_"SEL$4")
>
> OUTLINE(_at_"SEL$5")
>
> FULL(_at_"SEL$573A9BEE" "CN_COMMISSION_HEADERS_ALL"_at_"SEL$3")
>
> INDEX(_at_"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"_at_"SEL$5"
>
> ("CN_COMMISSION_LINES_ALL"."COMMISSION_HEADER_ID"
>
> "CN_COMMISSION_LINES_ALL"."CREDITED_SALESREP_ID"))
>
> LEADING(_at_"SEL$573A9BEE" "CN_COMMISSION_HEADERS_ALL"_at_"SEL$3"
> "CN_COMMISSION_LINES_ALL"_at_"SEL$5")
>
> USE_NL(_at_"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"_at_"SEL$5")
>
> NLJ_BATCHING(_at_"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"_at_"SEL$5")
>
> END_OUTLINE_DATA
>
> */
>
>
>
> Predicate Information (identified by operation id):
>
> ---------------------------------------------------
>
>
>
> 1 - filter(NULL IS NOT NULL)
>
> 4 - filter(("SOURCE_TRX_LINE_ID"=33025874 AND "SOURCE_TRX_ID"=5920213))
>
> 5 - access("COMMISSION_HEADER_ID"="COMMISSION_HEADER_ID" AND
> "CREDITED_SALESREP_ID"=100089722)
>
> 6 - filter(("STATUS"='CALC' AND INTERNAL_FUNCTION("QUOTA_ID")))
>
>
>
> SQL_ID 651b80h255jx4, child number 1
>
> -------------------------------------
>
> 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'
>
>
>
> Plan hash value: 141884393
>
>
>
>
> -----------------------------------------------------------------------------------------------------------
>
> | Id | Operation | Name | Rows
> | Bytes | Cost (%CPU)| Time |
>
>
> -----------------------------------------------------------------------------------------------------------
>
> | 0 | SELECT STATEMENT | |
> | | 1 (100)| |
>
> |* 1 | FILTER | |
> | | | |
>
> | 2 | NESTED LOOPS | | 1
> | 52 | 179K (5)| 00:35:51 |
>
> | 3 | NESTED LOOPS | | 2
> | 52 | 179K (5)| 00:35:51 |
>
> |* 4 | TABLE ACCESS FULL | CN_COMMISSION_HEADERS_ALL | 1
> | 23 | 179K (5)| 00:35:51 |
>
> |* 5 | INDEX RANGE SCAN | CN_COMMISSION_LINES_N10 | 2
> | | 3 (0)| 00:00:01 |
>
> |* 6 | TABLE ACCESS BY INDEX ROWID| CN_COMMISSION_LINES_ALL | 1
> | 29 | 5 (0)| 00:00:01 |
>
>
>
> PLAN_TABLE_OUTPUT
>
>
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
>
> -----------------------------------------------------------------------------------------------------------
>
>
>
> Outline Data
>
> -------------
>
>
>
> /*+
>
> BEGIN_OUTLINE_DATA
>
> IGNORE_OPTIM_EMBEDDED_HINTS
>
> OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
>
> DB_VERSION('11.2.0.4')
>
> OPT_PARAM('_b_tree_bitmap_plans' 'false')
>
> OPT_PARAM('_fast_full_scan_enabled' 'false')
>
> ALL_ROWS
>
> OUTLINE_LEAF(_at_"SEL$573A9BEE")
>
> MERGE(_at_"SEL$335DD26A")
>
> MERGE(_at_"SEL$7286615E")
>
> OUTLINE(_at_"SEL$1")
>
> OUTLINE(_at_"SEL$335DD26A")
>
> MERGE(_at_"SEL$3")
>
> OUTLINE(_at_"SEL$7286615E")
>
> MERGE(_at_"SEL$5")
>
> OUTLINE(_at_"SEL$2")
>
> OUTLINE(_at_"SEL$3")
>
> OUTLINE(_at_"SEL$4")
>
> OUTLINE(_at_"SEL$5")
>
> FULL(_at_"SEL$573A9BEE" "CN_COMMISSION_HEADERS_ALL"_at_"SEL$3")
>
> INDEX(_at_"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"_at_"SEL$5"
>
> ("CN_COMMISSION_LINES_ALL"."COMMISSION_HEADER_ID"
>
> "CN_COMMISSION_LINES_ALL"."CREDITED_SALESREP_ID"))
>
> LEADING(_at_"SEL$573A9BEE" "CN_COMMISSION_HEADERS_ALL"_at_"SEL$3"
> "CN_COMMISSION_LINES_ALL"_at_"SEL$5")
>
> USE_NL(_at_"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"_at_"SEL$5")
>
> NLJ_BATCHING(_at_"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"_at_"SEL$5")
>
> END_OUTLINE_DATA
>
> */
>
>
>
> Predicate Information (identified by operation id):
>
> ---------------------------------------------------
>
>
>
> 1 - filter(NULL IS NOT NULL)
>
> 4 - filter(("SOURCE_TRX_LINE_ID"=33025874 AND "SOURCE_TRX_ID"=5920213))
>
> 5 - access("COMMISSION_HEADER_ID"="COMMISSION_HEADER_ID" AND
> "CREDITED_SALESREP_ID"=100089722)
>
> 6 - filter(("STATUS"='CALC' AND INTERNAL_FUNCTION("QUOTA_ID")))
>
>
>
>
>
> 130 rows selected.
>
>
>
> *From:* oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> *On
> Behalf Of *Jonathan Lewis
> *Sent:* Friday, August 13, 2021 3:25 AM
> *To:* ORACLE-L (oracle-l_at_freelists.org) <oracle-l_at_freelists.org>
> *Subject:* [EXTERNAL] Re: Strange query behavior
>
>
>
> *CAUTION**: External source*
>
>
>
>
>
> 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/
> <https://nam10.safelinks.protection.outlook.com/?url=https%3A%2F%2Fjonathanlewis.wordpress.com%2F2007%2F01%2F09%2Fconditional-sql%2F&data=04%7C01%7Camir.hameed%40sleepnumber.com%7C5afe365466454e12aff408d95e7308a4%7Ced8aabd514de49829fb6d6528851af5e%7C0%7C0%7C637644670444158014%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&sdata=T%2FyoXOHll8cbdy6BAY9uJdaBHgeGG2TIU%2F0nsg8fGr0%3D&reserved=0>
>
>
>
> 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