SQL Server – “Lock Timeouts” – Identify Using “Extended Events”

Background

In this exercise we will create an Extended Event from Scratch and see if are able to successfully monitor “Lock Requests” timeout.

 

Previous Posts

  1. SQL Server – “Lock Timeouts” – ErrorLog
    Link
  2. SQL Server – Identify Lock TimeOuts via Extended Events ( from converted Trace File )
    Link
  3. SQL Server – “Lock Timeouts” – Trigger Timeouts – SSMS – Table Designer
    Link
  4. SQL Server – “Lock Timeouts” – Identifying through SQL Server Profiler
    Link

 

 

Prerequisite

v2008-R2+

Extended Events was introduced with SQL Server 2008, the GUI came a release later, v2008-R2 to be exact.

And, so your SSMS client to be on at least v2008/R2 and your targeted Server should be on v2008.

 

Design Extended Event

Create new Extended Event

Initiate Wizard

Initiate a new Extended Event Session Creation by selecting the SQL Instance, accessing Object Explorer and traversing the tree “Management“\ “Extended Events” \ “Sessions“.  Right click on the Sessions node and from the drop-down menu select “New Session Wizard“.

Image

 

Screen Shot

Image

Introduction
Image

 

 

Set Session Properties
Outline
  1. Session name :- lockTimeOut
  2. Schedule
    • Start the event session at server startup
      • Off
        • For now we will choose not to affect the Trace to happen at startup
Image

 

Choose Templates
Outline
  1. Use this event session template: Query Detail Tracking
    • This template collects detailed statement and error information.
      • What MSFT says
        • You can use this template to track each statement has executed on your system as a result of query batches or stored procedures and then track errors back to the specific statement that caused them.
        • This template also collects the query hash and query plan hash for every statement it tracks.
        • All statement events are collected in this session so collection size may be very large.
        • To reduce the collection size consider using the Query Detail Sampling template, which already includes a filter.
    • Might want to use Query Detail Sampling template
      • Events are only collected from 20% of the active sessions on the server at any given time.
      • You can change the sampling rate by modifying the filter for the event session.
Image

 

Select Events to Capture
Outline
  1. Error Reported
  2. Lock Cancel
  3. Lock Deadlock
  4. Lock Deadlock Chain
  5. Lock Timeout
  6. Lock Timeout Greater Than
  7. RPC Completed
  8. SQL batch Completed
  9. XML Deadlock Report
Tabulate
Event Event Detail Explanation  Link
Error Reported Occurs when an error is reported.  Link
 Lock Cancel Occurs when the request for a lock was canceled, such as when the query requesting the lock was canceled. Use this event to monitor locks. The Lock:Cancel event class indicates that acquisition of a lock on a resource has been canceled; for example, due to a query being canceled.  Link
 Lock Deadlock  Occurs when an attempt to acquire a lock is canceled for the victim of a deadlock. The Lock:Deadlock Chain event class is produced for each participant in a deadlock.

Use the Lock:Deadlock Chain event class to monitor when deadlock conditions occur. This information is useful to determine if deadlocks are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize deadlocks can be made.

 Link
 Lock Deadlock Chain  Occurs when an attempt to acquire a lock generates a deadlock. This event is raised for each participant in the deadlock.  The Lock:Deadlock Chain event class is produced for each participant in a deadlock.
Use the Lock:Deadlock Chain event class to monitor when deadlock conditions occur. This information is useful to determine if deadlocks are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize deadlocks can be made.
 Link
 Lock Timeout Occurs when a request for a lock times out because another transaction holds a blocking lock on the required resource. The time-out duration is determined by the @@LOCK_TIMEOUT system function. Use this event to help troubleshoot blocking issues. The Lock:Timeout event class indicates that a request for a lock on a resource, such as a page, has timed out because another transaction is holding a blocking lock on the required resource. Time-out is determined by the @@LOCK_TIMEOUT system function and can be set with the SET LOCK_TIMEOUT statement.

Use the Lock:Timeout event class to monitor when time-out conditions occur. This information is useful to determine if time-outs are significantly affecting the performance of your application, and which objects are involved. You can examine the application code that modifies these objects to determine if changes to minimize time-outs can be made.

 Link
 Lock Timeout Greater Than 0  Occurs when a request for a lock times out because of a blocking lock that is being held by a different resource. This event is identical to lock_timeout, but excludes cases in which the time-out value is 0, such as when lock probes are used. Time-outs with a duration of 0 do not necessarily indicate a blocking problem.  The Lock:Timeout (timeout > 0) event class indicates that a request for a lock on a resource, such as a page, has timed out because another transaction is holding a blocking lock on the required resource. This event class behaves the same as the Lock:Timeout event class, except it does not include any events where the timeout value is 0.
Include the Lock:Timeout (timeout > 0) event class in traces where you are using lock probes or other processes that have timeout values of zero. This allows you to see where actual time-outs are occurring without seeing time-out values of zero.
 Link
 RPC Completed  Occurs when a remote procedure call has completed.  The RPC:Completed event class indicates that a remote procedure call has been completed.  Link
 SQL Batch completed  Occurs when a Transact-SQL batch has finished executing.  The SQL:BatchCompleted event class indicates that the Transact-SQL batch has completed.  Link
 XML Deadlock Report  Produces a deadlock report in XML format.

 

 

Image

 

Capture Global Fields
Outline
  1. client app name
  2. client hostname
  3. collect system time
  4. database id
  5. database name
  6. is system
  7. server instance name
  8. server principal name
  9. session id
  10. session server principal name
  11. sql text
Image

 

Set Session Event Filters
Outline

Once we have the Session created, we will come back and add filtering elements.

Image

 

Specify Session Data Storage
Outline

Again we will come back and persistence once we have had things running for a while…

Image

 

Summary
Outline

We get a nice summary of our choices in tree view.  And, can click and review each choice.

Image

 

Create Event Session
Outline

The Wizard submits the SQL for creating the Session to the SQL Engine and it works behind the scene to create the event.

Image

 

Edit Extended Event

Initiate Wizard

Outline

Access the list of Extended Event Sessions by selecting the SQL Instance, accessing Object Explorer and traversing the tree “Management“\ “Extended Events” \ “Sessions“.

Review the list of existing Extended Event Sessions and right clicking on the one you will like to edit.

From the drop-down menu, select “Properties“.

Image

 

Edit Session Wizard

Session Properties – General

Outline

  1. Session Name :- lockTimeOut
  2. Template :- <Blank>
  3. Start the event Session at server startup
    • Checkbox that can be turned on or off
    • Indicates whether Session should be scheduled to start upon SQL Instance restart
  4. Start event session once Session is initially created
  5. Watch live data on screen at is captured
  6. Causality Tracking
    • very important as it allows to tie seemingly independent events will likely sources
    • AI Stuff
Image

 

Session Properties – Events

Outline

  1. Session Name :- lockTimeOut
  2. Template :- <Blank>
  3. Start the event Session at server startup
    • Checkbox that can be turned on or off
    • Indicates whether Session should be scheduled to start upon SQL Instance restart
  4. Start event session once Session is initially created
  5. Watch live data on screen at is captured
  6. Causality Tracking
    • very important as it allows to tie seemingly independent events will likely sources
    • AI Stuff
Image

 

Session Properties – Events

Outline

  1. This is the most important screen
  2. We add in events and leave out those not pertinent to our current use case
  3. And, can click the “Configure” button to add filtering to
Image

Session Properties – Selected Events – Configure

Event – “Error Reported”
Outline

The configure screen allows us to choose the fields we want to collect, and the filtering predicates.

Global Fields
Tabulate

We chose to follow the following fields for all events:

  1. client app name
  2. client hostname
  3. collect system time
  4. database id
  5. database name
  6. is system
  7. server instance name
  8. server principal name
  9. session id
  10. session server principal name
  11. sql text

 

Global Fields – Image

Filter Predicates
Filter Predicates – Matrix
Error Number Message Explanation
 2528  DBCC execution completed. If DBCC printed error messages, contact your system administrator.
 5701  Changed database context to ‘%.*ls’.
 5703  Changed language setting to %.*ls.

 

 

Filter Predicates – Image

 

Image – Error Reported – Error Number – 2528

Image – Error Reported – Error Number – 5701

 

Image – Error Reported – Error Number – 5703

Event – “lock cancel”,” lock deadlock”, “lock deadlock chain”, “lock timeout”, “lock timeout greater than”, “xml deadlock report”
Outline

This event captures Lock Requests that are cancelled.

We did not make any changes, but ensured that the request’s SQL text is captured, as well.

Event Fields – Tabulate

Here are specific fields that are captured

  1. database id
  2. mode
  3. object id
  4. resource 0, resource 1, resource 2
  5. resource description

 

Event Fields – Image

 

Watch Live Data

Events

 

Event – Lock Timeout

Outline

Raised when “Lock Timeout” occurs…

Image

Tabulated

 

Error Number Sample Explanation
 Associated Object ID  110623437 Issue object_schema_name({Associated Object ID}, Database_ID) to get schema nameIssue object_name({Associated Object ID}, Database_ID) to get Object Name
 Client Hostname  […DADENIJI-…]
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
 Duration  29999000  Value is is microseconds ( 30 seconds )
 Is System  False  Is request targeting a system or user object
 Mode  SCH_M  Schema Modification
 Object ID  110623437 Please see explanation for “Associated ID“, but replace “Associated Object ID” with Object ID
 Owner Type  Transaction
 Client Hostname  […DADENIJI-…]  Client’s workstation name
 Resource_0  110623437 Search for guide and code on the Net on how to find Resource Name when one has Resource  ID
 Resource Type  OBJECT  Resource Type granularity
 Server Instance Name  [DADENIJI\v2014]  SQL Instance Sever Name
 Server Principal Name  [Domain Name]\dadeniji Login Name
 Session Server Principal Name  [Domain Name]\dadeniji Same as Login name, except when in the middle of an “Execute As Login” code block
 SQL Text  ALTER TABLE dbo.person ADD   gender char(1) NULL  Underlying SQL

 

 

 

Event – Lock Timeout Greater Than 0

Outline

Raised when “Lock Timeout greater than 0” occurs…

Please keep in mind that Lock TimeOut is raise anytime that Lock Request Timed Out; while Lock Timeout only occurs when a time limit has been set on how long to wait.

In our scenario, we raised Lock Timeout greater than 0, as well.

 

Event – Error Reported

Outline

Raised when “Lock Timeout” occurs…

Image

Tabulated

Error Number Sample Explanation
Client Application Name  Microsoft SQL Server Management Studio Application Name
 Client Hostname  […DADENIJI-…]
Collect System Time  2017-03-31 12:41 PM System Time
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
Error Number  1222  Lock request time out period exceeded.
 Is System  False  Is request targeting a system or user object
 Message message Lock request time out period exceeded.
Severity  16 Please seek out extended documentation to get insight on the various severity levels
 SQL State  56  ???
 User Defined  false  SQL Server supports User defined errors.  If the error is triggered by the user through raiserror or  throw, this flag is set to true
 SQL State  56  ???
 User Defined  false  SQL Server supports User defined errors.  If the error is triggered by the user through raiserror or  throw, this flag is set to true

 

 

 

Event – SQL Batch Completed

Outline

Raised once the SQL Batch completes.

In our case, we are only capturing the ones that fail.

Image

 

Tabulated

Error Number Sample Explanation
 Batch Text ALTER TABLE dbo.person ADD   gender char(1) NULL
Client Application Name  Microsoft SQL Server Management Studio Application Name
 Client Hostname  […DADENIJI-…]
Collect System Time  2017-03-31 12:41 PM System Time
CPU Time  0 How much time the system has spent on the batch.
Please keep in mind this is different than the time expended wait time.
 Database ID  7  Database D
 Database Name
 Database Name ( Action )  DBLab  Issue db_name([Database ID]) if null
 Duration  30001486 30001486 is 30 million micro-seconds
30001 is 30 thousand milli-seconds
or 30 seconds
 Is System  False  Is request targeting a system or user object
Logical Reads 0  How much Logical Reads has been engaged
Physical Reads 0  How much physical Reads has been engaged
Result Error Has we said all of events will be Error
Row Count  false Aggregated Number of Records affected
SQL Text ALTER TABLE dbo.person ADD   gender char(1) NULL SQL Text
Writes  0 Measurement of Writes

 

 

 

Summary

We will let things run for a while.

Watch thing through Live Data.

And, come back and configure persisting of events.

And, in another post review and analysis of the saved events.

Leave a Reply

Please log in using one of these methods to post your comment:

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