Doug's Oracle Blog (Entries tagged as ASH)http://oracledoug.com/serendipity/
enSerendipity 1.5.2 - http://www.s9y.org/Doug BurnsDoug BurnsMon, 04 Oct 2010 12:25:31 GMThttp://oracledoug.com/serendipity/templates/default/img/s9y_banner_small.pngRSS: Doug's Oracle Blog - http://oracledoug.com/serendipity/
10021Network Events in ASHhttp://oracledoug.com/serendipity/index.php?/archives/1614-Network-Events-in-ASH.html
http://oracledoug.com/serendipity/index.php?/archives/1614-Network-Events-in-ASH.html#commentshttp://oracledoug.com/serendipity/wfwcomment.php?cid=16143http://oracledoug.com/serendipity/rss.php?version=2.0&type=comments&cid=1614dougburns@yahoo.com (Doug Burns)
<em>Note - using ASH and the Top Activity screen require the use of the Diagnostics Pack License.</em><br /><br />This post was prompted by yet another performance problem identified using
pretty pictures and Active Session History data. Although, as you'll see, some
pretty old-fashioned tools played their part too!<br /><br />ASH entries only exist for certain SQL*Net events. As usual, I think the
design is very successful as long as you have a basic understanding of how ASH
works.<br /><br />The events all fall into one of three wait classes - Application, Network
and Idle. <br /><br />
<pre>SQL&gt; select wait_class, name from v$event_name where name like 'SQL*Net%' order by 1, 2;
WAIT_CLASS&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; NAME
-------------------- ----------------------------------------
Application&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net break/reset to client
Application&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net break/reset to dblink
Idle&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net message from client
Idle&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net vector message from client
Idle&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net vector message from dblink
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net message from dblink
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net message to client
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net message to dblink
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net more data from client
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net more data from dblink
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net more data to client
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net more data to dblink
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net vector data from client
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net vector data from dblink
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net vector data to client
Network&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SQL*Net vector data to dblink
16 rows selected.
</pre><br />Hopefully that immediately dismisses the suggestion I've heard a few times that ASH/Top Activity ignores SQL*Net events. However, there <em>are</em> some events that are classed as Idle here that will not be captured in ASH data and will therefore not appear in the Top Activity screen. (In fact, even if you were to set the _ash_sample_all parameter you would not see these events in the Top Activity screen, even though ASH would contain entries for them. There is an additional filter applied to the data before it's displayed. In any case, I would *not* recommend setting _ash_sample_all except for fun.)<br /><br />The most contentious of these is probably
SQL*Net message from client. This event indicates that the Oracle server is
waiting for the client to&#160; do something. If the client is a user session, Oracle
is waiting for the user to do something - perhaps someone has a sql*plus session open that they're doing nothing with or they are filling in an application screen with data? From an Oracle perspective that session
is Idle and there isn't much we can do to tune it, including the waits would heavily skew the data we're using for our analysis and, because events in the Idle
class are specifically excluded from both ASH data and the OEM performance
pages,&#160; such activity won't appear. That seems sensible to me.<br /><br />However, if the client is actually an application server,
those supposedly idle events can tell us something about end-to-end system
performance. <a href="http://oracledoug.com/serendipity/index.php?/archives/893-Another-10046-Success.html">This blog post</a> describes one real life situation where that event
helped me identify the performance problem.<br /><br />Back to the problem at hand. Sadly, in the midst of a a very chaotic work situation, I didn't manage to grab any of the graphs in question but we had a persistent problem with our critical batch processes spending time waiting on 'SQL*Net more data from client', which showed up very clearly as network class waits. <br /><br />Now there are a number of reasons why this might be happening. Just a couple off the top of my head<br /><br />1) There is a performance problem with the application server so Oracle is expecting more data to arrive more quickly than the app server can deliver it.<br /><br />2) A network problem is affecting the delivery speed.<br /><br />Although the issue here turned out to be number 2, I suppose the true underlying issue is that this application is insanely 'chatty' and uses very frequent round trips to deliver data. Maybe the application design could be improved first?<br /><br />Ultimately we enabled Extended Tracing on the relevant sessions and confirmed that, yes, the sessions were spending most of their time waiting for the next batch of data and also how long these waits were. In practise, I'm not sure how much value the trace files added in this particular case. In fact, I think this is an excellent example of the underlying beauty of the sampling approach. As an event became *slower* it appeared *more often* in the samples and we had plenty of examples of how long some of the waits were. (But only some - probably the longest ones.)<br /><br />How did we solve this mysterious problem? With two very useful tools<br /><br />- ping/tracert. I simply went on to the app server, pinged the db server and confirmed that the response time (from my memory) was in the range of 70-80 milliseconds - far higher than I would expect. One of the Java developers then ran a trace route to the server which highlighted that network performance was great until we hit the db server. It turned out that one of the network interface cards had auto-negotiated down to 100M/s and this was the root cause - easily fixed. Sometimes old-fashioned and simple tools are all that you need, once you know where you should focus your attention (and ASH is great at focussing attention in the right place).<br /><br />- The next tool is one of the reasons I wanted to write this post. What made me try ping? Whilst I would have got there eventually, I thought I would try my performance optimisation secret weapon! One just for the database wizards! Something I've been keeping an eye on is Oracle Support's attempt to give people a methodical approach to solving performance issues via the Oracle Performance Diagnostic Guide on My Oracle Support - Note ID 390374.1. There are several guides on that landing page but here is the link to the <a href="https://support.oracle.com/CSP/main/article?cmd=show&amp;type=ATT&amp;id=390374.1:OPDG_SD_pdf">Slow Performance PDF</a>. (You'll need an account to be able to access this.) This is an example of the kind of advice there. (Note that this is for SQL*Net message from client, but you would tend to get most events together anyway and there's similar advice for more data from client.)<br /><em><br /></em>
<blockquote><em>&quot;Cause Identified: Slow network limiting the response time between client and database.</em><br /><em>The network is saturated and this is limiting the ability of the client and database to communicate with each other.</em><br /><em>Cause Justification</em><br /><em>TKProf:</em><br /><em>1. SQL*Net message from client waits are a large part of the overall time (see the overall summary</em><br /><em>section)</em><br /><em>2. Array operations are used. This is seen when there are more than 5 rows per execution on average (divide total rows by total execution calls for both recursive and non-recursive calls)</em><br /><em><strong>3. The average time for a ping is about equal to twice the average time for a SQL*Net message from client wait and this time is more than a few milliseconds. This indicates that most of the client time is spent in the network.</strong>&quot;</em><br /></blockquote><br />I've been loathe to mention this document until now because it looks like a work in progress (albeit not updated since the start of 2009), isn't perfect, has gaps and I can imagine a number of my peers taking issue with some of the content. But for something to aid learning if you're not naturally great at solving performance problems, I can think of much worse starting places. <br /><br />In the end, what could have been a really tricky performance problem (and might have taken a while to notice) was apparent with a brief glance at OEM and we could then follow up by applying the right analysis tools to the problem.<br /><br />To finish off, when I searched Google for any examples of 'SQL*Net more data from client', one of the first results that cropped up was <a href="http://www.oreillynet.com/pub/a/network/excerpt/optimizing_oracle_chap12/">a chapter from one of my favourite books</a> - 'Optimising Oracle Performance' by Cary Millsap and Jeff Holt. Well worth a read ....<br />
Sun, 03 Oct 2010 13:51:17 +0100http://oracledoug.com/serendipity/index.php?/archives/1614-guid.htmlashawrgrid controltime mattersAlternative Pictures Demohttp://oracledoug.com/serendipity/index.php?/archives/1613-Alternative-Pictures-Demo.html
http://oracledoug.com/serendipity/index.php?/archives/1613-Alternative-Pictures-Demo.html#commentshttp://oracledoug.com/serendipity/wfwcomment.php?cid=16130http://oracledoug.com/serendipity/rss.php?version=2.0&type=comments&cid=1613dougburns@yahoo.com (Doug Burns)
<em>Note - features in this post require the Diagnostics Pack license</em><br /><br />Not long after I'd finished <a href="http://oracledoug.com/serendipity/index.php?/archives/1612-That-Pictures-demo-in-full.html">the last post</a>, I realised I could reinforce the points I was making with a quick post showing another one of the example tests supplied with Swingbench - the Calling Circle (CC) application. Like the Sales Order Entry application, CC is a mixed read/write test consisting of small transactions. As always, there's more information at <a href="http://dominicgiles.com/swingbench.html">Dominic's website</a>.<br /><br />One of the main differences to the SOE test is that the CC test consumes data so you need to generate a new set of data before each test using the supplied ccwizard utility. I won't show you the entire workflow here but enough to give you a flavour of the process. The utility is the same one used to create the necessary CC schema in the first place but the option I'm looking for here is &quot;Generate Data for Benchmark Run&quot;.<br /><br /><!-- s9ymdb:314 --><img height="403" width="594" class="serendipity_image_center" src="http://oracledoug.com/serendipity/uploads/190910_1.png" alt="" /><br /><br />I'd already decided that my CC schema is populated with data for 1 million customers when I created it so I just need to specify the number of transactions the next test will be for. I happen to know that on my particular configuration, a 1000 transaction test will take around 5 minutes to run.<br /><br /><!-- s9ymdb:315 --><img height="402" width="595" src="http://oracledoug.com/serendipity/uploads/190910_2.png" class="serendipity_image_center" alt="" /><br /><br />I ran the test twice. I've highlighted the first run here in the Top Activity page.<br /><br /><!-- s9ymdb:316 --><img height="350" width="640" src="http://oracledoug.com/serendipity/uploads/190910_3.png" class="serendipity_image_center" alt="" /><br /><br />It should be clear that CC suffers significant log file sync waits on my particular test platform, just like the SOE test. Therefore I'll regenerate the test data set, enable asynchronous commits and re-run the test. Here I've highlighted the second test run.<br /><br /><!-- s9ymdb:317 --><img height="350" width="640" src="http://oracledoug.com/serendipity/uploads/190910_4.png" class="serendipity_image_center" alt="" /><br /><br />As well as seeing a similar change in the activity profile according to the ASH samples (the log file sync activity has disappeared as has the LGWR System I/O), there's a significant difference to the SOE test. Because this test run is based on a specific workload volume, as defined by the size of the test data, rather than a fixed time period, the second test run completed more quickly than the first run. The activity only fills the 5 minute activity bar partially, rather than the first test which filled the whole bar.<br /><br />If you test a specific and limited workload volume it is much clearer from the Top Activity page which test is processing transactions more quickly, based on the Time axis. That's why I didn't pick this example the first time - it's too obvious what's going on!<br />
Sun, 19 Sep 2010 20:39:34 +0100http://oracledoug.com/serendipity/index.php?/archives/1613-guid.htmlashawrgrid controlswingbenchtime mattersThat Pictures demo in fullhttp://oracledoug.com/serendipity/index.php?/archives/1612-That-Pictures-demo-in-full.html
http://oracledoug.com/serendipity/index.php?/archives/1612-That-Pictures-demo-in-full.html#commentshttp://oracledoug.com/serendipity/wfwcomment.php?cid=16126http://oracledoug.com/serendipity/rss.php?version=2.0&type=comments&cid=1612dougburns@yahoo.com (Doug Burns)
<em>Note - features in this post require the Diagnostics Pack license<br /><br /></em>With so many potential technical posts in my pile, it was initially difficult to decide where to start again but I figured I should avoid the stats series until I'm back into the swing of things <img src="http://oracledoug.com/serendipity/templates/default/img/emoticons/wink.png" alt=";-)" style="display: inline; vertical-align: bottom;" class="emoticon" /> Instead I decided to fulfill a commitment I made to myself (and others, whether they knew about it or not) almost three months ago.<br /><br />When I gave <a href="http://oracledoug.com/serendipity/index.php?/archives/1607-A-Good-Weekend.html">the evening demo session in the Amis offices</a> I think the 2 hours went pretty well but, as usual with the OEM presentations, I got a little carried away and didn't conclude the demo properly. (This is also the demo I *would* have done at Hotsos last year if the damn thing had worked first time <img src="http://oracledoug.com/serendipity/templates/default/img/emoticons/wink.png" alt=";-)" style="display: inline; vertical-align: bottom;" class="emoticon" />) It was a shame because as well as showing the neat and useful side of OEM Performance Pages, it also illustrates one of the common pitfalls in interpreting what the graphs are showing you.<br /><br />I began by running a 4 concurrent user Sales Order Entry (SOE) test using <a href="http://dominicgiles.com/swingbench.html">Dominic Giles' Swingbench utility</a>. I won't got into the details of the SOE test because I don't think it's particularly relevant here but you can always download and/or read about Swingbench for yourself at Dominics website.<br /><br />I ran the test for a fixed period of 5 minutes using no think-time delay.<br /><br /><!-- s9ymdb:303 --><!-- s9ymdb:307 --><img height="425" width="250" class="serendipity_image_center" src="http://oracledoug.com/serendipity/uploads/pic_demo8.png" alt="" /><br /><br /><br />Using the capability to look at ASH data in the recent past, the OEM Top Activity page looks like this.<br /><br /><!-- s9ymdb:308 --><img height="640" width="640" class="serendipity_image_center" src="http://oracledoug.com/serendipity/uploads/pic_demo9.png" alt="" /><br /><br /><br />- There was a fairly consistent average of 4-5 active sessions over the 5 minutes period and, looking at the Top Sessions panel in the bottom right of the screen, these were four SOE sessions of similar activity levels and the LGWR process. <br /><br />- The majority of time was spent on User I/O, System I/O and Commit Wait Class activity, with a little CPU.<br /><br />- Three PL/SQL blocks were responsible for most of the Commit activity.<br /><br />- The LGWR process was responsible for most of the System I/O activity.<br /><br />I'll leave it there for now and won't drill down into any more detail. <br /><br />In terms of optimising the performance of this test, what might I consider doing? <br /><br />The most important aspect is to optimise the application to reduce the resource consumption to the minimum required to achieve our objectives. There's a whole bunch of User I/O activity that could perhaps be eliminated? But I'm going to ask you to accept the big assumption here that this application has been optimised and that I'm just using a Swingbench test as an illustration of the type of system-wide problem you could see. In that case, my eye is drawn to the Commit activity.<br /><br />When I'm teaching this stuff, I'm usually deliberately simplistic (at least at the end of the process) and highlight that what I'm interested in 'tuning' is whatever most sessions are waiting on according to the ASH samples this screen uses. I used to explain how I'd look for the biggest areas of colour, drill down into those and identify what's going on. Sadly, I later heard that someone (I think it was JB at Oracle*) had already come up with a nifty acronym for this - COBS. Click on the Big Stuff! One day I will come up with a nifty acronym for something too, but you shouldn't hold your breath waiting.<br /><br />So, if I click on the big stuff here, I can see that the Commit Class waits are log file sync. <br /><br /><!-- s9ymdb:309 --><img height="640" width="640" class="serendipity_image_center" src="http://oracledoug.com/serendipity/uploads/pic_demo10.png" alt="" /><br /><br />How might I reduce the time that sessions are waiting for log file sync? Here are a few reasons why the test sessions might be waiting on log file sync more often or for longer than I'd like. <br /><br />- Application design - committing too frequently<br />- CPU starvation<br />- Slow I/O to online redo log files<br /><br />Whether waits are predominantly the result of CPU overload or slow I/O can be determined by looking at the underlying log file parallel write wait times on the LGWR process but that's a bigger subject for another time.<br /><br />You can look into all of these in more depth - and should - but as this is designed to be a fun demo of the pretty pictures (it used to be 'the USB stick demo'), I'll simply try to eliminate that activity and re-run the same test. Here's how Top Activity looks now.<br /><br /><!-- s9ymdb:310 --><img height="640" width="640" src="http://oracledoug.com/serendipity/uploads/pic_demo11.png" class="serendipity_image_center" alt="" /><br /><br />Oh. Maybe that wasn't what you expected? OK, the LGWR activity has disappeared, but it seems the system is almost as busy as it was before but that the main bottleneck is now User I/O activity. That's often the way, though - you eliminate one bottleneck in a system and it just shows up somewhere else. It must be good to get rid of log file sync waits though, right? User I/O seems like more productive work and I've managed to make the LGWR activity disappear completely. <br /><br />But then if you were to look at this graph in terms of <a href="http://www.oracle.com/technetwork/database/features/manageability/diag-techniques-presentation-ow07-128491.pdf">Average Active Sessions or DB Time</a> or (as it's more likely to be expressed) how big that spike looks, the two tests would look similarly busy from a system-wide perspective. They were but the real question is - busy doing *what*? There's some important information missing here and Swingbench is able to provide it. <br /><br /><!-- s9ymdb:311 --><img height="273" width="413" class="serendipity_image_center" src="http://oracledoug.com/serendipity/uploads/pic_demo12.png" alt="" /><br /><br />TotalCompletedTransactions 22,868<br /><br />Mmmm, so I wonder what that value was for the first run?<br /><br /><!-- s9ymdb:312 --><img height="274" width="410" class="serendipity_image_center" src="http://oracledoug.com/serendipity/uploads/pic_demo13.png" alt="" /><br /><br />TotalCompletedTransactions 12,232<br /><br />Woo-hoo! *That's* what I call tuning a benchmark - processing almost twice the number of transactions in the same 5 minute period.<br /><br />So it turns out that the sessions in the database *were* just as busy during the second run (not too surprising seeing as the test has no user think time so keeps hammering the database with as many requests as it can handle) but that they were busy doing the more productive work of reading and processing data rather than just waiting for COMMITs to complete.<br /><br />I raised this issue of DB Time not showing activity details with Graham Wood* at Oracle in relation to a previous blog post. I think he made the point to me that that's why the OEM Performance Home Page is *not* the Top Activity page. If I take a look at that home page, it shows me the same information as the Swingbench results output did, albeit not as clearly<br /><br /><!-- s9ymdb:313 --><img height="300" width="640" class="serendipity_image_center" src="http://oracledoug.com/serendipity/uploads/pic_demo14.png" alt="" /><br /><br /><br />Looking at the Throughput graph, I can see that the second test processesd around double the number of Transactions per second for the same test running on the same system.<br /><br />To wrap up (and be a little defensive) ...<br /><br />- Yes, I could have traced one or more sessions and generated a complete and detailed response time profile that should have lead me to the same conclusion.<br /><br />- Yes, as this is a controlled test environment and I'm the only 'user', AWR/Statspack would have been an even more powerful analysis tool in the right hands.<br /><br />- The Top Activity page is not the most appropriate tool for this job but it is handy for illustrating concepts. <br /><br />- Lest I seem a slavish pictures fan, I'm showing how people might misuse or misundersand ASH/Top Activity. In this case, the Home Performance Page is a much better tool because we're looking at system-wide data and not drilling into session or SQL details.<br /><br />Oh, and what is my Top Secret Magic Silver Bullet Tuning Tip for OLTP-type applications? (only to be used by Advanced Oracle Performance Wizards)<br /><br />
<pre>alter system set commit_write='BATCH, NOWAIT';</pre><br />Done! In fact, why not just use this on all of your systems, just in case people are waiting on log file sync?<br /><br />(Leaves space below for angry responses and my withering humorous retorts)<br /><br />* This is not name-dropping, this is giving due credit to the people who really know what they're talking about<br />
Sun, 12 Sep 2010 22:16:13 +0100http://oracledoug.com/serendipity/index.php?/archives/1612-guid.htmlashawrgrid controlswingbenchtime mattersDiagnosing Locking Problems using ASH/LogMiner – The Endhttp://oracledoug.com/serendipity/index.php?/archives/1495-Diagnosing-Locking-Problems-using-ASHLogMiner-The-End.html
http://oracledoug.com/serendipity/index.php?/archives/1495-Diagnosing-Locking-Problems-using-ASHLogMiner-The-End.html#commentshttp://oracledoug.com/serendipity/wfwcomment.php?cid=14950http://oracledoug.com/serendipity/rss.php?version=2.0&type=comments&cid=1495dougburns@yahoo.com (Doug Burns)
<p>Except&#160;it's not the&#160;end, of course. What I mean is&#160;that I usually agree with&#160;what Miladin Modrakovic said in <a href="http://oraclue.com/2009/04/20/detecting-deadlock-source/#comment-176">one of his comments</a> on his first <a href="http://oraclue.com/2009/04/20/detecting-deadlock-source/">deadlock blog post</a>.<br /><br />&quot;<em>There is always way around.</em>&quot;<br /><br />As I keep saying, there are many different ways of diagnosing locking problems. Which one works best&#160;depends on the situation you're faced with but I don't think there's an 'end' here, a single solution that works well in all circumstances.<br /><br /><em>Currently occurring&#160;problems</em> are easy. There's locking information in V$SESSION, V$TRANSACTION, V$LOCK etc and you can <em>probably</em> track down the SQL statement that's caused the problem.<br /><br /><em>Those in the past</em> are more difficult but, even in difficult cases, you'll often be able to get close enough to work out what's going on, particularly if you combine data from multiple sources - redo entries, ASH samples and AWR showing you what SQL was running when and so on. It becomes more difficult with a SELECT FOR UPDATE and no subsequent UPDATE, though, because the various tools available (e.g. Logminer) don't always return what you'd expect when the data doesn't actually change.<br /><br /><em>If you can recreate the problem or it's an ongoing problem that you expect to reoccur</em>, then you can enable various traces and&#160;have lots of information that will help you solve most real world problems.<br /><br />But the specific challenge here was to see which SQL statement was responsible for a locking problem, after the fact, when you weren't expecting the problem in the first place.<br /><br />I thought I'd give <a href="http://oraclue.com/2009/04/23/detecting-deadlock-source-part-2/">Miladin's most recent post</a>&#160;a try because it&#160;contains another interesting strategy - Flashback queries. Deadlock problems are different, not least because you have the resulting trace file. So his example isn't designed to address what I've been looking at here, but I thought I should give it a try, as suggested by Vlado <a href="http://oracledoug.com/serendipity/index.php?/archives/1491-Diagnosing-Locking-Problems-using-ASHLogMiner-Part-8.html#c6997">here</a>.<br /><br />The example he uses is a deadlock situation caused by updates, but I'll apply it to the specific example I've been using here. Three SELECT FOR UPDATE statements - which one was the blocker? This time I've created TEST_TAB2 with fewer rows, but the rest of the test is the same.</p>
<pre>SQL&gt; create table test_tab2
as select object_id pk_id, object_name from all_objects where object_id &lt; 400;<p></p><p>Table created.</p><p>SQL&gt; select * from test_tab2;</p><p>&#160;&#160;&#160;&#160; PK_ID OBJECT_NAME
---------- ------------------------------
&#160;&#160;&#160;&#160;&#160;&#160; 258 DUAL
&#160;&#160;&#160;&#160;&#160;&#160; 259 DUAL
&#160;&#160;&#160;&#160;&#160;&#160; 311 SYSTEM_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 313 SYSTEM_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 314 TABLE_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 316 TABLE_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 317 STMT_AUDIT_OPTION_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 319 STMT_AUDIT_OPTION_MAP</p><p>8 rows selected.</p><p></p><p></p><p>SQL&gt; @doug1
SQL&gt; column xidusn format 999
SQL&gt; column xidslot format 999
SQL&gt; column xidsqn format 999999
SQL&gt; select pk_id, object_name from test_tab2 order by pk_id desc for update;</p><p>&#160;&#160;&#160;&#160; PK_ID OBJECT_NAME
---------- ------------------------------
&#160;&#160;&#160;&#160;&#160;&#160; 319 STMT_AUDIT_OPTION_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 317 STMT_AUDIT_OPTION_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 316 TABLE_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 314 TABLE_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 313 SYSTEM_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 311 SYSTEM_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 259 DUAL
&#160;&#160;&#160;&#160;&#160;&#160; 258 DUAL</p><p>8 rows selected.</p><p>SQL&gt; select start_time, xid, xidusn, xidslot,
&#160; 2&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')
&#160; 3&#160; from v$transaction
&#160; 4&#160; order by start_time;</p><p>START_TIME&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; XID&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; XIDUSN XIDSLOT&#160; XIDSQN&#160; START_SCN TO_CHAR(STA
-------------------- ---------------- ------ ------- ------- ---------- -----------
05/01/09 11:53:36&#160;&#160;&#160; 0003001F000087AA&#160;&#160;&#160;&#160;&#160; 3&#160;&#160;&#160;&#160;&#160; 31&#160;&#160; 34730&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 0&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 0</p><p>SQL&gt; rollback;</p><p>Rollback complete.</p><p>SQL&gt; select pk_id from test_tab2 where object_name='SYSTEM_PRIVILEGE_MAP' for update;</p><p>&#160;&#160;&#160;&#160; PK_ID
----------
&#160;&#160;&#160;&#160;&#160;&#160; 311
&#160;&#160;&#160;&#160;&#160;&#160; 313</p><p>SQL&gt; select start_time, xid, xidusn, xidslot,
&#160; 2&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')
&#160; 3&#160; from v$transaction
&#160; 4&#160; order by start_time;</p><p>START_TIME&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; XID&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; XIDUSN XIDSLOT&#160; XIDSQN&#160; START_SCN TO_CHAR(STA
-------------------- ---------------- ------ ------- ------- ---------- -----------
05/01/09 11:53:37&#160;&#160;&#160; 0006000500008EEE&#160;&#160;&#160;&#160;&#160; 6&#160;&#160;&#160;&#160;&#160;&#160; 5&#160;&#160; 36590&#160;&#160; 85744191&#160;&#160;&#160;&#160; 51C5A3F</p><p>SQL&gt; rollback;</p><p>Rollback complete.</p><p>SQL&gt; select pk_id from test_tab2 where pk_id=313 for update;</p><p>&#160;&#160;&#160;&#160; PK_ID
----------
&#160;&#160;&#160;&#160;&#160;&#160; 313</p><p>SQL&gt; select start_time, xid, xidusn, xidslot,
&#160; 2&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')
&#160; 3&#160; from v$transaction
&#160; 4&#160; order by start_time;</p><p>START_TIME&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; XID&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; XIDUSN XIDSLOT&#160; XIDSQN&#160; START_SCN TO_CHAR(STA
-------------------- ---------------- ------ ------- ------- ---------- -----------
05/01/09 11:53:37&#160;&#160;&#160; 0002001900008F2E&#160;&#160;&#160;&#160;&#160; 2&#160;&#160;&#160;&#160;&#160; 25&#160;&#160; 36654&#160;&#160; 85744194&#160;&#160;&#160;&#160; 51C5A42</p></pre>
<p><br />So Session 1 has one row locked and will block Session 2.</p>
<pre>SQL&gt; @doug2
SQL&gt; column xidusn format 999
SQL&gt; column xidslot format 999
SQL&gt; column xidsqn format 999999
SQL&gt;
SQL&gt; select pk_id from test_tab2 where pk_id=313 for update;</pre><br />I rollback Session 1<br /><br />
<pre>SQL&gt; rollback;<p></p><p>Rollback complete.</p></pre><br />and Session 2 acquires the lock, then rolls back.<br /><br />
<pre>&#160;&#160;&#160;&#160; PK_ID
----------
&#160;&#160;&#160;&#160;&#160;&#160; 313<p></p><p>SQL&gt;
SQL&gt; select start_time, xid, xidusn, xidslot,
&#160; 2&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')
&#160; 3&#160; from v$transaction
&#160; 4&#160; order by start_time;</p><p>START_TIME&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; XID&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; XIDUSN XIDSLOT&#160; XIDSQN&#160; START_SCN TO_CHAR(STA
-------------------- ---------------- ------ ------- ------- ---------- -----------
05/01/09 11:53:39&#160;&#160;&#160; 00040018000067E3&#160;&#160;&#160;&#160;&#160; 4&#160;&#160;&#160;&#160;&#160; 24&#160;&#160; 26595&#160;&#160; 85744197&#160;&#160;&#160;&#160; 51C5A45</p><p>SQL&gt;
SQL&gt; rollback;</p><p>Rollback complete.</p></pre><br />This is what comes back from Flashback queries.<br /><br />
<pre>SQL&gt; @miladin
SQL&gt; set echo on
SQL&gt;
SQL&gt; SELECT&#160;&#160;&#160;&#160; VERSIONS_XID
&#160; 2&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_STARTTIME
&#160; 3&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_ENDTIME
&#160; 4&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_STARTSCN
&#160; 5&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_ENDSCN
&#160; 6&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_OPERATION
&#160; 7&#160; ,&#160;&#160;&#160;&#160;&#160; pk_id, object_name
&#160; 8&#160; FROM&#160;&#160; testuser.test_tab2 VERSIONS BETWEEN TIMESTAMP MINVALUE AND MAXVALUE
&#160; 9&#160; ORDER&#160; BY VERSIONS_STARTTIME;<p></p><p>VERSIONS_XID
----------------
VERSIONS_STARTTIME
---------------------------------------------------------------------------
VERSIONS_ENDTIME
---------------------------------------------------------------------------
VERSIONS_STARTSCN VERSIONS_ENDSCN V&#160;&#160;&#160;&#160;&#160; PK_ID OBJECT_NAME
----------------- --------------- - ---------- ------------------------------</p><p></p><p>&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 258 DUAL</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 259 DUAL</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 311 SYSTEM_PRIVILEGE_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 319 STMT_AUDIT_OPTION_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 314 TABLE_PRIVILEGE_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 316 TABLE_PRIVILEGE_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 317 STMT_AUDIT_OPTION_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 313 SYSTEM_PRIVILEGE_MAP</p><p>
8 rows selected.</p><p>SQL&gt;
SQL&gt; SELECT * FROM testuser.test_tab2
&#160; 2&#160; AS OF TIMESTAMP (SYSTIMESTAMP - INTERVAL '1' MINUTE);</p><p>&#160;&#160;&#160;&#160; PK_ID OBJECT_NAME
---------- ------------------------------
&#160;&#160;&#160;&#160;&#160;&#160; 258 DUAL
&#160;&#160;&#160;&#160;&#160;&#160; 259 DUAL
&#160;&#160;&#160;&#160;&#160;&#160; 311 SYSTEM_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 313 SYSTEM_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 314 TABLE_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 316 TABLE_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 317 STMT_AUDIT_OPTION_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 319 STMT_AUDIT_OPTION_MAP</p><p>8 rows selected.</p><p>SQL&gt;
SQL&gt; -- Narrow to specific column
SQL&gt;
SQL&gt; SELECT versions_xid XID, versions_startscn START_SCN, versions_endscn END_SCN,
versions_operation OPERATION, object_name
&#160; 2&#160; FROM testuser.test_tab2
&#160; 3&#160; VERSIONS BETWEEN SCN MINVALUE AND MAXVALUE
&#160; 4&#160; WHERE pk_id=313;</p><p>XID&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; START_SCN&#160;&#160;&#160; END_SCN O OBJECT_NAME
---------------- ---------- ---------- - ------------------------------
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; SYSTEM_PRIVILEGE_MAP</p></pre>
<p><br />Not much in other words. To check what I'm doing, I COMMITed the final update from Session 1 (as opposed to rolling it back) and got what I'd hope to see, because there's actually a different committed version of the data.</p>
<pre>SQL&gt; @miladin
SQL&gt; set echo on
SQL&gt;
SQL&gt; SELECT&#160;&#160;&#160;&#160; VERSIONS_XID
&#160; 2&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_STARTTIME
&#160; 3&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_ENDTIME
&#160; 4&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_STARTSCN
&#160; 5&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_ENDSCN
&#160; 6&#160; ,&#160;&#160;&#160;&#160;&#160; VERSIONS_OPERATION
&#160; 7&#160; ,&#160;&#160;&#160;&#160;&#160; pk_id, object_name
&#160; 8&#160; FROM&#160;&#160; testuser.test_tab2 VERSIONS BETWEEN TIMESTAMP MINVALUE AND MAXVALUE
&#160; 9&#160; ORDER&#160; BY VERSIONS_STARTTIME;<p></p><p>VERSIONS_XID
----------------
VERSIONS_STARTTIME
---------------------------------------------------------------------------
VERSIONS_ENDTIME
---------------------------------------------------------------------------
VERSIONS_STARTSCN VERSIONS_ENDSCN V&#160;&#160;&#160;&#160;&#160; PK_ID OBJECT_NAME
----------------- --------------- - ---------- ------------------------------
0002000A00008F4B
01-MAY-09 12.04.39</p><p>&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 85744966&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; U&#160;&#160;&#160;&#160;&#160;&#160;&#160; 313 XID 3</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 259 DUAL</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 311 SYSTEM_PRIVILEGE_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 319 STMT_AUDIT_OPTION_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 314 TABLE_PRIVILEGE_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 316 TABLE_PRIVILEGE_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 317 STMT_AUDIT_OPTION_MAP</p><p></p><p>
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 258 DUAL</p><p></p><p>01-MAY-09 12.04.39
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 85744966&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 313 SYSTEM_PRIVILEGE_MAP</p><p>
9 rows selected.</p><p>SQL&gt;
SQL&gt; SELECT * FROM testuser.test_tab2
&#160; 2&#160; AS OF TIMESTAMP (SYSTIMESTAMP - INTERVAL '1' MINUTE);</p><p>&#160;&#160;&#160;&#160; PK_ID OBJECT_NAME
---------- ------------------------------
&#160;&#160;&#160;&#160;&#160;&#160; 258 DUAL
&#160;&#160;&#160;&#160;&#160;&#160; 259 DUAL
&#160;&#160;&#160;&#160;&#160;&#160; 311 SYSTEM_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 313 SYSTEM_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 314 TABLE_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 316 TABLE_PRIVILEGE_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 317 STMT_AUDIT_OPTION_MAP
&#160;&#160;&#160;&#160;&#160;&#160; 319 STMT_AUDIT_OPTION_MAP</p><p>8 rows selected.</p><p>SQL&gt;
SQL&gt; -- Narrow to specific column
SQL&gt;
SQL&gt; SELECT versions_xid XID, versions_startscn START_SCN, versions_endscn END_SCN,
versions_operation OPERATION, object_name
&#160; 2&#160; FROM testuser.test_tab2
&#160; 3&#160; VERSIONS BETWEEN SCN MINVALUE AND MAXVALUE
&#160; 4&#160; WHERE pk_id=313;</p><p>XID&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; START_SCN&#160;&#160;&#160; END_SCN O OBJECT_NAME
---------------- ---------- ---------- - ------------------------------
0002000A00008F4B&#160;&#160; 85744966&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; U XID 3
&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; 85744966&#160;&#160; SYSTEM_PRIVILEGE_MAP</p></pre><br />So the problem is that although there's some locking information for the SELECT FOR UPDATEs (see previous blog posts) they're difficult to diagnose because there were no changes to the data.<br /><br />Ultimately, I like the way Graham Wood put it in an email, so I asked him if I could quote it here.<br /><br /><em>&quot;I may well have said that it was impossible to get from the V$ tables. The reason that it is impossible is that row locks exist only in the disk blocks, in the form of the ITL. This was a key part of the whole row level locking scheme as it meant that we did not have to maintain and configure a structure to contain lock information that could, at worse need one entry for every row in the database. The ITL cannot be extended to include a SQLID, or at least not without requiring a data migration to the new block structure.</em><em><br /><br /><br />You may well say that tracing will give you the blocking SQL. Well if you happen to be tracing the blocking session from the start of the blocking txn, then it is true that the trace file contains the blocking statement. However there may be many hundreds or thousands of statements in the trace file and there is no method that can tell you which one, even though you might be able to reduce the 'possibles' list by analysis of object access by the various statements.</em><em><br /><br /><br />As for the use of the XID. The XID is useful because it gives a finite limit to which operation may have caused the lock i.e the lock must have been caused by a statement that was in the same txn that the blocking session is in at the time that the&#160; waiter is blocked.&quot;</em><br /><br />There's a gap in the data block and redo data describing the transaction - no SQLID. By using various strategies you might be able to make an educated guess as to the source of the problem, but there's no way to <em>guarantee</em> that you have the correct statement. But with so many different possibilities to get you close to a diagnosis, I'm not sure having the SQLID in there would be very useful&#160;- certainly not worth&#160;amending the ITL&#160;structure.<br /><br />This series of posts is already way out of control, I've got other things I want to post about&#160;and I'm sort of bored&#160;by myself <img src="http://oracledoug.com/serendipity/templates/default/img/emoticons/wink.png" alt=";-)" style="display: inline; vertical-align: bottom;" class="emoticon" /> so, no matter what other approaches crop up, the most I'll be doing is linking to them!
Fri, 01 May 2009 12:30:00 +0100http://oracledoug.com/serendipity/index.php?/archives/1495-guid.htmlASHLockingDiagnosing Locking Problems using ASH/LogMiner – Part 9http://oracledoug.com/serendipity/index.php?/archives/1492-Diagnosing-Locking-Problems-using-ASHLogMiner-Part-9.html
http://oracledoug.com/serendipity/index.php?/archives/1492-Diagnosing-Locking-Problems-using-ASHLogMiner-Part-9.html#commentshttp://oracledoug.com/serendipity/wfwcomment.php?cid=14920http://oracledoug.com/serendipity/rss.php?version=2.0&type=comments&cid=1492dougburns@yahoo.com (Doug Burns)
<p>This time, instead of dumping the contents of the log file for a specific Data Block Address (DBA), as in the last part, I’m going to dump it for a specific operation type – Lock Rows (SELECT FOR UPDATE in this case) – which is part of the Row Operations layer (11) and is the LKR operation (4). This will allow me to eliminate less interesting activity and will include information for blocks other than the specific block that contains the PK_ID=313 row. </p>
<p>&#160;</p>
<pre>SQL&gt; alter system dump logfile '&amp;&amp;my_member'
&#160; 2&#160; layer 11 opcode 4;
old&#160;&#160; 1: alter system dump logfile '&amp;&amp;my_member'
new&#160;&#160; 1: alter system dump logfile '/data/oradata/PPL/redo03.log'<p></p><p>System altered.</p></pre>
<p>&#160;</p>
<p>Next, a quick reminder of the transaction history from the previous tests, that this log file covers.</p>
<p>Transaction ID&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;Session 1 Activity&#160; Transaction ID&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; Session 2 Activity</p>
<p>0003001100008615&#160; Whole Table Locked<br />&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; Locks Released<br />0002000100008DAA&#160; Two Rows Locked<br />&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;Locks Released<br />000900110000891B&#160; PK_ID=313 Locked&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; Waiting to lock PK_ID=313<br />&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; Lock Released&#160;&#160;&#160;&#160;&#160;&#160; 00080005000081D3&#160;&#160;&#160; PK_ID=313 Locked&#160;&#160;&#160;&#160;&#160;&#160;&#160; </p>
<p>Looking at the header (line numbers added by vi), I can see that the dump is restricted to Opcode 11.4.</p>
<p>&#160;</p>
<pre>&#160;&#160;&#160; 19&#160; DUMP OF REDO FROM FILE '/data/oradata/PPL/redo03.log'
&#160;&#160;&#160; 20&#160;&#160; Opcode 11.4 only
&#160;&#160;&#160; 21&#160;&#160; RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff
&#160;&#160;&#160; 22&#160;&#160; SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff
&#160;&#160;&#160; 23&#160;&#160; Times: creation thru eternity</pre>
<p>&#160;</p>
<p>Next I search for ‘xid: ‘ to find the first transaction ID, which brings up the first redo record, all 2214 lines of it! Relax, I’m not going to list it all here, just focus on the first CHANGE record.</p>
<p>&#160;</p>
<pre>&#160;&#160;&#160; 50&#160; REDO RECORD - Thread:1 RBA: 0x002304.00000002.0010 LEN: 0x45b0 VLD: 0x0d
&#160;&#160;&#160; 51&#160; SCN: 0x0000.050dc3e9 SUBSCN:&#160; 1 04/23/2009 09:40:19
&#160;&#160;&#160; 52&#160; CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06125 OBJ:144543 SCN:0x0000.050dc005 SEQ:185 OP:11.4
&#160;&#160;&#160; 53&#160; KTB Redo
&#160;&#160;&#160; 54&#160; op: 0x01&#160; ver: 0x01
&#160;&#160;&#160; 55&#160; op: F&#160; xid:&#160; 0x0003.011.00008615&#160;&#160;&#160; uba: 0x00803aaa.0f30.01
&#160;&#160;&#160; 56&#160; KDO Op code: LKR row dependencies Disabled
&#160;&#160;&#160; 57&#160;&#160;&#160; xtype: XA flags: 0x00000000&#160; bdba: 0x00c06125&#160; hdba: 0x00c06103
&#160;&#160;&#160; 58&#160; itli: 2&#160; ispac: 0&#160; maxfr: 4858
&#160;&#160;&#160; 59&#160; tabn: 0 slot: 183 to: 2</pre>
<p>&#160;</p>
<p>I can see this is a change to a Data Block (Class 1), the Trancation ID is 0x0003.011.00008615 which matches the XID 0003001100008615 from V$TRANSACTION and that it’s a row lock operation. Next up is a 5.2 operation that starts off the new transaction)</p>
<p>&#160;</p>
<pre>&#160;&#160;&#160; 60&#160; CHANGE #2 TYP:0 CLS:21 AFN:2 DBA:0x00800029 OBJ:4294967295 SCN:0x0000.050dc3c0 SEQ:&#160; 1 OP:5.2
&#160;&#160;&#160; 61&#160; ktudh redo: slt: 0x0011 sqn: 0x00008615 flg: 0x000a siz: 108 fbi: 0
&#160;&#160;&#160; 62&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160;&#160; uba: 0x00803aaa.0f30.01&#160;&#160;&#160; pxid:&#160; 0x0000.000.00000000</pre>
<p>&#160;</p>
<p>After that you’ll see tons more 11.4 entries as the various locks are acquired. Next I’ll search for the transaction ID for the second transaction (that locked two rows) by searching for ‘xid:&#160; 0x0002’ (two spaces in that string).</p>
<p>&#160;</p>
<pre>192358&#160; REDO RECORD - Thread:1 RBA: 0x002304.00000ce8.0010 LEN: 0x0238 VLD: 0x0d
192359&#160; SCN: 0x0000.050dc41f SUBSCN:&#160; 1 04/23/2009 09:40:20
192360&#160; CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc411 SEQ:102 OP:11.4
192361&#160; KTB Redo
192362&#160; op: 0x01&#160; ver: 0x01
192363&#160; op: F&#160; xid:&#160; 0x0002.001.00008daa&#160;&#160;&#160; uba: 0x00808827.124c.31
192364&#160; KDO Op code: LKR row dependencies Disabled
192365&#160;&#160;&#160; xtype: XA flags: 0x00000000&#160; bdba: 0x00c06104&#160; hdba: 0x00c06103
192366&#160; itli: 3&#160; ispac: 0&#160; maxfr: 4858
192367&#160; tabn: 0 slot: 2 to: 3</pre>
<p>&#160;</p>
<p>Looking at the line numbers, you can probably see why I didn’t want to show you all of the REDO RECORDs for the first transaction! Checking the transaction ID, that’s the one we’re looking for. While I’m at it, I might as well track down the last two transactions by searching for their xid: </p>
<p>&#160;</p>
<pre>192447&#160; REDO RECORD - Thread:1 RBA: 0x002304.00000cea.0010 LEN: 0x0180 VLD: 0x0d
192448&#160; SCN: 0x0000.050dc423 SUBSCN:&#160; 1 04/23/2009 09:40:25
192449&#160; CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc41f SEQ:&#160; 4 OP:11.4
192450&#160; KTB Redo
192451&#160; op: 0x01&#160; ver: 0x01
192452&#160; op: F&#160; xid:&#160; 0x0009.011.0000891b&#160;&#160;&#160; uba: 0x0081e118.14ee.05
192453&#160; KDO Op code: LKR row dependencies Disabled
192454&#160;&#160;&#160; xtype: XA flags: 0x00000000&#160; bdba: 0x00c06104&#160; hdba: 0x00c06103
192455&#160; itli: 3&#160; ispac: 0&#160; maxfr: 4858
192456&#160; tabn: 0 slot: 3 to: 3<p></p><p>192496&#160; REDO RECORD - Thread:1 RBA: 0x002304.00000cec.0010 LEN: 0x0180 VLD: 0x0d
192497&#160; SCN: 0x0000.050dc428 SUBSCN:&#160; 1 04/23/2009 09:40:34
192498&#160; CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc426 SEQ:&#160; 1 OP:11.4
192499&#160; KTB Redo
192500&#160; op: 0x01&#160; ver: 0x01
192501&#160; op: F&#160; xid:&#160; 0x0008.005.000081d3&#160;&#160;&#160; uba: 0x0081eda9.1058.20
192502&#160; KDO Op code: LKR row dependencies Disabled
192503&#160;&#160;&#160; xtype: XA flags: 0x00000000&#160; bdba: 0x00c06104&#160; hdba: 0x00c06103
192504&#160; itli: 3&#160; ispac: 0&#160; maxfr: 4858
192505&#160; tabn: 0 slot: 3 to: 3</p></pre><br />Yep, they both look right (which is more than can be said for Log Miner’s output!). The fact is that you could probably work out which transaction had locked the rows and the type of work it was doing, but still no nearer finding the offending SQL statement, really.<br /><br />In the next and absolutely definitely last part, I'll have a brief overview of some other suggestions such as <a href="http://oraclue.com/2009/04/23/detecting-deadlock-source-part-2/">Miladin Modrakivic's</a>.
Thu, 30 Apr 2009 14:35:00 +0100http://oracledoug.com/serendipity/index.php?/archives/1492-guid.htmlASHLocking