Re: performance issue after upgrade to oracle 11.2.0.1 linux 32 bit
Date: Sun, 22 Nov 2009 08:22:02 -0800 (PST)
Message-ID: <1628e614-9ed7-4820-9ed7-16c905d4720c_at_x16g2000vbk.googlegroups.com>
On Nov 22, 7:46 am, lsllcm <lsl..._at_gmail.com> wrote:
> Hi All, > > I have put both 10053 trace for both execution plan as below url, > could you help have a look? > > http://docs.google.com/View?id=ddqzpk2x_4cmpn7tfv > http://docs.google.com/View?id=ddqzpk2x_5db7q59fw > > Thanks > lsllcm
Thanks for posting all of the information. I looked at the 10053
trace files. The one identifying characteristic of the fast executing
SQL statement is the almost immediate substitution of the original SQL
statement with a hinted version of the SQL statement. This is from
the 10053 trace for the fast execution:
JE: Considering Join Elimination on query block SEL$1 (#0)
Join Elimination (JE)
SQL:******* UNPARSED QUERY IS *******
SELECT /*+ OPT_ESTIMATE (GROUP_BY ROWS=4.000000 ) OPT_ESTIMATE (TABLE
"F" MIN=27.000000 ) OPT_ESTIMATE (INDEX_SCAN "F" "F4FEEITEM_PK"
MIN=27.000000 ) OPT_ESTIMATE (INDEX_FILTER "F" "F4FEEITEM_PK" MIN=27.000000 ) OPT_ESTIMATE (TABLE "X" MIN=13.000000 ) OPT_ESTIMATE (INDEX_SCAN "X" "X4PAYMENT_FEEITEM_PK" MIN=13.000000 ) OPT_ESTIMATE (INDEX_FILTER "X" "X4PAYMENT_FEEITEM_PK" MIN=13.000000 ) */
"X"."SERV_PROV_CODE" "SERV_PROV_CODE","X"."B1_PER_ID1"
"B1_PER_ID1","X"."B1_PER_ID2" "B1_PER_ID2","X"."B1_PER_ID3"
"B1_PER_ID3",SUM(NVL("X"."FEE_ALLOCATION",0)) "GF_FEE" FROM
"test"."SETDETAILS" "S","test"."X4PAYMENT_FEEITEM"
"X","test"."F4FEEITEM" "F" WHERE "S"."SERV_PROV_CODE"='SACRAMENTO' AND
"S"."SET_ID"='CONNIE' AND "S"."REC_STATUS"='A' AND
"S"."SERV_PROV_CODE"="X"."SERV_PROV_CODE" AND
"F"."SERV_PROV_CODE"="S"."SERV_PROV_CODE" AND
"S"."B1_PER_ID1"="X"."B1_PER_ID1" AND
"S"."B1_PER_ID2"="X"."B1_PER_ID2" AND
"S"."B1_PER_ID3"="X"."B1_PER_ID3" AND
"F"."B1_PER_ID1"="S"."B1_PER_ID1" AND
"F"."B1_PER_ID2"="S"."B1_PER_ID2" AND
"F"."B1_PER_ID3"="S"."B1_PER_ID3" AND
"F"."FEEITEM_SEQ_NBR"="X"."FEEITEM_SEQ_NBR" AND
"S"."REC_STATUS"="X"."REC_STATUS" AND
"F"."REC_STATUS"="X"."REC_STATUS" AND
("X"."PAYMENT_FEEITEM_STATUS"<>'VOIDED' OR
"X"."PAYMENT_FEEITEM_STATUS" IS NULL) GROUP BY
"X"."SERV_PROV_CODE","X"."B1_PER_ID1","X"."B1_PER_ID2","X"."B1_PER_ID3"
JE: cfro: SETDETAILS objn:652770 col#:1 dfro:F4FEEITEM dcol#:1 JE: cfro: SETDETAILS objn:74851 col#:1 dfro:X4PAYMENT_FEEITEM dcol#: 1
This is the same section from the slow execution: JE: Considering Join Elimination on query block SEL$1 (#0)
Join Elimination (JE)
SQL:******* UNPARSED QUERY IS *******
SELECT "X"."SERV_PROV_CODE" "SERV_PROV_CODE","X"."B1_PER_ID1"
"B1_PER_ID1","X"."B1_PER_ID2" "B1_PER_ID2","X"."B1_PER_ID3"
"B1_PER_ID3",SUM(NVL("X"."FEE_ALLOCATION",0)) "GF_FEE" FROM
"test"."SETDETAILS" "S","test"."X4PAYMENT_FEEITEM"
"X","test"."F4FEEITEM" "F" WHERE "S"."SERV_PROV_CODE"='SACRAMENTO' AND
"S"."SET_ID"='CONNIE' AND "S"."REC_STATUS"='A' AND
"S"."SERV_PROV_CODE"="X"."SERV_PROV_CODE" AND
"F"."SERV_PROV_CODE"="S"."SERV_PROV_CODE" AND
"S"."B1_PER_ID1"="X"."B1_PER_ID1" AND
"S"."B1_PER_ID2"="X"."B1_PER_ID2" AND
"S"."B1_PER_ID3"="X"."B1_PER_ID3" AND
"F"."B1_PER_ID1"="X"."B1_PER_ID1" AND
"F"."B1_PER_ID2"="X"."B1_PER_ID2" AND
"F"."B1_PER_ID3"="X"."B1_PER_ID3" AND
"F"."FEEITEM_SEQ_NBR"="X"."FEEITEM_SEQ_NBR" AND
"S"."REC_STATUS"="X"."REC_STATUS" AND
"F"."REC_STATUS"="X"."REC_STATUS" AND
("X"."PAYMENT_FEEITEM_STATUS"<>'VOIDED' OR
"X"."PAYMENT_FEEITEM_STATUS" IS NULL) GROUP BY
"X"."SERV_PROV_CODE","X"."B1_PER_ID1","X"."B1_PER_ID2","X"."B1_PER_ID3"
JE: cfro: SETDETAILS objn:652770 col#:1 dfro:F4FEEITEM dcol#:1 JE: cfro: SETDETAILS objn:74851 col#:1 dfro:X4PAYMENT_FEEITEM dcol#: 1
*Something* is triggering the SQL statement replacement early in the 10053 trace, but I am not able to determine the source of the change. DBA_SQL_PROFILES should show SQL profiles for the SQL statement - I can't explain why you do not see any rows when querying that view. SQL plan baselines, I believe, are another possibility (looking back at Randolf's post, he has already mentioned this).
From:
http://download.oracle.com/docs/cd/E11882_01/server.112/e10821/optplanmgmt.htm
"In Oracle Database 11g, an automatically configured task runs the SQL
Tuning Advisor during a maintenance window. This automatic SQL tuning
task targets high-load SQL statements as identified by the execution
performance data collected in the Automatic Workload Repository (AWR)
snapshots. The automatic SQL tuning task implements the SQL profile
recommendations made by the SQL tuning advisor. Thus, the database
automatically adds tuned plans to the SQL plan baselines of the
identified high-load SQL statements."
The above quote seems to indicate that the database attempts to automatically "fix" itself when it finds a slow executing SQL statement...
An explanation of SQL plan baselines from the book "Troubleshooting
Oracle Performance":
http://books.google.com/books?id=b3DIkYO2gBQC&pg=PA291#v=onepage&q=&f=false
Parts 1-3 (of 4) about SQL plan baselines from the Oracle development
group:
http://optimizermagic.blogspot.com/2009_01_01_archive.html
The above web page shows the following SQL statement to check for SQL
plan baselines:
select sql_text, plan_name, enabled, accepted from
dba_sql_plan_baselines;
Randolf's suggestion to display the actual number of rows to the
estimated cardinalities was a good suggestion. The fast executing
plan includes the following:
| E-Rows | A-Rows | A-Time |
------------------------------- | | 4 |00:00:00.02 | | 60951 | 4 |00:00:00.02 | | | 13 |00:00:00.01 | | 60951 | 13 |00:00:00.01 | | 129 | 27 |00:00:00.01 | | 24 | 12 |00:00:00.01 | | 24 | 12 |00:00:00.01 | | 5 | 27 |00:00:00.01 | | 1 | 27 |00:00:00.01 | | 1 | 13 |00:00:00.01 | | 473 | 13 |00:00:00.01 | -------------------------------
The slow executing plan includes the following: | E-Rows | A-Rows | A-Time |
------------------------------- | | 4 |00:00:13.27 | | 1 | 4 |00:00:13.27 | | 91293 | 13 |00:00:13.98 | | | 28 |00:00:00.01 | | 95522 | 44 |00:00:00.01 | | 24 | 12 |00:00:00.01 | | 24 | 12 |00:00:00.01 | | 1 | 44 |00:00:00.01 | | 3907 | 28 |00:00:00.01 |
| 1173K| 1174K|00:00:10.84 |
-------------------------------
Except for the full table scan operation (the last operation in the slow plan), the actual number of rows returned is significantly less than the estimated number of rows. That probably explains why the slow plan uses a full table scan on a 1.17 million row table rather than an index range scan to return the 27 rows from that table.
The only suggestion that I have at this time is to check dba_sql_plan_baselines. You could use a series of hints to prevent the full table scan of F4FEEITEM, and to prevent the hash join operation, but I suspect that this is not a path you would want to take.
Jonathan Lewis and Randolf have both spent much more time working with 10053 trace files than I have - one of them might know of another event number that should be enabled with a 10053 trace to explain why the SQL statement in the fast execution was replaced immediately. I suspect that other contributors to this group would also have ideas to explain the substitution.
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
Received on Sun Nov 22 2009 - 10:22:02 CST