Investigating Enqueues Burns CPU Cycles

30 03 2011

March 30, 2011

If you take a look at the Oracle Database Performance Tuning Guide, you will find the following SQL statement to help identify the session waiting in an enqueue and the session that currently prevents that session from continuing:

SELECT DECODE(request,0,'Holder: ','Waiter: ') ||
          sid sess, id1, id2, lmode, request, type
   FROM V$LOCK
 WHERE (id1, id2, type) IN (SELECT id1, id2, type FROM V$LOCK WHERE request > 0)
   ORDER BY id1, request; 

If you look closely, you will see that the version of the query that appeared in the 11.1 release of the Performance Tuning Guide differs a little from what appeared in the 9.0.1 Performance Tuning Guide:

SELECT DECODE(request,0,'Holder: ','Waiter: ')||sid sess
     , id1, id2, lmode, request, type
  FROM V$LOCK
 WHERE (id1, id2, type) IN
             (SELECT id1, id2, type FROM V$LOCK WHERE lmode = 0)
 ORDER BY id1, request; 

The above SQL statements (at least the first one) are helpful, but it might be nice to know a little more about the sessions that are involved in the enqueue wait.  So, you might modify the SQL statement like this (feel free to replace SQL_HASH_VALUE with SQL_ID if you are running Oracle Database 10.1 or greater):

SELECT
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.SQL_HASH_VALUE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  L.LMODE,
  L.TYPE,
  L.BLOCK
FROM
  V$LOCK L,
  V$SESSION S
WHERE
  (L.ID1, L.ID2, L.TYPE) IN
  (SELECT
    ID1,
    ID2,
    TYPE
  FROM
    V$LOCK
  WHERE
    REQUEST > 0)
  AND L.SID=S.SID; 

Sometimes helpful is too helpful.  Assume that the above SQL statement is scripted to execute once an hour, once a minute, once a second, or multiple times per second.  What will happen?  Well, you could obtain useful information... but at a cost (we will take a look at that later).  Since we are assuming that the above SQL statement will be scripted, we could possibly use a SQL statement similar to the following, and if any rows are returned we could execute the more useful SQL statement above:

SELECT
  ID1,
  ID2,
  TYPE
FROM
  V$LOCK
WHERE
  REQUEST > 0; 

Another option would be to take advantage of an enhancement added to Oracle Database 10.1 - a couple of additional columns in V$SESSION, specifically the columns BLOCKING_SESSION and BLOCKING_SESSION_STATUS.  With the help of those columns, we could query V$SESSION and then if any rows are returned, use the enhanced version of the above query that returns the lock TYPE.  The SQL statement that would use the two columns from V$SESSION might look like this:

SELECT
  SID,
  BLOCKING_SESSION,
  BLOCKING_SESSION_STATUS
FROM
  V$SESSION
WHERE
  BLOCKING_SESSION IS NOT NULL; 

But now we have a problem.  We have three potential solutions, but no clue which approach will work most efficiently.  We could throw together a PL/SQL loop to help test the performance, but there is a chance that approach will yield performance results that are different from a solution that submits the SQL statements from a client-side application (or script).  But there is a simple solution: create the TEMP_STAT temporary table from the previous article, and then try the following script when several sessions (I used roughly 300) are connected to the database instance (as with previous scripts, replace MyDB, MyUser, and MyPassword with appropriate values:

Const adCmdText = 1
Const adCmdStoredProc = 4
Const adParamInput = 1
Const adVarNumeric = 139
Const adBigInt = 20
Const adDecimal = 14
Const adDouble = 5
Const adInteger = 3
Const adLongVarBinary = 205
Const adNumeric = 131
Const adSingle = 4
Const adSmallInt = 2
Const adTinyInt = 16
Const adUnsignedBigInt = 21
Const adUnsignedInt = 19
Const adUnsignedSmallInt = 18
Const adUnsignedTinyInt = 17
Const adDate = 7
Const adDBDate = 133
Const adDBTimeStamp = 135
Const adDBTime = 134
Const adVarChar = 200
Const adUseClient = 3
Const adOpenKeyset = 1
Const adLockOptimistic = 3

Dim i
Dim lngCntLast
Dim strSQL
Dim snpDataLock1
Dim comDataLock1
Dim snpDataLock2
Dim comDataLock2
Dim snpDataLock3
Dim comDataLock3
Dim comDataInsert
Dim dbDatabase
Dim snpData
Dim objFSO
Dim objFileLog

Dim strDatabase
Dim strUsername
Dim strPassword

Set snpDataLock1 = CreateObject("ADODB.Recordset")
Set comDataLock1 = CreateObject("ADODB.Command")
Set snpDataLock2 = CreateObject("ADODB.Recordset")
Set comDataLock2 = CreateObject("ADODB.Command")
Set snpDataLock3 = CreateObject("ADODB.Recordset")
Set comDataLock3 = CreateObject("ADODB.Command")
Set comDataInsert = CreateObject("ADODB.Command")
Set dbDatabase = CreateObject("ADODB.Connection")
Set snpData = CreateObject("ADODB.Recordset")

strDatabase = "MyDB"
strUsername = "MyUser"
strPassword = "MyPassword"

'Connect to the database
'Oracle connection string
dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";ChunkSize=1000;FetchSize=100;"

dbDatabase.ConnectionTimeout = 40
dbDatabase.CursorLocation = adUseClient
dbDatabase.open

dbDatabase.BeginTrans

With comDataLock1
    strSQL = "SELECT" & vbCrLf
    strSQL = strSQL & "  S.SID," & vbCrLf
    strSQL = strSQL & "  S.USERNAME," & vbCrLf
    strSQL = strSQL & "  S.PROGRAM," & vbCrLf
    strSQL = strSQL & "  S.SQL_HASH_VALUE," & vbCrLf
    strSQL = strSQL & "  L.REQUEST," & vbCrLf
    strSQL = strSQL & "  L.ID1," & vbCrLf
    strSQL = strSQL & "  L.ID2," & vbCrLf
    strSQL = strSQL & "  L.LMODE," & vbCrLf
    strSQL = strSQL & "  L.TYPE," & vbCrLf
    strSQL = strSQL & "  L.BLOCK" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  V$LOCK L," & vbCrLf
    strSQL = strSQL & "  V$SESSION S" & vbCrLf
    strSQL = strSQL & "WHERE" & vbCrLf
    strSQL = strSQL & "  (L.ID1, L.ID2, L.TYPE) IN " & vbCrLf
    strSQL = strSQL & "  (SELECT" & vbCrLf
    strSQL = strSQL & "    ID1," & vbCrLf
    strSQL = strSQL & "    ID2," & vbCrLf
    strSQL = strSQL & "    TYPE" & vbCrLf
    strSQL = strSQL & "  FROM" & vbCrLf
    strSQL = strSQL & "    V$LOCK" & vbCrLf
    strSQL = strSQL & "  WHERE" & vbCrLf
    strSQL = strSQL & "    REQUEST > 0)" & vbCrLf
    strSQL = strSQL & "  AND L.SID=S.SID"

    'Set up the command properties
    .CommandText = strSQL
    .CommandType = adCmdText
    .CommandTimeout = 30

    .ActiveConnection = dbDatabase
End With

With comDataLock2
    strSQL = "SELECT" & vbCrLf
    strSQL = strSQL & "  ID1," & vbCrLf
    strSQL = strSQL & "  ID2," & vbCrLf
    strSQL = strSQL & "  TYPE" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  V$LOCK" & vbCrLf
    strSQL = strSQL & "WHERE" & vbCrLf
    strSQL = strSQL & "  REQUEST > 0"

    'Set up the command properties
    .CommandText = strSQL
    .CommandType = adCmdText
    .CommandTimeout = 30

    .ActiveConnection = dbDatabase
End With

With comDataLock3
    strSQL = "SELECT" & vbCrLf
    strSQL = strSQL & "  SID," & vbCrLf
    strSQL = strSQL & "  BLOCKING_SESSION," & vbCrLf
    strSQL = strSQL & "  BLOCKING_SESSION_STATUS" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  V$SESSION" & vbCrLf
    strSQL = strSQL & "WHERE" & vbCrLf
    strSQL = strSQL & "  BLOCKING_SESSION IS NOT NULL"

    'Set up the command properties
    .CommandText = strSQL
    .CommandType = adCmdText
    .CommandTimeout = 30

    .ActiveConnection = dbDatabase
End With

With comDataInsert
    strSQL = "INSERT INTO TEMP_STAT" & vbCrLf
    strSQL = strSQL & "SELECT" & vbCrLf
    strSQL = strSQL & "  ? CNT," & vbCrLf
    strSQL = strSQL & "  SN.NAME," & vbCrLf
    strSQL = strSQL & "  MS.VALUE" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  V$STATNAME SN," & vbCrLf
    strSQL = strSQL & "  V$MYSTAT MS" & vbCrLf
    strSQL = strSQL & "WHERE" & vbCrLf
    strSQL = strSQL & "  SN.STATISTIC#=MS.STATISTIC#" & vbCrLf
    strSQL = strSQL & "  AND SN.NAME IN (" & vbCrLf
    strSQL = strSQL & "    'CPU used by this session'," & vbCrLf
    strSQL = strSQL & "    'consistent gets'," & vbCrLf
    strSQL = strSQL & "    'parse count (total)'," & vbCrLf
    strSQL = strSQL & "    'DB time')"

    'Set up the command properties
    .CommandText = strSQL
    .CommandType = adCmdText
    .CommandTimeout = 30

    .ActiveConnection = dbDatabase

    .Parameters.Append .CreateParameter("cnt", adNumeric, adParamInput, 8 )
End With

comDataInsert("cnt") = 0
comDataInsert.Execute
'Before
comDataInsert("cnt") = 1
comDataInsert.Execute
For i = 1 To 1000
    Set snpDataLock1 = comDataLock1.Execute

    If Not (snpDataLock1 Is Nothing) Then
        If Not (snpDataLock1.EOF) Then
            'Found one
        Else
            'Did not have a lock
        End If
        snpDataLock1.Close
    End If

    WScript.Sleep 200
Next
'After
comDataInsert("cnt") = 2
comDataInsert.Execute

'Before
comDataInsert("cnt") = 3
comDataInsert.Execute
For i = 1 To 1000
    Set snpDataLock2 = comDataLock2.Execute

    If Not (snpDataLock2 Is Nothing) Then
        If Not (snpDataLock2.EOF) Then
            'Found one
        Else
            'Did not have a lock
        End If
        snpDataLock2.Close
    End If

    WScript.Sleep 200
Next
'After
comDataInsert("cnt") = 4
comDataInsert.Execute

'Before
comDataInsert("cnt") = 5
comDataInsert.Execute
For i = 1 To 1000
    Set snpDataLock3 = comDataLock3.Execute

    If Not (snpDataLock3 Is Nothing) Then
        If Not (snpDataLock3.EOF) Then
            'Found one
        Else
            'Did not have a lock
        End If
        snpDataLock3.Close
    End If

    WScript.Sleep 200
Next
'After
comDataInsert("cnt") = 6
comDataInsert.Execute

strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  TS2.CNT," & vbCrLf
strSQL = strSQL & "  TS2.NAME," & vbCrLf
strSQL = strSQL & "  TS2.VALUE-TS1.VALUE DELTA" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  TEMP_STAT TS1," & vbCrLf
strSQL = strSQL & "  TEMP_STAT TS2" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  TS2.CNT=TS1.CNT+1" & vbCrLf
strSQL = strSQL & "  AND TS2.NAME=TS1.NAME" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  TS2.CNT," & vbCrLf
strSQL = strSQL & "  TS2.NAME"

Set objFSO = CreateObject("Scripting.FileSystemObject")
Set objFileLog = objFSO.CreateTextFile("C:\LockResourceResults.txt", True)

snpData.open strSQL, dbDatabase
lngCntLast = 0
Do While Not snpData.EOF
    If lngCntLast <> CLng(snpData("cnt")) Then
        lngCntLast = CLng(snpData("cnt"))
        Select Case lngCntLast
            Case 2
                objFileLog.Write vbCrLf & "Full Lock Query with BLOCKED and BLOCKER" & vbCrLf

            Case 4
                objFileLog.Write vbCrLf & "Query of V$LOCK" & vbCrLf

            Case 6
                objFileLog.Write vbCrLf & "Query of V$SESSION" & vbCrLf
        End Select
    End If

    Select Case lngCntLast
        Case 2, 4, 6
            objFileLog.Write "  " & CStr(snpData("name")) & "   " & CStr(snpData("delta")) & vbCrLf
    End Select
    snpData.MoveNext
Loop
snpData.Close
objFileLog.Close

dbDatabase.CommitTrans 

The above script executes each of the three possible solutions 1,000 times, pausing 0.2 seconds between each execution.  Once the test is complete, the test results are written to a text file named C:\LockResourceResults.txt.  I executed the above script (at least) three times, and these are the results that I received for three test executions (note that the results from the tests are not necessarily displayed in the order of execution):

Full Lock Query with BLOCKED and BLOCKER
  CPU used by this session   13153
  DB time                    13159
  consistent gets                0
  parse count (total)         1000

Query of V$LOCK
  CPU used by this session    1475
  DB time                     1478
  consistent gets                0
  parse count (total)         1000

Query of V$SESSION
  CPU used by this session      66
  DB time                       66
  consistent gets                0
  parse count (total)         1000 

 

Full Lock Query with BLOCKED and BLOCKER
  CPU used by this session   12526
  DB time                    12531
  consistent gets                0
  parse count (total)         1000

Query of V$LOCK
  CPU used by this session     881
  DB time                      870
  consistent gets                0
  parse count (total)         1000

Query of V$SESSION
  CPU used by this session      17
  DB time                       21
  consistent gets                2
  parse count (total)         1001 

 

Full Lock Query with BLOCKED and BLOCKER
  CPU used by this session   13157
  DB time                    13216
  consistent gets                0
  parse count (total)         1000

Query of V$LOCK
  CPU used by this session    1368
  DB time                     1369
  consistent gets                0
  parse count (total)         1000

Query of V$SESSION
  CPU used by this session     331
  DB time                      340
  consistent gets                0
  parse count (total)         1000 

Just looking at the first resultset of results, 131.53 CPU seconds consumed for the first approach compared to 14.75 CPU seconds for the second approach, and 0.66 CPU seconds for the third approach.  Obviously, the first approach is the best, because it would probably take an extra 5 minutes to code in the logic to see if the SQL statement used in the third approach returned any rows, and if it did to execute the SQL statement used in the first approach - if you don't use the CPU cycles, you lose them forever.  :-)


Actions

Information

3 responses

1 04 2011
Log Buffer #215, A Carnival of the Vanities for DBAs | The Pythian Blog

[...] speak for themselves – just the fact that they have been written after lot of hard work. Charles Hooper is in the habit of producing such gems regularly. Here is another one from him to relish over the [...]

28 04 2011
coskan gundogar

If I need to see blocking sessions only, I always use v$session.

As your tests already revealed that it is the min consumer I wonder how the resultset will be when you query gv$ tables for finding global blockers on RAC systems

I also need to say I saw a case where v$lock shows blocking (which was true) but at the same time v$session did not, which was a bit weird and looked like a bug which I don’t have a test case for :(

29 04 2011
Charles Hooper

Coskan,

Thank you for your view on the blog article – it might be interesting to see how the GV$ views compare to the V$ views in terms of performance.

Do you happen to remember if V$LOCK was showing identical values for the ID1, ID2, and TYPE columns for the two sessions – I understand that if the ID1 and ID2 columns are identical, but the TYPE columns are different, one session may not be blocking the other. If I remember correctly, that requirement was discussed in one of the blog articles on this site, it might have been this one:
http://hoopercharles.wordpress.com/2010/06/03/lock-watching-what-is-wrong-with-this-sql-statement/

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 139 other followers

%d bloggers like this: