You can find pdf version of the presentation here: Performance tuning – for developers . Feel free to ask questions in the comments.
Thank you Mary Elizabeth Mcneely for the opportunity to talk in the Dallas Oracle User Group technology meetup.
Archive for the ‘CBO’ Category
DOUG 2010 Presentation
Posted by Riyaj Shamsudeen on October 6, 2010
Posted in CBO, EBS11i, Performance tuning, Presentations | Tagged: CBO, oracle performance, sql tracing, statitics_level | 2 Comments »
Group by Hash aggregation
Posted by Riyaj Shamsudeen on September 30, 2010
So, Here I was merrily enjoying OpenWorld 2010 presentations in SFO, I got a call from a client about a performance issue. Client recently upgraded from Version 9i to Version 10g in an E-Business environment. I had the privilege of consulting before the upgrade, so we setup the environment optimally, and upgrade itself was seamless. Client did not see much regression except One query: That query was running for hours in 10g compared to 15 minutes in 9i.
Review and Analysis
Reviewed the execution plan in the development database and I did not see any issues with the plan. Execution plan in development and production looked decent enough. I wasn’t able to reproduce the issue in the development database either. So, the client allowed me to trace the SQL statement in the production database. Since the size of data in few tables is different between production and development databases, we had to analyze the problem in production environment.
I had to collect as much data possible as the tracing was a one-time thing. I setup a small script to get process stack and process memory area of that Unix dedicated server process to collect more details, in addition to tracing the process with waits => true.
Execution plan from the production database printed below. [ Review the execution plan carefully, it is giving away the problem immediately.] One execution of this statement took 13,445 seconds and almost all of it spent in the CPU time. Why would the process consume 13,719 seconds of CPU time?. Same process completed in just 15 minutes in 9i, as confirmed by Statspack reports. [ As a side note, We collected enormous amount of performance data in 9i in the Production environment before upgrading to 10g, just so that we can quickly resolve any performance issues, and you should probably follow that guideline too]. That collection came handy and It is clear that SQL statement was completing in 15 minutes in 9i and took nearly 3.75 hours after upgrading the database to version 10g.
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 10 13719.71 13445.94 27 5086407 0 99938
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 13719.71 13445.94 27 5086407 0 99938
24 HASH GROUP BY (cr=4904031 pr=27 pw=0 time=13240600266 us)
24 NESTED LOOPS OUTER (cr=4904031 pr=27 pw=0 time=136204709 us)
24 NESTED LOOPS (cr=4903935 pr=27 pw=0 time=133347961 us)
489983 NESTED LOOPS (cr=3432044 pr=27 pw=0 time=104239982 us)
489983 NESTED LOOPS (cr=2452078 pr=27 pw=0 time=91156653 us)
489983 TABLE ACCESS BY INDEX ROWID HR_LOCATIONS_ALL (cr=1472112 pr=27 pw=0 time=70907109 us)
489983 INDEX RANGE SCAN HR_LOCATIONS_UK2 (cr=981232 pr=0 pw=0 time=54338789 us)(object id 43397)
489983 INDEX UNIQUE SCAN MTL_PARAMETERS_U1 (cr=979966 pr=0 pw=0 time=17972426 us)(object id 37657)
489983 INDEX UNIQUE SCAN HR_ORGANIZATION_UNITS_PK (cr=979966 pr=0 pw=0 time=10876601 us)(object id 43498)
24 INDEX RANGE SCAN UXPP_FA_LOCATIONS_N3 (cr=1471891 pr=0 pw=0 time=27325172 us)(object id 316461)
24 TABLE ACCESS BY INDEX ROWID PER_ALL_PEOPLE_F (cr=96 pr=0 pw=0 time=2191 us)
24 INDEX RANGE SCAN PER_PEOPLE_F_PK (cr=72 pr=0 pw=0 time=1543 us)(object id 44403)
pstack, pmap, and truss
Reviewing pstack output generated from the script shows many function calls kghfrempty, kghfrempty_ex, qerghFreeHashTable etc, implying hash table operations. Something to do with hash table consuming time?
( Only partial entries shown ) 0000000103f41528 kghfrempty 0000000103f466ec kghfrempty_ex 0000000103191f1c qerghFreeHashTable 000000010318e080 qerghFetch 00000001030b1b3c qerstFetch ... 0000000103f41558 kghfrempty 0000000103f466ec kghfrempty_ex 0000000103191f1c qerghFreeHashTable 000000010318e080 qerghFetch 00000001030b1b3c qerstFetch
Truss of the process also showed quite a bit of mmap calls. So, the process is allocating more memory to an hash table?
... mmap(0xFFFFFFFF231C0000, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 7, 0) = 0xFFFFFFFF231C0000 ... pollsys(0xFFFFFFFF7FFF7EC8, 1, 0xFFFFFFFF7FFF7E00, 0x00000000) = 0 mmap(0xFFFFFFFF231D0000, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 7, 0) = 0xFFFFFFFF231D0000 ...
Execution plan again ..
Reviewing the execution plan again showed an interesting issue. I am going to post only two relevant lines from the execution plan below. As you can see that elapsed time at NESTED LOOPS OUTER step is 136 seconds. But the elapsed time at the next HASH GROUP BY step is 13240 seconds, meaning nearly 13,100 seconds spent in the HASH GROUP BY Step alone! Why would the process spend 13,100 seconds in a group by operation? Actual SQL execution took only 136 seconds, but the group by operation took 13,100 seconds. That doesn’t make sense, Does it?
24 HASH GROUP BY (cr=4904031 pr=27 pw=0 time=13240600266 us)
24 NESTED LOOPS OUTER (cr=4904031 pr=27 pw=0 time=136204709 us)
...
OFE = 9i
Knowing that time is spent in the Group by operation and that the 10g new feature Hash Grouping method is in use, I decided to test this SQL statement execution with 9i optimizer. The SQL completed in 908 seconds with OFE(optimizer_features_enabled) set to 9.2.0.8 (data is little bit different since production is an active environment). You can also see that SORT technique is used to group the data.
alter session set optimizer_features_enabled=9.2.0.8;
Explain plan :
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 106985 887.41 908.25 282379 3344916 158 1604754
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 106987 887.41 908.25 282379 3344916 158 1604754
4 SORT GROUP BY (cr=2863428 pr=0 pw=0 time=37934456 us)
4 NESTED LOOPS OUTER (cr=2863428 pr=0 pw=0 time=34902519 us)
4 NESTED LOOPS (cr=2863412 pr=0 pw=0 time=34198726 us)
286067 NESTED LOOPS (cr=2003916 pr=0 pw=0 time=24285794 us)
286067 NESTED LOOPS (cr=1431782 pr=0 pw=0 time=19288024 us)
286067 TABLE ACCESS BY INDEX ROWID HR_LOCATIONS_ALL (cr=859648 pr=0 pw=0 time=13568456 us)
286067 INDEX RANGE SCAN HR_LOCATIONS_UK2 (cr=572969 pr=0 pw=0 time=9271380 us)(object id 43397)
286067 INDEX UNIQUE SCAN MTL_PARAMETERS_U1 (cr=572134 pr=0 pw=0 time=4663154 us)(object id 37657)
...
Knowing the problem is in the GROUP BY step, we setup a profile with _gby_hash_aggregation_enabled set to FALSE, disabling the new 10g feature for that SQL statement. With the SQL profile, performance of the SQL statement is comparable to pre-upgrade timing.
This almost sounds like a bug! Bug 8223928 is matching with this stack, but it is the opposite. Well, client will work with the support to get a bug fix for this issue.
Summary
In summary, you can use scientific methods to debug performance issues. Revealing the details underneath, will enable you to come up with a workaround quickly, leading to a faster resolution.
Note that, I am not saying hash group by feature is bad. Rather, we seem to have encountered an unfortunate bug which caused performance issues at this client. I think, Hash Grouping is a good feature as the efficiency of grouping operations can be improved if you have ample amount of memory. That’s the reason why we disabled this feature at the statement level, NOT at the instance level.
This blog in a traditional format hash_group_by_orainternals
Update 1:
I am adding a script to capture pmap and pstack output in a loop for 1000 times, with 10 seconds interval. Tested in Oracle Solaris.
#! /bin/ksh
pid=$1
(( cnt=1000 ))
while [[ $cnt -gt 0 ]];
do
date
pmap -x $pid
pstack $pid
echo $cnt
(( cnt=cnt-1 ))
sleep 10
done
To call the script: assuming 7887 is the UNIX pid of the process.
nohup ./pmap_loop.ksh 7887 >> /tmp/a1.lst 2>>/tmp/a1.lst &
Syntax for the truss command is given below. Please remember, you can’t use pmap, pstack and truss concurrently. These commands stops the process (however short that may be!) and inspects them, so use these commands sparingly. [ I had a client who used to run truss on LGWR process on a continuous(!) basis and database used to crash randomly!]. I realize that pmap/pstack/truss can be scripted to work together, but that would involve submitting a background process for the truss command and killing that process after a small timeout window. That would be a risky approach in a Production environment and So, I prefer to use truss command manually and CTRL+C it after few seconds.
truss -d -E -o /tmp/truss.lst -p 7887
I can not stress enough, not to overuse these commands in a Production environment. Command strace( Linux), tusc (HP) are comparable commands of truss(Solaris).
Posted in CBO, EBS11i, Oracle database internals, Performance tuning | Tagged: optimizer_features_enabled, oracle performance, pmap, pstack, truss, _gby_hash_aggregation_enabled | 8 Comments »
Query transformation – Part 1
Posted by Riyaj Shamsudeen on May 1, 2010
Query transformation is a set of techniques used by the optimizer to rewrite a query and optimizer it better. Few optimization paths open up to the optimizer after query transformation. Some query transformations must be costed to be chosen and some do not need to be costed. For example, if a table can be eliminated completely from the join, then that transformation is applied and need to cost that transformation is minimal.
Test case
We will use the following test case to illustrate the concepts behind Query transformation. Some of the optimizations that we see here works from version 11gR1 onwards and so, these test cases might not work in the versions 10g and below.
create table backup.t1 (n1 number not null primary key, n2 number not null, n3 varchar2(256) ); insert into backup.t1 select n1, n1, lpad ( n1, 250,'x') from (select level n1 from dual connect by level <=100); create table backup.t2 (n1 number not null primary key , n2 number not null, n3 varchar2(256) ); alter table backup.t1 add constrainT t1_fk foreign key (n2) references backup.t2(n1) insert into backup.t2 select n1, n1, lpad ( n1, 250,'x') from (select level n1 from dual connect by level <=100); insert into backup.t1 select n1, n1, lpad ( n1, 250,'x') from (select level n1 from dual connect by level <=100);
Join elimination (JE)
JE is a technique in which one or more tables can be eliminated from the execution plan without altering functional behavior. In the listing 1-1, query selects columns from the table t1 only, but there exists a join predicate between t1 and t2 in that query. Further, no columns are selected from table t2 in this query and join to t2 simply serves as to verify the existence of foreign key values. Enabled Foreign key constraint between these two tables establishes the existence check already and so, there is no need for explicit existence check in the query also. Join to table t2 can be eliminated by the optimizer safely.
select /*+ gather_plan_statistics */ t1.* from t1, t2 where t1.n2 = t2.n1;
select * from table(dbms_xplan.display_cursor('','','allstats last'))
------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers |
------------------------------------------------------------------------------------
| 1 | TABLE ACCESS FULL| T1 | 1 | 82 | 100 |00:00:00.01 | 13 |
-----------------------------------------------------------------------------------
Listing 1-1 :JE example case 1
As you see from the listing 1-1, Table T2 is removed from the execution plan. Since there is a valid foreign key constraint, optimizer eliminated the join condition to that table t2.
Let’s also discuss another Join Elimination test case. In the Listing 1-2, predicate is “t1.n2 not in (select t2.n1 from t2)”. As the enabled foreign key constraint dictates that this predicate will always be false and no rows will be returned. Optimizer promptly identified this condition and added a filter predicate in the step 1 with “NULL is NOT NULL” as a predicate. Step 1 is executed before step 2; Step 2 is never executed as the value of Starts column is zero in the execution plan.
SQL_ID d09kmzum9wgta, child number 0 ------------------------------------- select /*+ gather_plan_statistics */ t1.* from t1 where t1.n2 not in (select t2.n1 from t2 ) Plan hash value: 3332582666 --------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | --------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 0 |00:00:00.01 | |* 1 | FILTER | | 1 | | 0 |00:00:00.01 | | 2 | TABLE ACCESS FULL| T1 | 0 | 100 | 0 |00:00:00.01 | --------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(NULL IS NOT NULL) Listing 1-2 :JE example case 2
Listing 1-3 provides another variation of JE.
select /*+ gather_plan_statistics */ t1.* from t1 where t1.n2 in (select t2.n1 from t2 ) Plan hash value: 3617692013 ------------------------------------------------------------------------------------ | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ------------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | 1 | | 100 |00:00:00.01 | 14 | | 1 | TABLE ACCESS FULL| T1 | 1 | 100 | 100 |00:00:00.01 | 14 | ------------------------------------------------------------------------------------ Listing 1-3 :JE example case 2
Following output shows the trace lines from the 10053 trace file.
JE: Considering Join Elimination on query block SEL$5DA710D3 (#1)
*************************
Join Elimination (JE)
*************************
JE: cfro: T1 objn:74684 col#:2 dfro:T2 dcol#:2
JE: cfro: T1 objn:74684 col#:2 dfro:T2 dcol#:2
Query block (0E0D43D0) before join elimination:
SQL:******* UNPARSED QUERY IS *******
SELECT “T1”.”N1″ “N1″,”T1”.”N2″ “N2″,”T1”.”N3″ “N3” FROM “CBO3”.”T2″ “T2″,”CBO3”.”T1″ “T1” WHERE “T1″.”N2″=”T2”.”N1″
JE: eliminate table: T2
Registered qb: SEL$14EF7918 0xe0d43d0 (JOIN REMOVED FROM QUERY BLOCK SEL$5DA710D3; SEL$5DA710D3; “T2″@”SEL$2”)
Filter Predicate(s) Generation from constraints
Various filter predicates are generated and added to the execution plan using enabled and validated constraints (check, not null constraints).
In the Listing 1-4, columns n1 and n2 has enabled valid NOT NULL constraints that precludes null values in the columns n1 and n2. Query in the listing 1-4 has predicate “n1 is null or n2 is null” which can never be true. This fact is used by the optimizer to improve the execution plan. Filter predicate (NULL IS NOT NULL) is added in step 1 which will be FALSE. So, Step 2 is never executed as the value of Starts column is 0 in the execution plan. This means that step (2) in the execution plan was never executed and table T1 was never accessed.
select /*+ gather_plan_statistics */ * from t1 where n1 is null or n2 is null;
select * from table(dbms_xplan.display_cursor('','','allstats last'));
---------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time |
---------------------------------------------------------------------------
|* 1 | FILTER | | 1 | | 0 |00:00:00.01 |
| 2 | TABLE ACCESS FULL| T1 | 0 | 100 | 0 |00:00:00.01 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(NULL IS NOT NULL)
Listing 1-4: Filter predicate generation from NOT NULL constraint.
Let’s add a check constraint to this column to explain this further. In the listing 1-5 a check constraint is added which specifies that “n1 200 and generated predicate n1<200 will nullify each other leading to an always FALSE condition. Optimizer identified this condition and added a filter predicate in step 1: NULL IS NOT NULL.
alter table t1 add constraint t1_n1_lt_150 check (n1 200;
select * from table(dbms_xplan.display_cursor('','','allstats last'));
---------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time |
---------------------------------------------------------------------------
|* 1 | FILTER | | 1 | | 0 |00:00:00.01 |
|* 2 | TABLE ACCESS FULL| T1 | 0 | 20 | 0 |00:00:00.01 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(NULL IS NOT NULL)
2 - filter("N1">200)
Listing 1-5:Filter predicate generation from a check constraint
Following lines from the trace file generated from event 10053 shows that a predicate n1<200 is added; This auto-generated predicate and existing predicate canceled each other leading to an eternally FALSE condition.
kkogcp: try to generate transitive predicate from check constraints for SEL$5DA710D3 (#0)
constraint: “T1”.”N1″<200
predicates with check contraints: "T1"."N2"="T2"."N1" AND "T1"."N1"<200
after transitive predicate generation: "T1"."N2"="T2"."N1" AND "T1"."N1"<200
finally: "T1"."N2"="T2"."N1"
apadrv-start: call(in-use=1056, alloc=16344), compile(in-use=44792, alloc=46272)
kkoqbc-start
SJC: Set to Join Conversion
In some cases, the optimizer can convert a set operator to a join operator. Interestingly, this feature is not enabled by default (up to 11gR1). In the listing 1-6, we enable this parameter. A MINUS set operation has been converted to a join operation.
alter session set "_convert_set_to_join"=true;
select /*+ gather_plan_statistics */ n2 from t1 minus select n1 from t2
Plan hash value: 3050591313
------------------------------------------------------------------------------------...
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time |...
------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 0 |00:00:00.01 |...
| 1 | HASH UNIQUE | | 1 | 99 | 0 |00:00:00.01 |
| 2 | NESTED LOOPS ANTI | | 1 | 99 | 0 |00:00:00.01 |
| 3 | TABLE ACCESS FULL| T1 | 1 | 100 | 100 |00:00:00.01 |
|* 4 | INDEX UNIQUE SCAN| SYS_C0010995 | 100 | 1 | 100 |00:00:00.01 |
------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
4 - access("N2"="N1")
Listing 1-6: SJC
There is also a new hint set_to_join with this new feature.
/*+
...
OPT_PARAM('_convert_set_to_join' 'true')
...
SET_TO_JOIN(@"SET$1")
...
*/
SU: Subquery Unnesting
Subqueries can be unnested in to a join. Listing 1-7 shows that a subquery is unnested in to a view and then joined to other row sources. In this listing, a correlated subquery is moved in to a view VW_SQ_1, unnested and then joined using Nested Loops Join technique. There are many different variations of Subquery Unnesting possible, but the crux of the matter is that subqueries can be unnested, joined and then costed.
select /*+ gather_plan_statistics */ n1 from t1 where n1 >
(select max(n2) from t2 where t2.n1 = t1.n1)
Plan hash value: 2311753844
-----------------------------------------------------------------------------------...
| Id | Operation | Name | Starts | E-Rows | A-Rows |
-----------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 0 |
| 1 | NESTED LOOPS | | 1 | 1 | 0 |
| 2 | VIEW | VW_SQ_1 | 1 | 5 | 100 |
|* 3 | FILTER | | 1 | | 100 |
| 4 | HASH GROUP BY | | 1 | 5 | 100 |
| 5 | TABLE ACCESS BY INDEX ROWID| T2 | 1 | 100 | 100 |
|* 6 | INDEX RANGE SCAN | SYS_C0010995 | 1 | 100 | 100 |
|* 7 | INDEX UNIQUE SCAN | SYS_C0010992 | 100 | 1 | 0 |
-----------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - filter(MAX("N2")<200)
6 - access("T2"."N1""MAX(N2)")
SU is one reason why there are many performance issues after a database upgrade to 10g and above. Cost of unnested subquery will go up or down leading to an unfortunate choice of not-so-optimal execution plan.
Use of ORDERED hint can really play havoc with SU feature too. For example, in the listing 1-8, join between t1 and t2 is preferred followed by other joins. You would expect to see the leading table in the join to be T1, but the leading row source is VW_SQ_1.
select /*+ gather_plan_statistics ORDERED */ t1.n1, t2.n1 from t1 , t2
where t1.n1 = t2.n1 and t1.n1 > (select max(n2) from t2 where t2.n1 =t1.n1)
Plan hash value: 3904485247
------------------------------------------------------------------------------------...
| Id | Operation | Name | Starts | E-Rows | A-Rows |
------------------------------------------------------------------------------------...
| 0 | SELECT STATEMENT | | 1 | | 0 |...
| 1 | NESTED LOOPS | | 1 | 1 | 0 |
| 2 | NESTED LOOPS | | 1 | 1 | 0 |
| 3 | VIEW | VW_SQ_1 | 1 | 5 | 100 |
|* 4 | FILTER | | 1 | | 100 |
| 5 | HASH GROUP BY | | 1 | 5 | 100 |
| 6 | TABLE ACCESS BY INDEX ROWID| T2 | 1 | 100 | 100 |
|* 7 | INDEX RANGE SCAN | SYS_C0010995 | 1 | 100 | 100 |
|* 8 | INDEX UNIQUE SCAN | SYS_C0010992 | 100 | 1 | 0 |
|* 9 | INDEX UNIQUE SCAN | SYS_C0010995 | 0 | 1 | 0 |
------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
4 - filter(MAX("N2")<200)
7 - access("T2"."N1""MAX(N2)")
9 - access("T1"."N1"="T2"."N1")
filter("T2"."N1"<200)
Is CBO not honoring our hint? It is honoring our hint. Except that ORDERED hint was applied after the SU transformation and so, unnested view is in the leading row source. A variation of the transfromed query from 10053 trace file is printed below. With ORDERED hint, of course, CBO must choose the unnested view as the leading row source. Use LEADING hint instead of ORDERED hint if necessary.
SELECT /*+ ORDERED */ “T1”.”N1″ “N1″,”T2”.”N1″ “N1” FROM
(SELECT MAX(“T2”.”N2″) “MAX(N2)”,”T2″.”N1″ “ITEM_1” FROM “CBO3”.”T2″ “T2” GROUP BY “T2”.”N1″) “VW_SQ_2”,
“CBO3”.”T1″ “T1″,”CBO3”.”T2″ “T2” WHERE “T1″.”N1″=”T2”.”N1″ AND “T1″.”N1″>”VW_SQ_2″.”MAX(N2)” AND “VW_SQ_2″.”ITEM_1″=”T1”.”N1″
Summary
There are many techniques to cover in one blog entry. We will discuss these features further in upcoming blogs. This can be read in more conventional format: query_transformation_part_1_orainternals
Posted in CBO, Oracle database internals, Performance tuning | Tagged: CBO, join elimination, oracle performance, query transformation, subquery unnesting, transitive predicates | 9 Comments »
RMOUG 2010: My presentations
Posted by Riyaj Shamsudeen on February 17, 2010
It is very disappointing to me that I had to cancel my trip to RMOUG training days. I am sick and was not able to catch the flight due to that.
But, I can always share my presentations here. I had two presentations planned in this training day and can be accessed as below:
Advanced RAC troubleshooting
Riyaj_Advanced_rac_troubleshooting_RMOUG_2010_doc
Riyaj_Advanced_rac_troubleshooting_RMOUG_2010_ppt
Why optimizer hates my sql
Riyaj_Why_optimizer_hates_my_sql_2010
RMOUG training days audience: Please accept my sincere apologies.
Posted in CBO, EBS11i, Oracle database internals, Performance tuning, Presentations, RAC | Tagged: CBO, object remastering, oracle performance, RAC performance, RAC performance myths, UDP RAC, udp_xmit_hiwat, upd_max_buf, _gc_affinitiy_minimum, _gc_affinity_limit, _gc_affinity_time | Leave a Comment »
Is plan_hash_value a final say?
Posted by Riyaj Shamsudeen on September 13, 2009
I was reviewing a performance issue with a client recently. Problem is that increased global cache waits causing application slowdown affecting few critical business functions. Using one of my script gc_traffic.sql > and graphing the results with Excel spreadsheet, it is established that there is a marked increase in GC traffic today compared to week earlier. Similar jobs runs every day and so comparing two week days is sufficient to show the GC traffic increase. Graph is between total blocks and AWR snap time in 30 minutes interval. [Click the picture below to review the graph clearly.]
Identifying the object creating this increased GC traffic is essential to identify root cause. We were able to quickly determine that this increase in GC traffic was localized around few SQL statements using ADDM and AWR reports. We decided to focus on one SQL with an obvious increase in elapsed time compared to prior week. So, first question asked, is there a change in the plan? plan_hash_value was reviewed and quickly determined that there is no change in the plan_hash_value.
Posted in CBO, Performance tuning, RAC, Uncategorized | Tagged: gc traffic, global cache CR, global cache CUR, oracle performance, plan_hash_value, scientific tuning | 7 Comments »
Exciting seminars in Dallas arena
Posted by Riyaj Shamsudeen on August 21, 2009
If you live in Dallas area, there are two very important seminars coming up:
- Tanel Poder is presenting his Advanced Oracle troubleshooting seminar on September 9-11, 2009. .
- Jonathan Lewis presenting two day seminar cost based optimization and writing efficient SQL on Oct 28 and Oct 29 2009
.
These two gentlemen needs no introduction. Tanel Poder is an expert in Oracle internals and Jonathan Lewis is a Guru in Cost based optimization and writing efficient SQL.
Tell them I sent ya 🙂
Update: I just heard from Tanel and he is unable to make it to Dallas this September. He is rescheduling his seminar and I can’t wait for his seminar. I will update this blog with his rescheduled dates.
Posted in CBO, Oracle database internals, Performance tuning, Presentations | 5 Comments »
COLLABORATE 2009 presentation: 11g performance new feature.
Posted by Riyaj Shamsudeen on May 6, 2009
I just presented about Oracle 11g new features specific to performance in COLLABORATE 2009, Orlando Florida. You can download presentation and paper from here:
11g performance specific new features – presentation
11g performance specific new features – paper
I met couple of new friends and many familiar faces.
Catherin Devlin introduced sqlpython tool to me. This tool is an user friendly replacement for sqlplus with many UNIX like goodies. This tool will be an useful addition to command line tools. You can see installation instructions for sqlpython here.
I also attended an interesting application performance panel discussion with fellow Oakie Mark W Farnheim, Mike Brown and Sandra Vucinic. We discussed few customer issues.
An interesting problem discussion is worth mentioning. A client clones production database to development database using full rapidclone methodology. But, access plans for a SQL statement is different between production and development, even though everything was exactly the same. I am hoping, that client will send 10053 trace files from both databases and I will blog about it if I get anything from that client. I think, bind peeking is causing the plan difference, but need to analyze 10053 trace file to confirm that. Another possibility is that, may be , he is not cloning Oracle Software and some software patches are not existing in cloned environment. Need trace files to proceed further here.
Of course, I met few other friends Jeremy Schneider, Dan Norris to mention few.
Posted in 11g, CBO, EBS11i, Oracle database internals, Performance tuning, Presentations | Tagged: 11g, adaptive cursor sharing, bind peeking, CBO, deduplicate, extended_stats, invisible indexes, lob compression, OD lock_type, oracle performance, securefile lobs | Leave a Comment »
DOUG presentation: Why does optimizer hate my SQL?
Posted by Riyaj Shamsudeen on April 18, 2009
I presented about Cost based optimizer explaining why some times CBO chose inefficient access plan, even though, there is an efficient plan in the search space. This entry is to post presentation slides and they can be downloaded from Why_optimizer_hates_my_sql
.
Update: Updated presentation after Greg’s comments.
Update2: Further bug fixes in presentation and script.
Update3: Updates after Randolf’s comments.
Posted in 11g, CBO, Performance tuning, Presentations | Tagged: CBO, dbms_xplan, extended statistics, first_rows, oracle performance, performance | 8 Comments »
Dynamic_plan_table, x$kqlfxpl and extreme library cache latch contention
Posted by Riyaj Shamsudeen on March 13, 2009
We had an interesting latch contention issue with a client database worth sharing. Client complained that they are seeing increased library cache latch contention in production with no logical explanation (yet). So, client wanted us to find the root cause. This performance issue seems to have started recently and occurs intermittently and also resolves by itself. Client is planning to upgrade to 10g in 4 weeks time frame and this issue need to be resolved to avoid any delays in 10g upgrade.
From statspack analysis and various statistics analysis, it is visible that there is an increase in library cache latch contention, but nothing jumps up as a problem. Of course, this is a very active application [ 5 node RAC application] with very high number of literal SQLs but that is nothing new, it is always been this way. No new dynamic SQLs, no DDLs invalidating cursors or anything of that sort. I started watching production instance, in real time, waiting for the re-occurrence of this issue. It occurred!
latchprofx for rescue
At this very juncture, instance was suffering from latch contention and It was visible that sessions were starting to queue up for latches.
I was ready with necessary tools. Tanel Poder has written a great tool latchprofx to sample v$latch_holder with high frequency [ Actually, it uses x$ tables but you get the idea ]. In this case, high frequency sampling is a must since this performance problem disappears in few minutes or so. Executed latcprofx script for library cache latches and 10000 samples as printed below.
SQL> @/tmp/latchprofx sid,name % library 10000 -- LatchProfX 1.06 by Tanel Poder ( http://www.tanelpoder.com ) SID NAME Held Held % Held ms ------ ----------------------------------- ---------- ------- ----------- 140 library cache 9555 95.55 25167.870 185 library cache 198 1.98 521.532 245 library cache 97 .97 255.498 185 library cache pin 69 .69 181.746 245 library cache pin 39 .39 102.726 240 library cache 33 .33 86.922 240 library cache pin 6 .06 15.804 227 library cache 2 .02 5.268 227 library cache pin 1 .01 2.634
Yikes. We can see that one session holding library cache latch in 95.5% of samples. That seems bit odd.
Of course, there are many latch children for library cache latches. Is that session repeatedly acquiring just one latch children? Or is it acquiring many different latch children? More importantly what is that session executing ?
Latchprofx to the rescue again. Latchprofx can also print latch children address. Re-executing latcprofx script with modified second argument to the call. Only difference between these two calls is that first argument to latchprofx includes laddr now.
@/tmp/latchprofx sid,name,laddr % library 10000 SID NAME LADDR Held Held % Held ms ------ ----------------------------------- ---------------- ---------- ------- ----------- 140 library cache 0000000990FEFA18 298 2.98 783.442 140 library cache 0000000990FED2B8 270 2.70 709.830 140 library cache 0000000990FEF298 254 2.54 667.766 140 library cache 0000000990FEF658 254 2.54 667.766 140 library cache 0000000990FEECF8 240 2.40 630.960 140 library cache 0000000990FF0198 236 2.36 620.444 140 library cache 0000000990FEE488 225 2.25 591.525 140 library cache 0000000990FEFCE8 223 2.23 586.267 140 library cache 0000000990FEEED8 222 2.22 583.638 140 library cache 0000000990FEF388 222 2.22 583.638 140 library cache 0000000990FEDEE8 220 2.20 578.380 140 library cache 0000000990FF00A8 216 2.16 567.864 140 library cache 0000000990FEE758 215 2.15 565.235 140 library cache 0000000990FEEFC8 212 2.12 557.348 140 library cache 0000000990FEE938 211 2.11 554.719 140 library cache 0000000990FEE668 205 2.05 538.945 140 library cache 0000000990FEDB28 201 2.01 528.429 ....
Whoa! This session was acquring nearly all latch children. Notice that latch addresses are different in every row output. Meaning, various samples of latchprofx saw that this session is holding a different latch children. In a nutshell, this session was acquiring and releasing ALL library cache latches ( aka children) in quasi sequential fashion and causing massive performance issue. There are 53 latch children for library cache latch (in this database). Column held% is approximately 2%, indicating all library cache latch children were acquired and released in a quasi-uniform distributed(2% times 50), quasi-cyclical fashion! Same pattern repeates if I reduce or increase samples.
Latch greedy session
Initially, I thought, this is a bug. I have not seen a case where all library cache latch children were needed to execute a SQL or a process causing massive latch contention. [ Okay, I confess, I have simulated that kind of issue in my test database holding library cache latch children using oradebug kslgetl stuff, but that is a different topic altogether]. Session 140 was executing a SQL printed below. This SQL is querying execution plan from shared_pool for a specific hash_value in this 9i database( Equivalent to dbms_xplan.display_cursor stuff in 10g.]
select plan_table_output from TABLE( dbms_xplan.display ( 'backup.dynamic_plan_table',
(select rawtohex(address)||'_'||child_number x from v$sql where hash_value=&hv ), 'serial' ) )
/
Turned on sqltrace on that session and tkprof showed that recursive SQL generated from dbms_xplan package as a costly SQL.
REM Removing few lines to improve readability.
SELECT /* EXEC_FROM_DBMS_XPLAN */ id, position, level , operation, options, object_name , cardinality, bytes, temp_space,
cost, io_cost, cpu_cost ,decode(partition_start, 'ROW LOCATION',
....
from BACKUP.DYNAMIC_PLAN_TABLE start with id = 0
and timestamp >=
(select max(timestamp) from BACKUP.DYNAMIC_PLAN_TABLE where id=0 and
statement_id = '00000009BB9B6D50_0' and nvl(statement_id, ' ') not like 'SYS_LE%')
and nvl(statement_id, ' ') not like 'SYS_LE%' and statement_id = '00000009BB9B6D50_0' connect by (prior id = parent_id
and prior nvl(statement_id, ' ') =
nvl(statement_id, ' ')
and prior timestamp <= timestamp)
or (prior nvl(object_name, ' ') like 'SYS_LE%'
and prior nvl(object_name, ' ') =
nvl(statement_id, ' ')
and id = 0 and prior timestamp <= timestamp)
order siblings by id
/
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.03 0.02 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 30 53.79 55.90 423 375837 0 29
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 32 53.82 55.93 423 375837 0 29
X$KQLFXPL
55 seconds to execute this SQL? That seems bit excessive. This SQL is the only time-consuming recursive SQL generated from the select statement. So, somehow, this must be causing latch contention. I will print only relevent lines from the plan output.
....
| 4 | NESTED LOOPS OUTER | | 1 | 4479 | 21 (5)|
| 5 | NESTED LOOPS OUTER | | 1 | 4475 | 20 (5)|
|* 6 | FIXED TABLE FULL | X$KQLFXPL | 1 | 4444 | | <---- FTS
| 7 | TABLE ACCESS BY INDEX ROWID| OBJ$ | 1 | 31 | 3 (34)|
|* 8 | INDEX UNIQUE SCAN | I_OBJ1 | 1 | | 2 (50)|
| 9 | TABLE ACCESS CLUSTER | USER$ | 1 | 4 | 2 (50)|
|* 10 | INDEX UNIQUE SCAN | I_USER# | 1 | | |
....
6 - filter("P"."INST_ID"=:B1 AND "P"."KQLFXPL_HADD""P"."KQLFXPL_PHAD")
Line #6 is the problem. This table x$kqlfxpl is accessed using Full table scan. Looks like, x$kqlfxpl can NOT be accessed without holding library cache latches. Since there is a FTS on this fixed table, almost every library cache object need to be touched which potentially means all library cache objects must be inspected. Further, accessing this x$ table means library cache buckets (_kgl_bucket_count controlled area) need to be walked, latches acquired and released before that memory area is inspected. Makes sense!
Repeated calls to kqlfxp, kglic, kglic0 also visible in the stack output. These calls suggests that library cache latches were acquired and released. Systemstate dumps confirms that too.
I was also able to reproduce this issue querying x$kqlfxpl in a cloned database.
SQL> select /*+ full(a) */ count(*) from x$kqlfxpl a;
COUNT(*)
----------
48926
-------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)|
-------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 18 (6)|
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | FIXED TABLE FULL | X$KQLFXPL | 100 | | |
-------------------------------------------------------------------------
Running latchprofx script from another session concurrently shows that accessing this x$ table will result in excessive library cache latching activity. Row estimates column for this table shows 100 which is a CBO default cardinality estimate if there are no statistics on a table.
@/tmp/latchprofx sid,name,laddr % library 10000 SID NAME LADDR Held Held % Held ms ------ ----------------------------------- ---------------- ---------- ------- ----------- 127 library cache 0000000990FED2B8 26 .26 68.120 127 library cache 0000000990FEFEC8 24 .24 62.880 127 library cache 0000000990FEF658 23 .23 60.260 127 library cache 0000000990FEE668 22 .22 57.640 127 library cache 0000000990FEFA18 22 .22 57.640 ...
Background
Now, a little bit background is necessary. What started all this? As a part of 10g upgrade planning, Client DBAs had setup a job to capture costly SQLs and store execution plans from shared_pool using dynamic_plan_table script, borrowed from Tom kyte dynamic_plan_table discussion. Excellent idea and wonderfully written sql, Tom.
If you don’t know already, Tom’s method creates following view. Client script passes the hash_value of costly SQLs from v$sql to this view.
create or replace view dynamic_plan_table
as
select
rawtohex(address) || '_' || child_number statement_id,
sysdate timestamp, operation, options, object_node,
object_owner, object_name, 0 object_instance,
optimizer, search_columns, id, parent_id, position,
cost, cardinality, bytes, other_tag, partition_start,
partition_stop, partition_id, other, distribution,
cpu_cost, io_cost, temp_space, access_predicates,
filter_predicates
from v$sql_plan
;
REM there is a wrapper script calling following SQL, in a loop, for top 20 SQL statements at a stretch.
REM Of course, there is more logic in that script.
select plan_table_output from TABLE( dbms_xplan.display ( 'backup.dynamic_plan_table',
(select rawtohex(address)||'_'||child_number x from v$sql where hash_value=&hv ), 'serial' ) )
/
Unfortunately, such an awesome method has side effects in version 9.2.0.8, as explained above.
At this point, I am almost sure that we need to collect statistics on fixed tables to resolve this issue. There is a fixed index on x$kqlfxpl (KQLFXPL_HADD, KQLFXPL_PHAD,KQLFXPL_HASH) and if that index is used, effect of this problem should disappear. Since there is a plan to upgrade to 10g soon, client didn’t want to collect fixed statistics.
So, I worked around the issue. Not an elegant solution, but it avoids problem by recreating the view with hardcoded hash value for every loop.
create or replace view backup.dynamic_plan_table
as
select
rawtohex(address) || '_' || child_number statement_id,
sysdate timestamp, operation, options, object_node,
object_owner, object_name, 0 object_instance,
optimizer, search_columns, id, parent_id, position,
cost, cardinality, bytes, other_tag, partition_start,
partition_stop, partition_id, other, distribution,
cpu_cost, io_cost, temp_space, access_predicates,
filter_predicates
from v$sql_plan
where hash_value=&&hv -- Added this line..
;
select plan_table_output from TABLE( dbms_xplan.display ( 'backup.dynamic_plan_table',
(select rawtohex(address)||'_'||child_number x from v$sql where hash_value=&&hv ), 'serial' ) )
/
Now, it is evident that query runs in 0.03 seconds and also used fixed index.
51 NESTED LOOPS OUTER (cr=261 r=0 w=0 time=1327 us)
51 NESTED LOOPS OUTER (cr=131 r=0 w=0 time=892 us)
51 FIXED TABLE FIXED INDEX X$KQLFXPL (ind:3) (cr=0 r=0 w=0 time=496 us)
27 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=131 r=0 w=0 time=327 us)
27 INDEX UNIQUE SCAN I_OBJ1 (cr=104 r=0 w=0 time=212 us)(object id 33)
27 TABLE ACCESS CLUSTER USER$ (cr=130 r=0 w=0 time=359 us)
27 INDEX UNIQUE SCAN I_USER# (cr=28 r=0 w=0 time=78 us)(object id 11)
Finally
10g upgrade guide recommends collecting fixed table statistics. So, this issue should completely disappear in 10g.
Posted in CBO, Oracle database internals, Performance tuning | Tagged: kglic, kglic0, kqlfxp, latches, library cache latch, oracle, oracle performance, RAC, x$kqlfxpl | 11 Comments »
Cardinality feedback to resolve a Cache buffers chains latch contention issue
Posted by Riyaj Shamsudeen on January 2, 2009
Earlier, I blogged about resolving cache buffers chains latch contention in my earlier entry , in which, root cause was excessive index access due to Nested Loops join. Recently, we resolved another similar issue.
Problem
CPU usage was very high in production database server in user% mode. Dynamic performance view v$session_wait indicated excessive waits for latch contention. Output from a script wait_details.sql (scripts available at the end of this post) shows that many sessions were waiting for ‘latch free’ event. Also, address for these latch children are the same, meaning all these sessions are trying to access one latch children.
SQL> @wait_details
SID PID EVENT USERNAME STATE WAIT_TIME WIS P1_P2_P3_TEXT
------ ------- ------------- --------- ---------- ------------------- --------- ----- -----------------------------------
91 24242 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 0
101 4884 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 0
116 23899 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 0
187 19499 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 0
108 23498 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 3
194 23701 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 0
202 26254 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 4
220 23274 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 0
227 23643 latch free CSTMOP WAITED KNOWN TIME 2 0 address 69476807024-number 98-tries 0
331 26519 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 0
297 23934 latch free CSTMOP WAITING 0 0 address 69476807024-number 98-tries 3
....
We can identify SQL causing latch contention querying v$session_wait. From the output below, SQL with hash_value 1509082258 is suspicious since there are many sessions executing that SQL and waiting / waited recently for ‘latch free’ event.
select substr(w.event, 1, 28 ) event, sql_hash_value, count(*) from v$session_wait w, v$session s, v$process p where s.sid=w.sid and p.addr = s.paddr and s.username is not null and event not like '%pipe%' and event not like 'SQL*%' group by substr(w.event, 1, 28), sql_hash_value ; EVENT SQL_HASH_VALUE COUNT(*) ------------------------------ -------------- ---------- enqueue 3740270 1 enqueue 747790152 1 enqueue 1192921796 1 latch free 622474477 3 latch free 1509082258 58 <--- latch free 1807800540 1 global cache null to x 3740270 1 global cache null to x 1473456670 1 global cache null to x 3094935671 1 db file sequential read 109444956 1
Mapping to object_name
Keep Reading
Posted in CBO, EBS11i, Performance tuning | Tagged: cache buffers chain, CBO, latches, oracle, oracle performance, performance, v$session_wait | 7 Comments »
Oracle database internals by Riyaj 