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

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

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!)<\/p>\n

“It’s probably worth pointing out that NO TOOL can claim to identify the blocking SID->SQL in such a case as there is no relationship kept in Oracle between locks acquired by users and the SQL that acquired the locks”<\/p><\/blockquote>\n

I\u2019ll try to deal with that point and some other thoughts I had here in a further example. For this example, I decided to suggest how to create a quick table so that you can test this out for yourself.<\/p>\n

SQL> create user testuser identified by testuser\n\u00a0 2\u00a0 default tablespace USERS\n\u00a0 3\u00a0 temporary tablespace TEMP;\n\nUser created.\n\nSQL> grant create session, create table to testuser;\n\nGrant succeeded.\n\nSQL> connect testuser\/testuser\n\nConnected.\n\nSQL> create table test_tab1 as select object_id pk_id, object_name from all_objects;\n\nTable created.<\/pre>\n
As easy as that.<\/p>\n
In the last part<\/a> I showed that the SQL_ID for the last sample of a blocking session immediately before it went idle might not be the SQL statement holding the lock. In that case, it was fairly obvious that it wasn\u2019t because it was a simple query that couldn\u2019t have been responsible. However, it\u2019s likely to be even more confusing if the SQL_ID captured by the ASH sample *looks* like it\u2019s responsible, but isn\u2019t, and the previous example didn’t illustrate that clearly.<\/p>\n
Session 1 \u2013 Connected as TESTUSER<\/strong><\/p>\n
SQL> select pk_id, object_name from test_tab1 order by pk_id desc for update;\n\n<Trimmed>\n\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 890 DBMS_STANDARD\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 889 DBMS_STANDARD\n\n\u00a0\u00a0\u00a0\u00a0 PK_ID OBJECT_NAME\n---------- ------------------------------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 887 STANDARD\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 886 RE$NV_LIST\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 605 MAP_OBJECT\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 319 STMT_AUDIT_OPTION_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 317 STMT_AUDIT_OPTION_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 316 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 314 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 311 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 259 DUAL\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 258 DUAL\n\n4477 rows selected.\n\nSQL> rollback;\n\nRollback complete.\n\nSQL> select pk_id from test_tab1 where object_name='SYSTEM_PRIVILEGE_MAP' for update;\n\n\u00a0\u00a0\u00a0\u00a0 PK_ID\n----------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 311\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313\n\nSQL> rollback;\n\nRollback complete.\n\nSQL> select pk_id from test_tab1 where pk_id=313 for update;\n\n\u00a0\u00a0\u00a0\u00a0 PK_ID\n----------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313\n\nSQL><\/pre>\n
So session 1 has executed three different queries, all of which lock one or more rows including the row with PK_ID=313, has rolled back the first two (releasing the locks) and has just that row locked now.<\/p>\n
Session 2 \u2013 Connected as TESTUSER<\/strong><\/p>\n
SQL> select pk_id from test_tab1 where pk_id=313 for update;<\/pre>\n
Session 2 hangs, waiting for the lock.<\/p>\n
Session 1 \u2013 Connected as TESTUSER<\/strong><\/p>\n
SQL> rollback;\n\nRollback complete.<\/pre>\n
So the lock is released and session 2 acquires the lock and then releases it<\/p>\n
Session 2 \u2013 Connected as Testuser<\/strong><\/p>\n
\u00a0\u00a0\u00a0\u00a0 PK_ID\n----------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313\n\nSQL> rollback;\n\nRollback complete.<\/pre>\n
OK, time to look at the ASH data for the last two minutes for TESTUSER sessions. (Note that I have added each session\u2019s serial# to the query. Graham Wood corrected a statement I made in the last post \u2026<\/p>\n
\u201cwho is to say that that session 148 is the same session as the blocking session 148 and not an earlier session that has disconnected?\u201d<\/p><\/blockquote>\n
\u2026 by pointing out that session_serial# would allow me to differentiate between different sessions where SID=148. I\u2019ve updated the previous post to that effect.)<\/p>\n
break on MY_TIME\ncolumn my_sid format 999\ncolumn my_ser format 99999\ncolumn my_state format a30\ncolumn my_blkr format 999\nselect to_char(a.sample_time, 'HH24:MI:SS') MY_TIME,a.session_id MY_SID,a.session_serial# MY_SER,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 DECODE(a.session_state, 'WAITING' ,a.event, a.session_state) MY_STATE,a.xid, a.sql_id,\n        a.blocking_session MY_BLKR\nfrom v$active_session_history a, dba_users u\nwhere u.user_id = a.user_id\nand u.username = 'TESTUSER'\nand a.sample_time > SYSTIMESTAMP-(2\/1440);\n\nMY_TIME\u00a0 MY_SID MY_SER MY_STATE\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 SQL_ID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 MY_BLKR\n-------- ------ ------ ------------------------------ ---------------- ------------- -------\n12:53:01\u00a0\u00a0\u00a0 300\u00a0\u00a0 2739 enq: TX - row lock contention\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 2pa7rnqf65gj3\u00a0\u00a0\u00a0\u00a0 304\n12:53:00\u00a0\u00a0\u00a0 300\u00a0\u00a0 2739 enq: TX - row lock contention\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 2pa7rnqf65gj3\u00a0\u00a0\u00a0\u00a0 304\n12:52:59\u00a0\u00a0\u00a0 300\u00a0\u00a0 2739 enq: TX - row lock contention\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 2pa7rnqf65gj3\u00a0\u00a0\u00a0\u00a0 304\n12:52:50\u00a0\u00a0\u00a0 304\u00a0\u00a0 1445 ON CPU\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0006000E0000884D 95k0s60jznz76<\/pre>\n
So what statement is SQL_ID \u201895k0s60jznz76\u2019?<\/p>\n
SQL> select sql_text from v$sql where sql_id='95k0s60jznz76';\n\nSQL_TEXT\n-----------------------------------------------------------------------------\nselect pk_id, object_name from test_tab1 order by pk_id desc for update<\/pre>\n
Let\u2019s face it, if you were to look at this data, how likely is it that you would think that that statement was responsible for blocking session 2, when it wasn’t?<\/p>\n","protected":false},"excerpt":{"rendered":"
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 NO TOOL can claim… Continue reading Diagnosing Locking Problems using ASH \u2013 Part 4<\/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-1481","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1017,"url":"http:\/\/orcldoug.com\/blog\/2006\/07\/13\/alter-table-move-and-table-stats\/","url_meta":{"origin":1481,"position":0},"title":"alter table … move and table stats","date":"July 13, 2006","format":false,"excerpt":"Howard Rogers left a comment on my last blog, showing an example of using alter table ... move on a 10gR2 database on Linux. In his example, unlike mine, the table rebuild did not nullify the table's statistics. I admit I was surprised myself when I ran my example yesterday\u2026","rel":"","context":"With 4 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":999,"url":"http:\/\/orcldoug.com\/blog\/2012\/06\/18\/saving-optimiser-stats-9i\/","url_meta":{"origin":1481,"position":1},"title":"Saving Optimiser Stats – 9i","date":"June 18, 2012","format":false,"excerpt":"In a recent blog I described how a mis-timed optimiser statistics collection job led to a bad execution plan for one of the SQL statements in a regular batch jobIt's no coincidence that we were already in the process of implementing a change to our stats collection period to retain\u2026","rel":"","context":"With 4 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1044,"url":"http:\/\/orcldoug.com\/blog\/2006\/08\/04\/tracing-session-activity-over-a-remote-database-link\/","url_meta":{"origin":1481,"position":2},"title":"Tracing session activity over a remote database link","date":"August 4, 2006","format":false,"excerpt":"Yesterday someone asked me how to trace a session that selects from a view in a remote database via a link. If they activated the trace on the local instance, they wouldn't see the bulk of the work which was happening on the remote instance - just a bunch of\u2026","rel":"","context":"With 2 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1637,"url":"http:\/\/orcldoug.com\/blog\/2013\/05\/15\/statistics-on-partitioned-tables-part-6e-copy_table_stats-bug\/","url_meta":{"origin":1481,"position":3},"title":"Statistics on Partitioned Tables – Part 6e – COPY_TABLE_STATS – Bug","date":"May 15, 2013","format":false,"excerpt":"I'd bet regular readers might have guessed I'd never get back to the stats series, particularly given my extremely limited output this year Well, here goes ... The theme of this post is already covered in the paper and the presentation, so if you've read either of those, then you\u2026","rel":"","context":"With 2 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1491,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/23\/diagnosing-locking-problems-using-ashlogminer-part-8\/","url_meta":{"origin":1481,"position":4},"title":"Diagnosing Locking Problems using ASH\/LogMiner \u2013 Part 8","date":"April 23, 2009","format":false,"excerpt":"So what about those SELECT FOR UPDATEs?I know that they\u2019ll generate redo entries and so something should appear in both log file dumps and the LogMiner output, but what exactly will appear? (This is all on Oracle 10.2.0.4)For this post I\u2019ll go back to the example from Part 4, where\u2026","rel":"","context":"With 4 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1062,"url":"http:\/\/orcldoug.com\/blog\/2006\/08\/21\/resumable-storage-allocation\/","url_meta":{"origin":1481,"position":5},"title":"Resumable Storage Allocation","date":"August 21, 2006","format":false,"excerpt":"At the moment I'm writing a short 9i\/10g New Features seminar for the developers at work. The idea is to run through lots of new features very quickly to see if anything lights their candle and they can then go off and investigate further afterwards.It occurred to me while I\u2026","rel":"","context":"With 9 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1481","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=1481"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1481\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1481"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1481"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1481"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}