Coskan Gundogar and Karl Arao have written two interesting articles about Oracle performance analysis and visualization, check these out!
Coskan’s article:
Karl’s article:
Note that in March I will be releasing PerfSheet v3.0, which will have lots of improvements! ;-)
In my Beyond Oracle Wait interface article I troubleshooted a test case where an execution plan somehow went “crazy” and started burning CPU, lots of logical IOs and the query never completed.
I have uploaded the test case I used to my new website, to a section where I will upload some of my demo scripts which I show at my seminars (and people can download & test these themselves too):
http://tech.e2sn.com/oracle-seminar-demo-scripts
Basically what I do is this:
Using nested loops over lots of rows is a sure way to kill your performance.
And an interesting thing with my script is that the problem still happens in Oracle 11.1 and 11.2 too!
Oracle 11g has Adaptive Cursor Sharing, right? This should take care of such a problem, right? Well no, adaptive bind variable peeking is a reactive technique – it only kicks in after the problem has happened!
So feel free to download the script, review it and test it out!
I have been very busy over last months (as you see from the lack of blog entries). Part of the reason is that I’ve been building new seminar material and now I’m pleased to announce some first seminar dates!
I have updated new seminar dates and cities in m new webpage:
From April 2010 I offer total 3 different seminars
I have rearranged the Advanced Oracle Troubleshooting class based on customer feedback, removed some content, added new content and I think this deserves a new version number, 2.0.
Also, I created an entirely new class Advanced Oracle SQL Tuning which should provide the same for SQL tuners that my Advanced Oracle Troubleshooting class has provided for database troubleshooters. This class will not start with CBO concepts and how SQL execution might work in theory, insead we will start from going very deep into understanding how Oracle really executes SQL execution plans and what is the data flow order and hierarchy in the execution plan tree.
From there we go on into learning how to read execution plans of any complexity and how to control SQL execution plans – how to make them do exactly what we want. And CBO topics will come in the end – by then the CBO fundamental concepts such as Cardinality, Density and IO/CPU Cost will make good sense and are not just some arbitrary names for some magic numbers coming from the optimizer ;-)
In addition, I separated Parallel Execution and Partitioning topics (which not everyone is using) into a separate 1-day seminar, Oracle Partitioning and Parallel Execution for Performance, which I usually deliver right after the 3-day SQL tuning seminar.
In coming days I also plan to upload some SQL tuning related content to tech.e2sn.com to show the quality of the upcoming seminar ;-)
So, feel free to check out the seminar dates and descriptions here:
Cool stuff, Oracle, Oracle 11g, Oracle 11gR2, Performance, SQL, Troubleshooting
In early January I wrote that I’m gonna start organizing the more serious and practical Oracle content into my new website and I’ll leave my blog for Oracle hacks, my (IT) observations and philosophy, general thoughts and just fun.
It’s time to publish the newsite now with an application demo rototype which gives some clue of what kind of features will there be in the secret project I’ve been working on for several months with my friend and business partner.
The website is located here:
E2SN does have a meaning, but I’ll leave it a secret for now ( you are free to guess ;-)
So, there’s not much technical content at the site yet, but there’s a cool online app which you should check if you deal with SQL tuning and execution plan analysis much.
It’s called PlanViz, Oracle Execution Plan Visualization app, you can check it out here:
Oh, I’ve also created something called a “Living Book” into my website, where I will write about Oracle, performance, troubleshooting, etc. There is also a place where people can request what I should write about there!
And that’s all for today!
Administration, Cool stuff, Internals, Oracle, Performance, Productivity, SQL, Tools
This is the second part of the joint blog “project” with James Morle, called “The Wait Interface Is Useless (Sometimes)”.
We already did a joint presentation on this topic at UKOUG and more conferences will follow :) Read the first part by James here for intro.
So, where do we go when Oracle’s wait interface doesn’t help us? We will show multiple techniques over time, but here’s where I normally continue when wait interface is “useless”.
I use V$SESSTAT.
Oh, were you expecting something more “advanced” instead of boring old V$SESSTAT’s performance counters which has been available in Oracle for ages? ;-)
Well, there is a reason why the V$SESSTAT has been available in Oracle for ages, very likely even before Wait Interface was introduced (but I wouldn’t know for sure, I was still in elementary school back then or something :).
And the reason is that session level performance counters are VERY useful about finding out WHAT Oracle is doing. Every time you parse, a counter goes up by one in V$SESSTAT for the session. Every time you execute, a counter goes up. Every time you do a logical IO, a counter goes up. Every time you commit, a counter goes up. Every time an index block is split, a counter goes up. You get the point.
Oracle’s V$SESSTAT tells you WHAT Oracle is doing. Wait interface tells you how much TIME is spent waiting for something, but V$SESSTAT counters just tell you how many times some operation was done. You can not conclude how much time was spent by looking just at the number of times something has happened (as Cary will tell you) but nevertheless, the V$SESSTAT counters definitely give you a good clue into WHAT THE [FU|HE]CK is an Oracle session doing – especially when wait interface says you’re not waiting for anything and SQL trace doesn’t print a line.
How many different operations are counted for each session in Oracle? Let’s check (Oracle 11.2):
SQL> select count(*) from v$sesstat where sid = 14; COUNT(*) ---------- 611
Oracle 11.2 keeps track of the counts of 611 different operations, for each session!
That’s VERY valuable source of information for understanding what Oracle is doing and its relatively easy to use.
And that’s exactly the reason why I wrote my Snapper script – I wanted this information to be VERY EASY to use!
And here’s an example – session 14 is stuck, doesn’t respond, user complains. Let’s check the wait interface:
If I want to know what a session is doing, I sample V$SESSION_WAIT first, with my sw.sql script (or I could just query ASH which gives me the same data with history):
SQL> @sw 14
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
14 WORKING On CPU / runqueue 3486 130
1 row selected.
SQL>
SQL> @sw 14
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
14 WORKING On CPU / runqueue 3486 137
1 row selected.
SQL>
SQL>
SQL> @sw 14
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
14 WORKING On CPU / runqueue 3486 139
1 row selected.
SQL>
From here we see 2 things:
So, it’s pretty evident that this session is just burning CPU and wait interface is useless here (as we are not waiting for anything, as far as Oracle sees it of course). Alternatively I could just run top or prstat and check whether the process is 100% on CPU or not.
So, before going on to Snapper, lets look into what kind of SQL this session executes right now (we could sample this also multiple times, to check whether we are constantly running the same statement):
SQL> <strong>select * from table(select dbms_xplan.display_cursor(sql_id,sql_child_number) from v$session where sid = 14);</strong>
PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 5vy5qjd3fsn5c, child number 0
-------------------------------------
SELECT MIN(t1.created), MAX(t1.created) FROM t1 , t2 , t3
WHERE t1.object_id = t2.object_id AND t2.object_id = t3.object_id
AND t1.owner = :v AND t2.owner = :v AND t3.owner = :v
Plan hash value: 3271631391
----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 4 (100)| |
| 1 | SORT AGGREGATE | | 1 | 66 | | |
|* 2 | HASH JOIN | | 7 | 462 | 4 (25)| 00:00:01 |
| 3 | NESTED LOOPS | | | | | |
| 4 | NESTED LOOPS | | 7 | 329 | 2 (0)| 00:00:01 |
| 5 | TABLE ACCESS BY INDEX ROWID| T1 | 7 | 196 | 1 (0)| 00:00:01 |
|* 6 | INDEX RANGE SCAN | I1 | 7 | | 1 (0)| 00:00:01 |
|* 7 | INDEX RANGE SCAN | I2 | 27 | | 1 (0)| 00:00:01 |
|* 8 | TABLE ACCESS BY INDEX ROWID | T2 | 1 | 19 | 1 (0)| 00:00:01 |
| 9 | TABLE ACCESS BY INDEX ROWID | T3 | 40 | 760 | 1 (0)| 00:00:01 |
|* 10 | INDEX RANGE SCAN | I3 | 40 | | 1 (0)| 00:00:01 |
----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("T2"."OBJECT_ID"="T3"."OBJECT_ID")
6 - access("T1"."OWNER"=:V)
7 - access("T2"."OWNER"=:V)
8 - filter("T1"."OBJECT_ID"="T2"."OBJECT_ID")
10 - access("T3"."OWNER"=:V)
33 rows selected.
SQL>
Hmm… can anyone reliably tell why this SQL statement is slow and burns all the CPU time?
The answer is no. An execution PLAN is a plan of actions which would be executed when someone runs the execution plan. It doesn’t tell you anything about what’s exactly going on right now, it doesn’t tell you what exactly is using all the CPU time. Anything we would say at this point, would be a guess! Lets use V$SESSTAT instead, for gathering more hard evidence!
(The syntax of Snapper is documented inside the script or just search for snapper in my blog, plenty of examples :)
SQL> <strong>@snapper out 5 1 14 </strong> -- Session Snapper v2.02 by Tanel Poder ( http://www.tanelpoder.com ) -- ---------------------------------------------------------------------------------------------------------------------- SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH ---------------------------------------------------------------------------------------------------------------------- 14, SYS , STAT, session logical reads , 81351, 16.27k, 14, SYS , STAT, consistent gets , 81351, 16.27k, 14, SYS , STAT, consistent gets from cache , 81351, 16.27k, 14, SYS , STAT, consistent gets from cache (fastpath) , 81352, 16.27k, 14, SYS , STAT, no work - consistent read gets , 81381, 16.28k, 14, SYS , STAT, table fetch by rowid , 2904784, 580.96k, 14, SYS , STAT, index scans kdiixs1 , 93, 18.6, 14, SYS , STAT, buffer is pinned count , 5736560, 1.15M, 14, SYS , STAT, buffer is not pinned count , 75248, 15.05k, 14, SYS , STAT, no buffer to keep pinned count , 1, .2, 14, SYS , TIME, DB CPU , 6050000, 1.21s, 121.0%, |@@@@@@@@@@| 14, SYS , TIME, sql execute elapsed time , 6059922, 1.21s, 121.2%, |@@@@@@@@@@| 14, SYS , TIME, DB time , 6059922, 1.21s, 121.2%, |@@@@@@@@@@| -- End of snap 1, end=2010-01-15 17:33:22, seconds=5 PL/SQL procedure successfully completed.
As our previous sw.sql output showed – we are not waiting for anything. If we were, then snapper would show you WAIT lines from wait interface (V$SESSION_EVENT) as well. But we don’t see any waits.
So, now its the time to go through all the V$SESSTAT stats reported in Snapper! These are the lines with STAT in them (TIME lines are V$SESS_TIME_MODEL breakdown available since 10g, but they are not detailed enough for diagnosing complex problems).
One thing we see, there is a statistic session logical reads and from the last column of Snapper output we see that this session did over 16000 logical reads (buffer gets) per second during snapper run time (of 5 seconds). That’s already a good indication of why we burn so much CPU time – we are doing lots of logical IOs.
Also, we see that we did 18.6 index range scans per second (the statistic index scans kdiixs1 shows that). That doesn’t seem “much” does it. However, check the value for buffer is pinned count statistic! This counter is updated every time we go to a buffer to get some data from it AND it already happens to be open by my session! Oracle keeps buffers pinned and relevant buffer handles cached during a database call in some cases (like nested loop joins and index scans) to avoid reopening the buffer again (getting a buffer again if its closed would mean another logical IO).
Nevertheless, we can see that we re-visited some buffers again and again and again – over a million times per second! When checking my index structures I see that every index has only a few hundred blocks, so having millions and millions of buffer visits (buffer is pinned count + session logical reads) means we are heavily re-visiting the same blocks again and again and again! This points directly to NESTED LOOPS (and also INDEX RANGE SCANS) in the execution plan. Nested loops, as the name says loops through inner rowsource and revisits some of its data as many times as the number of rows coming from the outer rowsource (with few special cases, as usual).
And there’s one more statistic in Snapper output which I do NOT see – execute count. This statistic shows how many times the session executed cursors (executed new ones or re-executed the same one). NB! Snapper only reports these V$SESSTAT statistics which changed during the snapshot – as execute count is not reported, it means that the execute count did not increase during the snapshot, thus the session still executed the same statement! (so for example we were not hard parsing and lots of different statements to “justify” this CPU usage, Snapper would have shown parse count (hard) going up if this session had done so).
So, using the above diagnosis, this is the place where I would take a serious look whether the NESTED LOOPS in the above execution plan are a right thing to do. I would check how many rows would actually match the bind variable values (more about that later) in the SQL statement predicates – NESTED LOOPS is not a good operation for joining large number of rows. More about SQL tuning very soon ;-)
To finish this blog entry, this is the sequence of troubleshooting which I usually use (if a user complains or “something” is slow):
Note that Snapper is just an anonymous PL/SQL block and it doesn’t require any changes to the database!
Ok, back to James now!
Cary Millsap’s recent post prompted me to write down some of the related thoughts in my head.
Here are few of my mantras for systematic troubleshooting and performance tuning, which have materialized in my head over the years of work:
- You are doing too much work
- You are waiting for too much
…both of the above things can be measured in Oracle…
Here’s a link to a Cary Millsap’s awesome post, read it!
By the way, as far as database design and writing SQL is concerned here’s a good chance to learn how to write SQL right from C. J. Date:
There’s another interesting thread going on in Oracle-L, about understanding logical IOs and drilling down into their reasons. Of course sometimes (or rather usually) the excessive logical IOs come from a bad execution plan (when a nested loop loops over lots of datablocks again and again or a wrong index is used for driving a query etc), but sometimes the excessive LIOs are caused by some internal issues, like space management etc.
A convenient tool I use for reporting logical IO reasons is (again) my Snapper! It has an option “b” for reporting Buffer get reasons or as I use below – option “a” shows All information Snapper can show.
There are couple of gotchas though which make this approach imperfect:
Anyway, if you are testing in an environment exclusively used by you, on Oracle 10.2 or lower, then you can run snapper with the gather=a option to report a bunch instance-level statistics in addition to the standard session-level stats:
Here’s an example, prepare for long output:
In Oracle-L mailing list a question was asked about under which conditions can the explain plan report a wrong execution plan (not the one which was actually used when a problem happened).
I replied this, but thought to show an example test case of this problem too:
1) The optimizer statistics the EXPLAIN PLAN ends up using are different
from the statistics the other session ended up using2) Explain plan does not use bind variable peeking thus will not optimize
for current bind variable values3) Explain plan treats all bind variables as VARCHAR2, thus you ma have
implicit datatype conversion happening during the plan execution, (meaning
to_char,to_number functions are added around variables/columns) and this for
example may make optimizer to ignore some indexes if you get unlucky.…Of course explain plan doesn’t really
execute the plan so the implicit datatype conversion you see is in the
explained plan only, but if you actually execute the statement (with correct
bind datatypes) then there’s no implicit datatype conversion. And that’s
where the difference comes from…
And here comes an example of condition number 3 above. Lets use a little bit of bad design out there and put numeric values into varchar2 columns:
SQL> create table t (id varchar2(10), name varchar2(100)); Table created. SQL> insert into t select to_char(object_id), object_name from dba_objects; 51449 rows created.
Now we add a little index for lookup performance and gather stats:
SQL> create index i on t(id); Index created. SQL> exec dbms_stats.gather_table_stats(user,'T',cascade=>true); PL/SQL procedure successfully completed.
Now lets define a bind variable of NUMBER type and set a value for it:
SQL> var x number SQL> SQL> exec :x:=99999 PL/SQL procedure successfully completed.
Now lets use “explain plan for” to estimate the execution plan:
SQL> explain plan for
2 select sum(length(name)) from t where id > :x;
Explained.
SQL> select * from table(dbms_xplan.display) ;
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------
Plan hash value: 3694077449
-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 29 | 56 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 29 | | |
| 2 | TABLE ACCESS BY INDEX ROWID| T | 2572 | 74588 | 56 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | I | 463 | | 3 (0)| 00:00:01 |
-------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("ID">:X)
15 rows selected.
Explain plan command nicely reports that we’d be using an index range scan, which would be a good thing to do given my test data and search condition.
Now lets actually run the statement and see the REAL execution plan actually used for the execution. I’ll use dbms_xplan.display_CURSOR for this. If you don’t pass SQL_ID/child into that function it will just report the last SQL statement executed in your current session. But the key difference between the dbms_xplan.DISPLAY and DISPLAY_CURSOR is that the latter goes to library cache and fetches the actual SQL plan used from there. The explain plan command just reparses the statement and estimates a plan, ignoring any bind variable values and assuming that all bind variables are of type varchar2:
SQL> select sum(length(name)) from t where id > :x;
SUM(LENGTH(NAME))
-----------------
SQL> select * from table(dbms_xplan.display_cursor);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------
SQL_ID 7zm570j6kj597, child number 0
-------------------------------------
select sum(length(name)) from t where id > :x
Plan hash value: 2966233522
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 60 (100)| |
| 1 | SORT AGGREGATE | | 1 | 29 | | |
|* 2 | TABLE ACCESS FULL| T | 2572 | 74588 | 60 (5)| 00:00:01 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter(TO_NUMBER("ID")>:X)
19 rows selected.
Whatta? We actually used a full table scan!
2nd part will follow soon :-)
I received a question about migrated rows recently.
It was about how to detect migrated rows in a 200TB data warehouse, with huge tables – as the ANALYZE TABLE xyz LIST CHAINED ROWS INTO command can not be automatically parallelized at table level (as DBMS_STATS can be, but oh, DBMS_STATS doesn’t gather the migrated/chained row info). Therefore the analyze command would pretty much run forever before returning (and committing) the chained row info in the output table. Also as there are regular maintenance jobs running on these tables (I suspect partition maintentance for example), then it wouldn’t be nice to keep running ANALYZE on the whole table constantly.
So, is there any faster or better way for finding the amount of migrated rows?
Ihave two answers to this.
Answer 1:
As we are dealing with a huge 200+ TB data warehouse its tables/indexes are most likely partitioned. Thus you could use the ANALYZE TABLE xyz PARTITION (abc) LIST CHAINED ROWS command to analyze individual partitions, even in parallel (sqlplus sessions) if you like. This would allow you to focus only on the partitions of interest (the latest ones, with the heaviest activity perhaps).
SQL> create table CHAINED_ROWS ( 2 owner_name varchar2(30), 3 table_name varchar2(30), 4 cluster_name varchar2(30), 5 partition_name varchar2(30), 6 subpartition_name varchar2(30), 7 head_rowid rowid, -- actual chained row's head piece address in the segment 8 analyze_timestamp date 9 );
Table created.
SQL> SQL> analyze table tmp partition (sys_p501) list chained rows; -- the default table name used for output is "CHAINED_ROWS"
Table analyzed.
SQL> analyze table tmp partition (sys_p502) list chained rows;
Table analyzed.
SQL> select partition_name, count(*) from chained_rows group by partition_name;
PARTITION_NAME COUNT(*) ------------------------------ ---------- SYS_P502 252 SYS_P501 5602 SQL>
So, from above you see its possible to find out partition (or even sub-partition level row chaining).
However this above command lists you both CHAINED rows and MIGRATED rows (even though Oracle calls them all chained rows internally, as the chaining mechanism is the same for both cases).
Chained row is a row which is too large to fit into a block, so will always have to be split between multiple different blocks – with an exception of intra-block chaining which is used for rows with more than 255 columns. Migrated row on the other hand is a row which has been updated larger than it initially was – and if as a result it doesn’t fit into its original block, the row itself is moved to a new block, but the header (kind of a stub pointer) of the row remains in original location. This is needed so that any indexes on the table would still be able to find that row using original ROWIDs stored in them). If Oracle didn’t leave the row head piece in place then it would always go and update all indexes which have the ROWID of the migrating row in them.
Why should we care whether a row is a real chained row or just a migrated row?
It’s because if the row is chained, then any reorgs would not help you – if a row is too big to fit into a block, its too big to fit into a block no matter how many times you move around the table. (Note that if you have large tables full of rows longer than 8KB there’s likely something wrong with your design).
But migrated rows on the other hand are “chained” into another block due some update which made them not fit into existing block anymore. This happens when PCTFREE is set too low compared to real row growth factor and sometimes you may want to fix it by reorganizing the table/partition with ALTER TABLE/PARTITION MOVE or by backing the rows up, deleting them and reinserting them back to the table (that one makes sense when only a small amount of rows in a table are migrated).
If you are completely sure that you don’t have any rows longer than the free space in an empty block (thus all individual rows would fit into a block and would need to be split among multiple blocks) then you can conclude that all the rows reported were migrated due their growth.
Another option would be to query out all or a sample of these chained/migrated rows and actually measure how long they are if all columns are put together. This could be done using vsize() function (or also dump() and lengthb() in some cases). Of course the column and row header overhead would need to be accounted in as well.
So, this already gets pretty complex and there are more tiny details which we should take into account… thus I will introduce another way to look into the row migration/chaining thing:
Answer 2: (Alternatively called “should we care?”)
Administration, Internals, Oracle, Performance, Troubleshooting
Sometimes when an attendee describes me some totally weird problem during a seminar, I am immediately able to answer something like “Hey this looks like a bug related to this Oracle configuration and can be influenced by xyz”.
And then people ask me “How the hell do you know all this stuff?”
Well, I haven’t been bitten by all of these bugs myself, but I have been doing something for many years, almost every day… reading my email!
Oh, and additionally I have configured Metalink to send me daily updates about new/updated notes, forum articles and… bug descriptions!
The last part is very important. Bug descriptions tell you something about new bugs found (and old bugs rediscovered) and sometimes their details tell you an interesting piece or two about Oracle internals related to them.
Administration, Cool stuff, Internals, Oracle, Performance, Productivity, Troubleshooting
Tweets
|
|
|
|
Recent Comments