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@xxxxxxxxxxxxxxx>
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@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> *On
Behalf Of *Jonathan Lewis
*Sent:* Friday, August 13, 2021 11:57 AM
*To:* ORACLE-L (oracle-l@xxxxxxxxxxxxx) <oracle-l@xxxxxxxxxxxxx>
*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@xxxxxxxxxxxxxxx>
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(@"SEL$573A9BEE")
MERGE(@"SEL$335DD26A")
MERGE(@"SEL$7286615E")
OUTLINE(@"SEL$1")
OUTLINE(@"SEL$335DD26A")
MERGE(@"SEL$3")
OUTLINE(@"SEL$7286615E")
MERGE(@"SEL$5")
OUTLINE(@"SEL$2")
OUTLINE(@"SEL$3")
OUTLINE(@"SEL$4")
OUTLINE(@"SEL$5")
FULL(@"SEL$573A9BEE" "CN_COMMISSION_HEADERS_ALL"@"SEL$3")
INDEX(@"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"@"SEL$5"
("CN_COMMISSION_LINES_ALL"."COMMISSION_HEADER_ID"
"CN_COMMISSION_LINES_ALL"."CREDITED_SALESREP_ID"))
LEADING(@"SEL$573A9BEE" "CN_COMMISSION_HEADERS_ALL"@"SEL$3"
"CN_COMMISSION_LINES_ALL"@"SEL$5")
USE_NL(@"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"@"SEL$5")
NLJ_BATCHING(@"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"@"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(@"SEL$573A9BEE")
MERGE(@"SEL$335DD26A")
MERGE(@"SEL$7286615E")
OUTLINE(@"SEL$1")
OUTLINE(@"SEL$335DD26A")
MERGE(@"SEL$3")
OUTLINE(@"SEL$7286615E")
MERGE(@"SEL$5")
OUTLINE(@"SEL$2")
OUTLINE(@"SEL$3")
OUTLINE(@"SEL$4")
OUTLINE(@"SEL$5")
FULL(@"SEL$573A9BEE" "CN_COMMISSION_HEADERS_ALL"@"SEL$3")
INDEX(@"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"@"SEL$5"
("CN_COMMISSION_LINES_ALL"."COMMISSION_HEADER_ID"
"CN_COMMISSION_LINES_ALL"."CREDITED_SALESREP_ID"))
LEADING(@"SEL$573A9BEE" "CN_COMMISSION_HEADERS_ALL"@"SEL$3"
"CN_COMMISSION_LINES_ALL"@"SEL$5")
USE_NL(@"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"@"SEL$5")
NLJ_BATCHING(@"SEL$573A9BEE" "CN_COMMISSION_LINES_ALL"@"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@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> *On
Behalf Of *Jonathan Lewis
*Sent:* Friday, August 13, 2021 3:25 AM
*To:* ORACLE-L (oracle-l@xxxxxxxxxxxxx) <oracle-l@xxxxxxxxxxxxx>
*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@xxxxxxxxxxxxxxx>
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
