ba6.us - Dave's Database Related Stuff

When you troubleshoot an Oracle (performance) problem you usually want to find out what are the problem sessions doing (wrong) and then why are they doing it.

The “what” question is usually answered using some wait interface based method – like ASH or SQL*Trace, which both add plenty of extra details to the plain wait event data.

My normal session troubleshooting data collection sequence consists of only three steps:

1. Interpret session-level top wait and top SQL data (ASH, SQL*Trace or custom tools sampling session-level V$views)
2. Interpret session-level performance counter data (V$SESSTAT)
3. Sample the problem process stack and list the top stack branches where execution spent the most time

Only looking into #1 is enough in 90% of problem cases. But for advanced troubleshooting of complex and exotic problems I regularly have to dive into the #2 – V$SESSTAT performance counters (That’s the reason why I wrote Snapper for example).

Maybe only once out of every 40-50 troubleshooting cases I dive down into #3 – process stack sampling. While process stack sampling doesn’t lie – it helps especially in these cases where the Oracle’s instrumentation itself doesn’t have a clue what a session/process is doing – it’s like a microscope. It gives you very detailed overview of one part of the problem, but not the big picture. That’s why I never start from #3 when troubleshooting (and if you do, you are doing it wrong – with an exception of a completely hung database ;) I always start from #1 and proceed to #2 only when needed.

Snapper lists both #1 and #2 data for a process by the way.

Anyway, the reason why I’m writing this post is that a few days ago I received a question about an issue which nicely illustrates a case where step #1 shows that there’s an issue and step #2 explains why it’s happening.

There was an execution plan, which ran slightly slower on a new server compared to the old one – and it did read 36 blocks per execution as opposed to only 5:

select ... from TABLE_X where ... call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.02 0.02 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.00 0.07 36 5 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.02 0.09 36 5 0 1

The “disk” column above shows 36 blocks being read in via physical IO – while only 5 buffers had actually been accessed after that (logical IOs are shown in the “query” column).

Now that’s weird – as logical IOs are the ones which cause physical IOs, so the LIO count should normally be equal or greater than the physical IO count.

What’s more stranger, the execution plan is an index unique scan:

Rows Row Source Operation ------- --------------------------------------------------- 1 TABLE ACCESS BY INDEX ROWID TABLE_X (cr=5 pr=36 pw=0 time=0 us cost=4 size=26 card=1) 1 INDEX UNIQUE SCAN TABLE_X_IDX (cr=4 pr=35 pw=0 time=0 us cost=3 size=0 card=1)(object id 51063)

… but if you look into the “pr=” column, which means “blocks read via physical read”, then you see that 35 out of the 36 blocks were read in by the INDEX UNIQUE SCAN row source (pr=35). These counters are cumulative, so the pr=36 in the parent TABLE ACCESS BY INDEX ROWID row source means that there was only one block read by physical IO at the table access level. So why does the index access read 35 blocks?

Is it index height? Can’t be – as the max index height is 24 levels (including the leaf level). And such an index would be ridiculous anyway :)

Let’s look into the wait profile:

Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 Disk file operations I/O 4 0.00 0.00 db file sequential read 4 0.01 0.04 db file scattered read 1 0.03 0.03 SQL*Net message from client 2 0.15 0.15 ********************************************************************************

Wow, an index unique scan which is supposed to traverse the index tree with precise single block reads, has done 4 single block reads and one multiblock read!

Now this is where the wait interface and ASH-style data would not help us any further. We know what’s happening – a multiblock read happening where “it shouldn’t”. We still don’t know why this is happening. We would have to guess from here. And this is where V$SESSTAT comes in – there’s over 600 performance counters maintained for each session and many of them show valuable information about what kind of operations (and how many) the RDBMS kernel has done. So I asked the client to run Snapper on a test session and here’s the output (note that the below output is from a different test run where the queries were executed many times in a loop):

---------------------------------------------------------------------------------------------------------------------------------------- SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH ---------------------------------------------------------------------------------------------------------------------------------------- 1612, ORACLE , STAT, opened cursors cumulative , 6617, 1.32k, 1612, ORACLE , STAT, user calls , 13234, 2.65k, 1612, ORACLE , STAT, pinned cursors current , -1, -.2, 1612, ORACLE , STAT, session logical reads , 5293, 1.06k, 1612, ORACLE , STAT, CPU used when call started , 7, 1.4, 1612, ORACLE , STAT, CPU used by this session , 7, 1.4, 1612, ORACLE , STAT, DB time , 306, 61.2, 1612, ORACLE , STAT, user I/O wait time , 223, 44.6, 1612, ORACLE , STAT, non-idle wait time , 224, 44.8, 1612, ORACLE , STAT, non-idle wait count , 6775, 1.36k, 1612, ORACLE , STAT, process last non-idle time , 5, 1, 1612, ORACLE , STAT, physical read total IO requests , 158, 31.6, 1612, ORACLE , STAT, physical read total multi block requests , 31, 6.2, 1612, ORACLE , STAT, physical read total bytes , 8265728, 1.65M, 1612, ORACLE , STAT, cell physical IO interconnect bytes , 8265728, 1.65M, 1612, ORACLE , STAT, consistent gets , 5293, 1.06k, 1612, ORACLE , STAT, consistent gets from cache , 5293, 1.06k, 1612, ORACLE , STAT, consistent gets - examination , 5293, 1.06k, 1612, ORACLE , STAT, physical reads , 1009, 201.8, 1612, ORACLE , STAT, physical reads cache , 1009, 201.8, 1612, ORACLE , STAT, physical read IO requests , 158, 31.6, 1612, ORACLE , STAT, physical read bytes , 8265728, 1.65M, 1612, ORACLE , STAT, free buffer requested , 1008, 201.6, 1612, ORACLE , STAT, physical reads cache prefetch , 851, 170.2, 1612, ORACLE , STAT, physical reads prefetch warmup , 851, 170.2, 1612, ORACLE , STAT, shared hash latch upgrades - no wait , 188, 37.6, 1612, ORACLE , STAT, calls to get snapshot scn: kcmgss , 1319, 263.8, 1612, ORACLE , STAT, file io service time , 25, 5, 1612, ORACLE , STAT, file io wait time , 2219641, 443.93k, 1612, ORACLE , STAT, min active SCN optimization applied on CR , 1, .2, 1612, ORACLE , STAT, index fetch by key , 1292, 258.4, 1612, ORACLE , STAT, session cursor cache hits , 6440, 1.29k, 1612, ORACLE , STAT, buffer is not pinned count , 1277, 255.4, 1612, ORACLE , STAT, parse time elapsed , 6, 1.2, 1612, ORACLE , STAT, parse count (total) , 6380, 1.28k, 1612, ORACLE , STAT, execute count , 6378, 1.28k, 1612, ORACLE , STAT, bytes sent via SQL*Net to client , 2195633, 439.13k, 1612, ORACLE , STAT, bytes received via SQL*Net from client , 2721339, 544.27k, 1612, ORACLE , STAT, SQL*Net roundtrips to/from client , 6374, 1.27k, 1612, ORACLE , TIME, parse time elapsed , 114215, 22.84ms, 2.3%, |@ | 1612, ORACLE , TIME, PL/SQL execution elapsed time , 67004, 13.4ms, 1.3%, |@ | 1612, ORACLE , TIME, DB CPU , 630000, 126ms, 12.6%, |@@ | 1612, ORACLE , TIME, sql execute elapsed time , 2595410, 519.08ms, 51.9%, |@@@@@@ | 1612, ORACLE , TIME, DB time , 3190919, 638.18ms, 63.8%, |@@@@@@@ | 1612, ORACLE , WAIT, db file sequential read , 978601, 195.72ms, 19.6%, |@@ | 1612, ORACLE , WAIT, db file scattered read , 1213550, 242.71ms, 24.3%, |@@@ | 1612, ORACLE , WAIT, SQL*Net message to client , 9212, 1.84ms, .2%, | | 1612, ORACLE , WAIT, SQL*Net message from client , 1667368, 333.47ms, 33.3%, |@@@@ | -- End of Stats snap 1, end=2012-03-09 14:47:02, seconds=5

See the highlighted lines above and scroll right if you don’t see the metric values…

• The physical read total multi block requests statistic confirms that indeed there were some multiblock reads done by the monitored session.
• The physical reads cache prefetch metric indicates that there was some data block prefetching happening! This explains why we had multiblock reads done where only single block reads were really needed.
• And the physical reads prefetch warmup metric explains why did we do any prefetching at all – it’s for buffer cache warmup, where after a restart or a significant buffer cache size increase Oracle decides to populate the empty buffer cache with any data as fast as possible. Oracle assumes that a random multiblock read doesn’t take that much more time than a random single block read anyway, so why not just read a bunch of additional blocks from around that single block that the index access wanted to read. The read operation will be slightly slower, but it might help to avoid multiple future single block reads as they are already in cache. This should affect things only when you restart the instance or significantly increase the buffer cache size. So on a steady state production system you shouldn’t see it (and it’s for a good cause anyway), but if you do performance tests on some test database, change something, bounce the instance and immediately run a test – this may affect your test results. Btw, this is controlled by a hidden parameter _db_cache_pre_warm, but I’m mentioning this just for educational purposes here, I have never fixed a problem by changing this parameter so you should touch it only in your sandbox hacking database :)

And now back to the original topic – this post wasn’t really about this specific prewarm feature, but rather a yet another example of how the V$SESSTAT metrics tell you much more than the usual wait interface and TOP-sql based approach. And you do not need to enable any tracing or undocumented events for getting these detailed metrics out of Oracle, just query the V$SESSION views at the right time. As I said in the beginning, I don’t jump to the microscopic view unless the higher level views aren’t helpful enough, so I recommend you to follow the 3-step “Advanced Oracle Troubleshooting” method when trying to diagnose what the heck some session is doing and why ;^)

Ok, it took only a year or so, but I’ve fixed most of the broken links (to my scripts etc) in my blog :-)

Please let me know if you hit any more broken links from now on….

There was a question in Oracle-L about where is the LOB data actually stored (in the row or the LOB segments) and what are the exact conditions when a switch from one to another may happen. The documentation isn’t fully clear about this and the “4000 bytes” number may mislead people to think that you can store 4000 bytes of your data in a LOB item before it must move out-of-line.

I clarified this in my post in Oracle-L, but will post it here too. First check this diagram:
 

 
If you create the LOB column with DISABLE STORAGE IN ROW, then the LOB data is always stored out-of-line. LOB index is always used. Only the LOB ID is stored inline, and the ID is looked up in LOB index, where you’ll get the pointers to actual LOB chunk blocks.
 
If you create the LOB column with ENABLE STORAGE IN ROW, then the LOB data may be stored in-line or out-of-line.
 
If the total LOB data + overhead <= 4000 bytes, then the LOB item will be stored in-line. No LOB index is used, even if you modify the LOB later on as everything is stored in-line with the row and versioning/rollback is achieved with undo data.
 
If the total LOB data + overhead > 4000 bytes, then the LOB item will be stored out-of-line. If the LOB fits into 12 x LOB_chunk_size, then no LOB index entries are created, because the in-line LOB locator can store up to 12 pointers to the LOB chunk blocks for each lob item. So if your LOB chunk size is 8kB, you can store LOB items up to 96kB in size without inserting anything to LOB index. However if the LOB item is bigger, then no pointers are stored in-row and all pointers will be put to the LOB index.
 
Note that once you modify an existing LOB item (which is bigger than 4000 bytes with its overhead), but smaller than 12 x chunk_size, then LOB index will still be used after the first LOB change operation as pointers to the old LOB chunk versions have to be stored in it (LOB segments don’t rely on undo for rollback & consistency, but just use LOB chunk versioning managed by LOB index).
 
The “overhead” of an in-line LOB item is 36 bytes, so the actual LOB data must be 4000 – 36 = 3964 bytes or less in order to fully fit in-row. And note that we are talking about bytes here, not characters. With multibyte character sets a character in a CLOB may take multiple bytes.
 
I wrote a presentation about LOB internals quite some time ago, back when Oracle 10.1 came out I think – check it here:
 

• http://www.slideshare.net/tanelp/oracle-lob-internals-and-performance-tuning

 
Enjoy! :-)
 
P.S. The next Advanced Oracle Troubleshooting v2.0 class will start in 3 weeks! (I just added the online payment option back too for convenience:)
 

Ok, I’ve wanted to write this blog entry for a long time – and now it’s time!

Most of my blog readers (thank you!) are performance-minded computer enthusiasts, who care about efficiency and optimization. You’ve been tuning SQL execution plans, instance and OS configuration so that your sessions would achieve the same results with less work and also with less waiting!

You probably know to appreciate why asynchronous I/O must be enabled for busy modern databases, so that your database sessions can do I/O (talk to the storage) without actually having to wait for the I/O operations to complete! You can increase the processing throughput, by not submitting every single I/O separately and waiting for it to complete, before being able to process the results and submit the next one. Asynchronous I/O is a crucial thing for good performance.

Because of all the performance geeks here, this audience (you!) is the best audience ever, whom to announce my (non-Oracle) pet project of last 12 months – Async.it Instant Voice Messenger!

Basically it’s Asynchronous I/O for People :-)

With the Async.it! mobile app you can send voice messages to your colleagues, friends and family – without having to wait until they stop what they were doing and pick up the phone – or without having to end up in a lengthy discussion if you wanted to just send a quick update to someone. And it’s way faster than texting, that’s why we say Save Time – Async.it! :-)

So, if you like what asynchronous I/O does for your database performance, you will like what Async.it! will do for your own I/O performance!

It’s free and iPhone/iPad only at the moment – so if you have one, check it out and tell me what you think! You can find my Async.it contact via Facebook if you’re connected to me in Facebook or by replying a message to the support user you see when logging on (the voice in the support messages is not mine ;-)

If you like the app – make sure to rate it in the app store too! :^)

Update: There is no Facebook dependency, logging on with or using Facebook contacts is totally optional (though more convenient). You can sign up with just your email address and send messages to your contacts in your phone’s contact list (the 1st invite message will send a SMS or email to your contact, depending on which contact method you chose, but once he/she installs the async.it app, all further communication will happen just via data connection, no SMS/email involved).

There was a question in the twitter-sphere about whether using sequences (sequence.NEXTVAL) in your select query’s projection list would somehow disable smart scans happening?

The answer is no, sequence use with smart scans works just fine. The smart scan offloading applies to data retrieval row sources (and filtering) only and nothing else. So, what you have in the query’s projection list (the sequence use for example), does not directly affect the smart scan decision. Just like any other operations like sorting, grouping etc, do not have anything to do with smart scans and don’t disable their use. Smart scans are only related to data retrieval and any other operations do not affect them.

In other words, sequence.NEXTVAL can be used in a query and you can still get smart scans. Here’s simple proof:

 

SQL Monitoring Report SQL Text ------------------------------ SELECT /*+ MONITOR */ t.object_name, s.NEXTVAL n FROM t WHERE owner LIKE 'TANEL%' Global Information ------------------------------ Status : DONE (ALL ROWS) Instance ID : 1 Session : TANEL (204:2707) SQL ID : 5kzs2ucxwf4wk SQL Execution ID : 16777216 Execution Started : 04/13/2012 09:06:46 First Refresh Time : 04/13/2012 09:06:46 Last Refresh Time : 04/13/2012 09:06:48 Duration : 2s Module/Action : SQL*Plus/- Service : dbm Program : sqlplus@mac02.local (TNS V1-V3) Fetch Calls : 4 Global Stats ======================================================================================== | Elapsed | Cpu | IO | Concurrency | Fetch | Buffer | Read | Read | Cell | | Time(s) | Time(s) | Waits(s) | Waits(s) | Calls | Gets | Reqs | Bytes | Offload | ======================================================================================== | 1.50 | 0.36 | 1.06 | 0.08 | 4 | 323K | 2503 | 2GB | 99.97% | ======================================================================================== SQL Plan Monitoring Details (Plan Hash Value=1589210007) ====================================================================================================================================================================== | Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Cell | Activity | Activity Detail | | | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | Offload | (%) | (# samples) | ====================================================================================================================================================================== | 0 | SELECT STATEMENT | | | | 3 | +0 | 1 | 1408 | | | | | | | 1 | SEQUENCE | S | | | 3 | +0 | 1 | 1408 | | | | | | | 2 | TABLE ACCESS STORAGE FULL | T | 439K | 20738 | 4 | +0 | 1 | 1408 | 2496 | 2GB | 99.97% | 100.00 | cell smart table scan (1) | ======================================================================================================================================================================

I have highlighted the query text (which includes sequence.NEXTVAL) and the TABLE ACCESS STORAGE FULL row source, if you scroll right, you’ll see the “cell smart table scan” wait event and also the Offload % column populated, which both indicate that smart scan did happen for that monitored query execution.

Note that often I hear a saying, something like “xyz disables smart scan”, or “using a non-offloadable function disables the smart scan”. This can be misleading and give the impression that if you use a non-Exadata supported function/feature in one part of your query, then smart scanning is disabled for the whole query. This is incorrect.

First of all, the smart scanning is not a query level thing, it’s an access path level thing. So, you can easily run a two table join on one table which is on NFS storage (no smart scanning) and another table, which is on Exadata storage (which allows smart scanning). So, even though smart scanning is “disabled” for the first table, the other table still can be accessed using it! By the way, it’s even possible to have some partitions of your table on NFS and other partitions of the same table on Exadata storage cells and the same table scan can use smart scanning for the partitions stored on the cells and regular buffered or direct path read access for the partitions on NFS. So, smart scanning is not some “all or nothing” query level thing, this decision is made separately for every single segment full scanned in the query. More details in the book.

Secondly, using a non-offloadable function in a filter predicate when retrieving rows does not prevent Oracle to push other, offloadable, predicate functions to be pushed to the storage cells. So again, it’s not an all-or-nothing decision. If a predicate function is not offloadable, it will just not be offloaded (and will show up as just a filter() predicate as opposed to both storage() and filter() predicate), but all the other supported predicates can still be offloaded without a problem. Here’s an example:

SELECT * FROM t WHERE line = 9999 AND mod(line,10) = 0 AND f1(line) =9999 Plan hash value: 1601196873 ---------------------------------------------------------------- | Id | Operation | Name | E-Rows | Cost (%CPU)| ---------------------------------------------------------------- | 0 | SELECT STATEMENT | | | 2887 (100)| |* 1 | TABLE ACCESS STORAGE FULL| T | 1 | 2887 (1)| ---------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - storage(("LINE"=9999 AND MOD("LINE",10)=0)) filter(("LINE"=9999 AND MOD("LINE",10)=0 AND "F1"("LINE")=9999))

Note that the F1() function is a PL/SQL function and filtering based on PL/SQL functions can not be offloaded (as Exadata cells don’t run PL/SQL). This is visible in the predicate section where two predicates are shown in the storage() predicate list but the third one (F1) only shows up in the filter() predicate list.

So, as I explained in the beginning, the smart scan is not an all-or-nothing thing, this decision is made for every segment (partition) separately during query execution phase, again for every execution, of course assuming that we are doing a full table scan (of fast full index scan) on them – that part is fixed in the execution plan.

And as shown above, predicate offload is not an all-or-nothing thing either. If one predicate can’t be offloaded, then other predicates still can.

However, there’s a catch. If you combine such predicates with ANDs, Oracle can push the offloadable (storage()) predicates to the storage cells, where they will do the early filtering – and the last, non-offloadable (filter()) predicate is applied then on the retrieved dataset in the database layer.

But when you combine such predicates with an OR clause, then there’s a logical problem here. OR has to return rows which match ANY of the predicates (not ALL the predicates), therefore you can’t only return a subset of rows from the storage cells which match the predicate A and hope that this set contains all the rows which would match the (non-offloadable) predicate B as well. To evaluate B, you would still need to go through all the rows, but as B is non-offloadable, this has to be done in the database layer. All rows have to be fetched into the database layer for this.

This explains why the storage() predicate disappears when I chain my query predicates together with an OR instead of the AND:

SELECT * FROM t WHERE line = 9999 AND mod(line,10) = 0 OR f1(line) =9999 Plan hash value: 1601196873 ---------------------------------------------------------------- | Id | Operation | Name | E-Rows | Cost (%CPU)| ---------------------------------------------------------------- | 0 | SELECT STATEMENT | | | 2963 (100)| |* 1 | TABLE ACCESS STORAGE FULL| T | 6353 | 2963 (3)| ---------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(("F1"("LINE")=9999 OR ("LINE"=9999 AND MOD("LINE",10)=0)))

The storage() predicate section above is gone – as Oracle has to retrieve all the rows to the database layer anyway (due to the non-offloadable F1 function used in an OR predicate), it doesn’t make sense to offload the other filters to the storage (and then return the row anyway as it’s needed in the db layer). Makes sense? ;-)

Note that even though the storage() predicates disappeared from the plan, this doesn’t mean that the entire smart scanning has been disabled, the smart scanning can still happen, it’s only the predicate offloading sub-component of the smart scan what is not used. The storage cells can still do the asynchronous prefetching, decompression offloading and projection offloading in these cases.

By the way, it’s all explained in the book!

Ok fellow internals geeks, tomorrow’s going to be another 1-hour hacking session (which will probably take 2 hours) with me. It’s about how Oracle parameters work and all the different types of them too. See the registration link for more info:

• https://www1.gotomeeting.com/register/654456656

Date: 12 april 2012

Time: 9am Pacific (see in other timezones here)

If you can’t attend this – don’t worry, I will be publishing the recording too!

 

Update: By the way, the previous hacking sessions are here:

• http://blip.tv/tanel-poder-oracle-troubleshooting-tv

I am going to run my updated Advanced Oracle Troubleshooting online training again, in May and June! :)

As there’s been so much demand from all over the world (thanks to everyone who’ve sent me mails about it ;-), I’ll actually do it twice, once for the US/European timezones (8am-12pm in California and d 5-9pm in central Europe) and once for the APAC timezones (2pm-6pm in Sydney/Melbourne) on every day. Both events are split into 2 parts, for the US event there’s around a month between the parts, for the APAC event there’s a week betweern Part1 and 2 (so you can get some rest and/or some work done in between too :-)

As I’m now part of Enkitec, our training crew will help me out with all the registration and payment stuff, everything else (the webinar URL, slides, scripts, Q&A and the actual training you will get from me as usual :)

Check out the details here:

• http://blog.tanelpoder.com/seminar/

 

Note to previous AOT attendees – I will schedule a Q&A session soon too!

“See” you soon!

(ok, I think I should finish some of my long-overdue blog articles now ;-)

I just noticed that (finally) in 11.2 this syntax is supported:

SQL> CREATE DATABASE LINK demo_x2  2 CONNECT TO tanel IDENTIFIED BY password  3 USING 'exadb03:1521/DEMO'; Database link created.

This just makes life a bit easier as there’s no need to use the long TNS format entry (or a tnsnames.ora/LDAP alias). It might work in 11.1 too (haven’t tested) but it didn’t work on 10.2.0.4 …

Update: This feature works for dblinks in 10.2 onwards – when I tested it on my 10.2, I got an error initially, but it was because the hostname I used didn’t resolve to an IP. Thanks to Randolf Geist for pointing this out.

In case you didn’t know, the sqlplus supports such an easy connect method since 10g:

tanel@mac02:~$ sqlplus tanel/password@exadb03/DEMO SQL*Plus: Release 10.2.0.4.0 - Production on Mon Mar 5 09:51:27 2012 Copyright (c) 1982, 2007, Oracle. All Rights Reserved. Connected to: Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP, Data Mining and Real Application Testing options SQL>

If you omit the port from the syntax, it defaults to 1521.