Strange query behavior
Date: Fri, 13 Aug 2021 03:17:25 +0000
Message-ID: <CH0PR14MB50127A09F85682B011F0519EE0FA9_at_CH0PR14MB5012.namprd14.prod.outlook.com>
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
Received on Fri Aug 13 2021 - 05:17:25 CEST