{"id":1477,"date":"2009-03-30T12:00:00","date_gmt":"2009-03-30T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1477"},"modified":"2009-03-30T12:00:00","modified_gmt":"2009-03-30T12:00:00","slug":"diagnosing-locking-problems-using-ash-part-1","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2009\/03\/30\/diagnosing-locking-problems-using-ash-part-1\/","title":{"rendered":"Diagnosing Locking Problems using ASH – Part 1"},"content":{"rendered":"

Some features in this post require a Diagnostics Pack license.<\/em><\/p>\n

There are few better illustrations of the utility of ASH data than the ability to detect and diagnose locking problems*<\/sup>, even after they’ve occurred. Because ASH is sampling all active sessions all of the time, you should have information both for the blocked and blocking sessions, even when problems are first reported after they have disappeared and the sessions have disconnected. This has proved very useful to me in solving several production performance problems in the past, so I usually try to demonstrate it during the course.<\/p>\n

Something cropped up when one of the demos went wrong last week and it took me a minute to work out what the problem was. I made a simple mistake in the way I approached the demo, but I decided to blog about it because I think it reinforces the nature and inherent limitations of ASH data.<\/p>\n

This is a recreation of the demo, which captures the gist of what went ‘wrong’.<\/p>\n

Session 1 – logged in as TESTUSER<\/strong><\/p>\n

TESTUSER@TEST1020> select pk_id from test_tab1 where rownum=1 for update;\n\n\u00a0\u00a0\u00a0\u00a0 PK_ID\n----------\n\u00a0\u00a0\u00a0\u00a0\u00a0 4051<\/pre>\n
Session 1 holds a lock on that row and I’ll use the PK_ID that was returned from the query to make sure I try to lock the same row in the next session.<\/p>\n
Session 2 – logged in as TESTUSER<\/strong><\/p>\n
TESTUSER@TEST1020> select pk_id from test_tab1 where pk_id=4051 for update;<\/pre>\n
Session 2 hangs, waiting for session 1 to release the lock<\/p>\n
Session 1 – commits, to release the lock<\/strong><\/p>\n
TESTUSER@TEST1020> commit;\n\nCommit complete.<\/pre>\n
Session 2 – Is now able to acquire the lock, so locks the row and returns the result<\/strong><\/strong><\/p>\n
\u00a0\u00a0\u00a0\u00a0 PK_ID\n----------\n\u00a0\u00a0\u00a0\u00a0\u00a0 4051<\/pre>\n
So I’ve just created ‘a locking problem’ that occurred in the past but has been resolved now. At this point, there are a few different things we could look at. In last week’s class I dived straight into the contents of V$ACTIVE_SESSION_HISTORY at the command line but I’ll take the GUI approach first here. Here is how the Top Activity screen in DB\/Grid Control looks. (Click on the thumbnails to see the full-sized images)<\/p>\n
\"\"<\/a><\/p>\n
The period of the test is highlighted and I can see the spike for one active session, which is reflected in the Top Sessions panel (Session 137 is responsible for most of the activity) and I can see from the Top SQL panel that a single SQL statement is responsible for most of the activity. The majority of samples are waiting on “Application” events, with some “User I\/O” as well. Looking at the chart, I can see that the User I\/O activity followed the Application waits.<\/p>\n
If I drill down into the Application events they are all “enq: TX – row lock contention”, all associated with the same Session and SQL statement. (Note the more descriptive 10g event description, rather than “enqueue” in previous versions.)<\/p>\n
\"\"<\/a><\/p>\n
Next I’ll drill down into the SQL statement.<\/p>\n
\"\"<\/a><\/p>\n
As well as the lock waits followed by db file scattered reads, I can see the SQL statement is the one I ran in session 2.<\/p>\n
Next I’ll drill down into the Session details for the blocked session and we’ll see the first sign of limitations.<\/p>\n
\"\"<\/a><\/p>\n
On the Blocking Tree tab, I find ‘No sessions found to be currently blocking other sessions”. That’s true now because Session 1 released the lock and Session 2 (SID 137) was able to acquire it, but for the period of time the ASH data covers, there was a session blocking this one.<\/p>\n
Note that if I had run this demo *before* Session 1 commited, this screen would have highlighted the problem, like this.<\/p>\n
\"\"<\/a><\/p>\n
This was taken from another run of the test, but it should be obvious that the idle Session 1 (SID 150) is blocking Session 2 (SID 147) and that there’s a handly “Kill Session” button! (Actually, that “Idle” is a giveaway to what’s coming next.) <\/p>\n
I can look at the ASH data for the blocked session in more detail by selecting the “Activity” tab and then changing the view to “Show Raw Data”. In reverse time order (the way ASH data is returned if you don’t order it), it’s clear that there were db file scattered reads against TESTUSER.TEST_TAB1, preceded by those lock waits.<\/p>\n
\"\"<\/a><\/p>\n
But that’s only showing the ASH data for one session and doesn’t include the useful BLOCKING_SESSION% columns that help diagnose locking problems, so in the next part I’ll switch to looking at the raw data in V$ACTIVE_SESSION_HISTORY.<\/strong><\/p>\n
*<\/sup>Why am I still seeing locking problems? I think it’s because I often have to support Third-Party “Database-independent” (yuck!) applications, some of which insist on implementing their own locking mechanisms. Sigh.<\/p>\n","protected":false},"excerpt":{"rendered":"
Some features in this post require a Diagnostics Pack license. There are few better illustrations of the utility of ASH data than the ability to detect and diagnose locking problems*, even after they’ve occurred. Because ASH is sampling all active sessions all of the time, you should have information both for the blocked and blocking… Continue reading Diagnosing Locking Problems using ASH – Part 1<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[],"class_list":["post-1477","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1480,"url":"http:\/\/orcldoug.com\/blog\/2009\/03\/31\/diagnosing-locking-problems-using-ash-part-3\/","url_meta":{"origin":1477,"position":0},"title":"Diagnosing Locking Problems using ASH – Part 3","date":"March 31, 2009","format":false,"excerpt":"Some features in this post require a Diagnostics Pack license.In the last part I described a locking scenario where the blocking session had only executed one SQL statement that was quick enough to avoid being sampled by ASH and is now inactive. As a result, there is no ASH data\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1478,"url":"http:\/\/orcldoug.com\/blog\/2009\/03\/30\/diagnosing-locking-problems-using-ash-part-2\/","url_meta":{"origin":1477,"position":1},"title":"Diagnosing Locking Problems using ASH – Part 2","date":"March 30, 2009","format":false,"excerpt":"Some features in this post require a Diagnostics Pack license.I tried the graphical approach to tracking down the root cause of a locking problem in the last part. Now let's look at the underlying ASH data. I ran the same test after bouncing my test instance to start from a\u2026","rel":"","context":"With 3 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1487,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/20\/diagnosing-locking-problems-using-ash-part-6\/","url_meta":{"origin":1477,"position":2},"title":"Diagnosing Locking Problems using ASH \u2013 Part 6","date":"April 20, 2009","format":false,"excerpt":"\"Toto, I've a feeling we're not in Kansas any more.\"What started as a simple write-up of a course demo gone wrong (or right, depending the way you look at these things) has grown arms and legs and staggered away from the original intention to talk about ASH. so I thought\u2026","rel":"","context":"With 1 comment","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1481,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/09\/diagnosing-locking-problems-using-ash-part-4\/","url_meta":{"origin":1477,"position":3},"title":"Diagnosing Locking Problems using ASH \u2013 Part 4","date":"April 9, 2009","format":false,"excerpt":"Some features in this post require a Diagnostics Pack license.No sooner had I finished part 3 with some conclusions than I thought of another example I should have included and then someone else made a comment in an email which suggested another. (Thanks, JB!) \"It's probably worth pointing out that\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1484,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/17\/diagnosing-locking-problems-using-ash-part-5\/","url_meta":{"origin":1477,"position":4},"title":"Diagnosing Locking Problems using ASH \u2013 Part 5","date":"April 17, 2009","format":false,"excerpt":"... and so it continues.Coincidentally, the subject of tracking down locking problems after they occurred cropped up on the Oak Table mailing list just after the last post. Several suggestions were offered but I think the nearest and most detailed suggestion was that proposed by Kyle Hailey, ex-Oracle and now\u2026","rel":"","context":"With 5 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1669,"url":"http:\/\/orcldoug.com\/blog\/2012\/01\/10\/ukoug-2011-ash-outliers\/","url_meta":{"origin":1477,"position":5},"title":"UKOUG 2011 – Ash Outliers","date":"January 10, 2012","format":false,"excerpt":"My final UKOUG 2011 post is about another of my favourite presentations -\u00a0 \"ASH Outliers: Detecting Unusual Events in Active Session History\" by John Beresniewicz. (JB for short, but Marco Gralike made a fairly good stab at pronouncing his surname correctly during the introduction.)I'd been looking forward to this presentation\u2026","rel":"","context":"With 11 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1477","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/comments?post=1477"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1477\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1477"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1477"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1477"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}