28

I'm collecting blocked process reports using Extended Events, and for some reason in some reports the blocking-process node is empty. This is the full xml:

<blocked-process-report monitorLoop="383674">
 <blocked-process>
  <process id="processa7bd5b868" taskpriority="0" logused="106108620" waitresource="KEY: 6:72057613454278656 (8a2f7bc2cd41)" waittime="25343" ownerId="1051989016" transactionname="user_transaction" lasttranstarted="2017-03-20T09:30:38.657" XDES="0x21f382d9c8" lockMode="X" schedulerid="7" kpid="15316" status="suspended" spid="252" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2017-03-20T09:39:15.853" lastbatchcompleted="2017-03-20T09:39:15.850" lastattention="1900-01-01T00:00:00.850" clientapp="Microsoft Dynamics AX" hostname="***" hostpid="1348" loginname="***" isolationlevel="read committed (2)" xactid="1051989016" currentdb="6" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
   <executionStack>
    <frame line="1" stmtstart="40" sqlhandle="0x02000000f7def225b0edaecd8744b453ce09bdcff9b291f50000000000000000000000000000000000000000" />
    <frame line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000" />
   </executionStack>
   <inputbuf>
(@P1 bigint,@P2 int)DELETE FROM DIMENSIONFOCUSUNPROCESSEDTRANSACTIONS WHERE ((PARTITION=5637144576) AND ((FOCUSDIMENSIONHIERARCHY=@P1) AND (STATE=@P2)))   </inputbuf>
  </process>
 </blocked-process>
 <blocking-process>
  <process />
 </blocking-process>
</blocked-process-report>

The index definition for the index this hobt_id belongs to is

CREATE UNIQUE CLUSTERED INDEX [I_7402FOCUSDIMENSIONHIERARCHYIDX] ON [dbo].[DIMENSIONFOCUSUNPROCESSEDTRANSACTIONS]
(
    [PARTITION] ASC,
    [FOCUSDIMENSIONHIERARCHY] ASC,
    [STATE] ASC,
    [GENERALJOURNALENTRY] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, IGNORE_DUP_KEY = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
GO

There is no partitioning involved, this is the table definition:

CREATE TABLE [dbo].[DIMENSIONFOCUSUNPROCESSEDTRANSACTIONS](
    [FOCUSDIMENSIONHIERARCHY] [bigint] NOT NULL DEFAULT ((0)),
    [GENERALJOURNALENTRY] [bigint] NOT NULL DEFAULT ((0)),
    [STATE] [int] NOT NULL DEFAULT ((0)),
    [RECVERSION] [int] NOT NULL DEFAULT ((1)),
    [PARTITION] [bigint] NOT NULL DEFAULT ((5637144576.)),
    [RECID] [bigint] NOT NULL,
 CONSTRAINT [I_7402RECID] PRIMARY KEY NONCLUSTERED 
(
    [RECID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]

GO

ALTER TABLE [dbo].[DIMENSIONFOCUSUNPROCESSEDTRANSACTIONS]  WITH CHECK ADD CHECK  (([RECID]<>(0)))
GO

There are no triggers or foreign keys defined on any of the tables in the entire database.

The exact SQL Server build is:

Microsoft SQL Server 2012 (SP3-CU4) (KB3165264) - 11.0.6540.0 (X64)
Jun 23 2016 17:45:11 Copyright (c) Microsoft Corporation Enterprise Edition: Core-based Licensing (64-bit) on Windows NT 6.3 (Build 14393: ) (Hypervisor)

The extended events is fairly simple, just logging the blocked process reports:

CREATE EVENT SESSION [Dynperf_Blocking_Data] ON SERVER 
ADD EVENT sqlserver.blocked_process_report(
    ACTION(package0.collect_system_time,sqlserver.client_hostname,sqlserver.context_info)),
ADD EVENT sqlserver.lock_escalation(
    ACTION(package0.collect_system_time,sqlserver.client_hostname,sqlserver.context_info)),
ADD EVENT sqlserver.xml_deadlock_report(
    ACTION(package0.collect_system_time,sqlserver.client_hostname,sqlserver.context_info)) 
ADD TARGET package0.event_file(SET filename=N'F:\SQLTrace\Dynamics_Blocking.xel',max_file_size=(100),max_rollover_files=(10))
WITH (MAX_MEMORY=32768 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=PER_NODE,TRACK_CAUSALITY=ON,STARTUP_STATE=ON)
GO

The database is configured in Read Committed Snapshot Isolation, and max degree of parallelism is set to 1. This is the server configuration:

+------------------------------------+-------+
|                name                | value |
+------------------------------------+-------+
| access check cache bucket count    |     0 |
| access check cache quota           |     0 |
| Ad Hoc Distributed Queries         |     0 |
| affinity I/O mask                  |     0 |
| affinity mask                      |     0 |
| affinity64 I/O mask                |     0 |
| affinity64 mask                    |     0 |
| Agent XPs                          |     1 |
| allow updates                      |     0 |
| backup compression default         |     1 |
| blocked process threshold (s)      |     2 |
| c2 audit mode                      |     0 |
| clr enabled                        |     0 |
| common criteria compliance enabled |     0 |
| contained database authentication  |     0 |
| cost threshold for parallelism     |     5 |
| cross db ownership chaining        |     0 |
| cursor threshold                   |    -1 |
| Database Mail XPs                  |     1 |
| default full-text language         |  1033 |
| default language                   |     0 |
| default trace enabled              |     1 |
| disallow results from triggers     |     0 |
| EKM provider enabled               |     0 |
| filestream access level            |     0 |
| fill factor (%)                    |     0 |
| ft crawl bandwidth (max)           |   100 |
| ft crawl bandwidth (min)           |     0 |
| ft notify bandwidth (max)          |   100 |
| ft notify bandwidth (min)          |     0 |
| index create memory (KB)           |     0 |
| in-doubt xact resolution           |     0 |
| lightweight pooling                |     0 |
| locks                              |     0 |
| max degree of parallelism          |     1 |
| max full-text crawl range          |     4 |
| max server memory (MB)             | 65536 |
| max text repl size (B)             | 65536 |
| max worker threads                 |     0 |
| media retention                    |     0 |
| min memory per query (KB)          |  1024 |
| min server memory (MB)             |     0 |
| nested triggers                    |     1 |
| network packet size (B)            |  4096 |
| Ole Automation Procedures          |     0 |
| open objects                       |     0 |
| optimize for ad hoc workloads      |     1 |
| PH timeout (s)                     |    60 |
| precompute rank                    |     0 |
| priority boost                     |     0 |
| query governor cost limit          |     0 |
| query wait (s)                     |    -1 |
| recovery interval (min)            |     0 |
| remote access                      |     1 |
| remote admin connections           |     0 |
| remote login timeout (s)           |    10 |
| remote proc trans                  |     0 |
| remote query timeout (s)           |   600 |
| Replication XPs                    |     0 |
| scan for startup procs             |     1 |
| server trigger recursion           |     1 |
| set working set size               |     0 |
| show advanced options              |     1 |
| SMO and DMO XPs                    |     1 |
| transform noise words              |     0 |
| two digit year cutoff              |  2049 |
| user connections                   |     0 |
| user options                       |     0 |
| xp_cmdshell                        |     0 |
+------------------------------------+-------+

I ran a server side trace for a while and I get the same empty nodes in a trace file as I do using extended events.
This blocked process report was captured using a server side trace on another server also running Dynamics AX, so it's not specific to this server or build.

<blocked-process-report monitorLoop="1327922">
 <blocked-process>
  <process id="processbd9839848" taskpriority="0" logused="1044668" waitresource="KEY: 5:72057597098328064 (1d7966fe609a)" waittime="316928" ownerId="3415555263" transactionname="user_transaction" lasttranstarted="2017-03-27T07:59:29.290" XDES="0x1c1c0c3b0" lockMode="U" schedulerid="3" kpid="25236" status="suspended" spid="165" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2017-03-27T07:59:47.873" lastbatchcompleted="2017-03-27T07:59:47.873" lastattention="2017-03-27T07:58:01.490" clientapp="Microsoft Dynamics AX" hostname="***" hostpid="11072" loginname="***" isolationlevel="read committed (2)" xactid="3415555263" currentdb="5" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
   <executionStack>
    <frame line="1" stmtstart="236" stmtend="676" sqlhandle="0x020000004d6830193d42a167edd195c201f40bb772e9ece20000000000000000000000000000000000000000"/>
   </executionStack>
   <inputbuf>
(@P1 numeric(32,16),@P2 int,@P3 bigint,@P4 nvarchar(5),@P5 nvarchar(36),@P6 int,@P7 numeric(32,16),@P8 bigint,@P9 int)UPDATE PRODCALCTRANS SET REALCOSTAMOUNT=@P1,RECVERSION=@P2 WHERE (((((((PARTITION=@P3) AND (DATAAREAID=@P4)) AND (COLLECTREFPRODID=@P5)) AND (COLLECTREFLEVEL=@P6)) AND (LINENUM=@P7)) AND (RECID=@P8)) AND (RECVERSION=@P9))   </inputbuf>
  </process>
 </blocked-process>
 <blocking-process>
  <process/>
 </blocking-process>
</blocked-process-report>

Does anybody have an explanation for these reports? What is blocking the query?

Is there any way to find out what was happening if I'm looking at the reports after the locks have long gone?

One thing that might be useful to add is that these queries are run via sp_cursorprepareand sp_cursorexecute

So far I haven't been able to reproduce it, it seems to happen randomly but very often.

It happens on several instances (of different builds) and several tables/queries, all related to Dynamics AX.

There are no index or other database maintenance jobs occurring in the background at the time.

Using the code provided in the answer by srutzky I was able to capture some logging related to this blocked process report:

<blocked-process-report monitorLoop="1621637">
 <blocked-process>
  <process id="processd06909c28" taskpriority="0" logused="0" waitresource="KEY: 5:72057597585719296 (d2d87c26d920)" waittime="78785" ownerId="4436575948" transactionname="user_transaction" lasttranstarted="2017-04-13T07:39:17.590" XDES="0x3219d034e0" lockMode="U" schedulerid="3" kpid="133792" status="suspended" spid="106" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2017-04-13T07:39:17.657" lastbatchcompleted="2017-04-13T07:39:17.657" lastattention="1900-01-01T00:00:00.657" clientapp="Microsoft Dynamics AX" hostname="****" hostpid="11800" loginname="****" isolationlevel="read committed (2)" xactid="4436575948" currentdb="5" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
   <executionStack>
    <frame line="1" stmtstart="72" stmtend="256" sqlhandle="0x0200000076a6a92ab1256af09321b056ab243f187342f9960000000000000000000000000000000000000000"/>
    <frame line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000"/>
   </executionStack>
   <inputbuf>
(@P1 int,@P2 int,@P3 bigint,@P4 int)UPDATE PRODROUTEJOB SET JOBSTATUS=@P1,RECVERSION=@P2 WHERE ((RECID=@P3) AND (RECVERSION=@P4))   </inputbuf>
  </process>
 </blocked-process>
 <blocking-process>
  <process/>
 </blocking-process>
</blocked-process-report>

This is found in the logging tables for the same resource around that time: Gist because of character limit

Further investigation shows that just before and after the report with an empty blocking process I have reports for the same resourceid that do have blocking process nodes:

<blocked-process-report monitorLoop="1621636">
 <blocked-process>
  <process id="processd06909c28" taskpriority="0" logused="0" waitresource="KEY: 5:72057597585719296 (d2d87c26d920)" waittime="73765" ownerId="4436575948" transactionname="user_transaction" lasttranstarted="2017-04-13T07:39:17.590" XDES="0x3219d034e0" lockMode="U" schedulerid="3" kpid="133792" status="suspended" spid="106" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2017-04-13T07:39:17.657" lastbatchcompleted="2017-04-13T07:39:17.657" lastattention="1900-01-01T00:00:00.657" clientapp="Microsoft Dynamics AX" hostname="***" hostpid="11800" loginname="***" isolationlevel="read committed (2)" xactid="4436575948" currentdb="5" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
   <executionStack>
    <frame line="1" stmtstart="72" stmtend="256" sqlhandle="0x0200000076a6a92ab1256af09321b056ab243f187342f9960000000000000000000000000000000000000000"/>
    <frame line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000"/>
   </executionStack>
   <inputbuf>
(@P1 int,@P2 int,@P3 bigint,@P4 int)UPDATE PRODROUTEJOB SET JOBSTATUS=@P1,RECVERSION=@P2 WHERE ((RECID=@P3) AND (RECVERSION=@P4))   </inputbuf>
  </process>
 </blocked-process>
 <blocking-process>
  <process status="sleeping" spid="105" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2017-04-13T07:40:31.417" lastbatchcompleted="2017-04-13T07:40:31.423" lastattention="1900-01-01T00:00:00.423" clientapp="Microsoft Dynamics AX" hostname="**" hostpid="11800" loginname="**" isolationlevel="read committed (2)" xactid="4436165115" currentdb="5" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
   <executionStack/>
   <inputbuf>
(@P1 bigint,@P2 nvarchar(5),@P3 bigint,@P4 bigint,@P5 nvarchar(11),@P6 int,@P7 nvarchar(21),@P8 datetime2)SELECT T1.REGDATETIME,T1.REGDATETIMETZID,T1.WORKERPILOT,T1.WORKER,T1.WRKCTRIDPILOT,T1.REGTYPE,T1.PROFILEDATE,T1.JOBID,T1.JOBIDABS,T1.MATCHRECIDSTARTSTOP,T1.JOBACTIVE,T1.RESNO,T1.STARTITEMS,T1.GOODITEMS,T1.SCRAPITEMS,T1.FINISHEDCODE,T1.TMPGOODITEMS,T1.TMPSCRAPITEMS,T1.SYSMRPUPDATEREQUEST,T1.ERROR,T1.ERRORTXT,T1.TMPSTARTITEMS,T1.AUTOSTAMP,T1.ERRORSPECIFICATION,T1.COSTCATEGORY,T1.ONCALLACTIVITY,T1.TERMINALID,T1.PDSCWGOODITEMS,T1.PDSCWSCRAPITEMS,T1.PDSCWSTARTITEMS,T1.RETAILTERMINALID,T1.MODIFIEDDATETIME,T1.RECVERSION,T1.PARTITION,T1.RECID FROM JMGTERMREG T1 WHERE (((PARTITION=@P1) AND (DATAAREAID=@P2)) AND (((((WORKER=@P3) OR ((WORKER=@P4) AND (WRKCTRIDPILOT=@P5))) AND (REGTYPE=@P6)) AND (JOBID=@P7)) AND (REGDATETIME&gt;=@P8))) ORDER BY T1.REGDATETIME   </inputbuf>
  </process>
 </blocking-process>
</blocked-process-report>

Using the new script provided by srutzky new data has been collected. It's posted on github because of the maximum post length.

Since the originally posted data didn't have both session id's some new data has been posted on github again

New data including the connections on github

6

I can't test this theory at the moment, but based on the most recent capture data posted to GitHub, I would say that the reason that thee <process> node is empty is that it requires a currently running request (many of the attributes are found in sys.dm_exec_requests and not in sys.dm_exec_sessions) and without a currently running request, it can't report any details, similar to how doing an INNER JOIN between sys.dm_exec_requests and sys.dm_exec_sessions will exclude rows where a Session is active but is idle due to no current request.

Looking at the top set of data (monitorLoop values: 1748823, 1748824, 1748825, and 1748827) we can see the following:

  • the id of the blocked-process is the same in each case: process2552c1fc28, and the only attribute that is different is the waittime (understandably).
  • the attributes of the blocking-process nodes show differences in both lastbatchstarted and lastbatchcompleted
  • the attributes of the blocking-process nodes show identical values for spid and xactid

So, how can the SessionID and TransactionID of the blocking process be the same across 4 different query batches? Easy, an explicit transaction was started and then these batches were executed. And because these are seperate batches, there is time between them being submitted, at which point there is no current request, hence no process info to show (but the session and the transaction are still there).

In order to do additional research into this, you can capture helpful information from sys.dm_exec_requests and sys.dm_tran_locks by placing the following T-SQL in a SQL Server Agent "Transaction-SQL script (T-SQL)" Job Step, setting the "Database" to be the one you are researching (in this case it is the one with an ID of 6), and scheduling this job to run every 10 seconds. The T-SQL below will create the two tables in that same DB if they don't exist and then will populate the "Requests" table if any request is either blocking itself, or if it is a Delete or Update operation that is being blocked. If any requests are found, it will try to capture:

  • Session and Request info on the blocking process (this part does not assume that there is an active Request, hence the RIGHT JOIN to at least get the Session info)
  • Connection info for the blocked and (hopefully) blocking processes.
  • the current locks for those same session_id's (just keep in mind that the lock info isn't guaranteed to be 100% accurate as that info can change in the time between those two statements executing; still, the info is good enough often enough to be worth capturing). This section is currently commented out.

SQL Server Agent T-SQL Job Step:

-- !! Remember to set the "Database" for the T-SQL Job Step to
--    the DB that has database_id = 6 !!
SET NOCOUNT ON;
IF (OBJECT_ID(N'dbo.tmpBlockingResearch_Requests') IS NULL)
BEGIN
  -- Create requests capture table
  SELECT SYSDATETIME() AS [CaptureTime], req.*,
         ses.login_time, ses.[host_name], ses.[program_name], ses.host_process_id,
         ses.client_version, ses.client_interface_name, ses.security_id,
         ses.login_name, ses.nt_domain, ses.nt_user_name, ses.memory_usage,
         ses.total_scheduled_time, ses.endpoint_id, ses.last_request_start_time,
         ses.last_request_end_time, ses.is_user_process, ses.original_security_id,
         ses.original_login_name, ses.last_successful_logon, ses.last_unsuccessful_logon,
         ses.unsuccessful_logons, ses.authenticating_database_id
  INTO   dbo.tmpBlockingResearch_Requests
  FROM   sys.dm_exec_requests req
  INNER JOIN sys.dm_exec_sessions ses
          ON ses.[session_id] = req.[session_id]
  WHERE  1 = 0;
END;

IF (OBJECT_ID(N'dbo.tmpBlockingResearch_Connections') IS NULL)
BEGIN
  -- Create connections capture table
  SELECT SYSDATETIME() AS [CaptureTime], con.*
  INTO   dbo.tmpBlockingResearch_Connections
  FROM   sys.dm_exec_connections con
  WHERE  1 = 0;
END;

IF (OBJECT_ID(N'dbo.tmpBlockingResearch_Locks') IS NULL)
BEGIN
  -- Create locks capture table
  SELECT SYSDATETIME() AS [CaptureTime], loc.*
  INTO   dbo.tmpBlockingResearch_Locks
  FROM   sys.dm_tran_locks loc
  WHERE  1 = 0;
END;
---------------------------------
DECLARE @SessionIDs TABLE (SessionID SMALLINT NOT NULL,
                           BlockingSessionID SMALLINT NOT NULL);

INSERT INTO dbo.tmpBlockingResearch_Requests
OUTPUT inserted.[session_id], inserted.[blocking_session_id]
INTO   @SessionIDs ([SessionID], [BlockingSessionID])
  SELECT SYSDATETIME() AS [CaptureTime], req.*,
         ses.login_time, ses.[host_name], ses.[program_name], ses.host_process_id,
         ses.client_version, ses.client_interface_name, ses.security_id,
         ses.login_name, ses.nt_domain, ses.nt_user_name, ses.memory_usage,
         ses.total_scheduled_time, ses.endpoint_id, ses.last_request_start_time,
         ses.last_request_end_time, ses.is_user_process, ses.original_security_id,
         ses.original_login_name, ses.last_successful_logon, ses.last_unsuccessful_logon,
         ses.unsuccessful_logons, ses.authenticating_database_id
  FROM   sys.dm_exec_requests req
  INNER JOIN sys.dm_exec_sessions ses
          ON ses.[session_id] = req.[session_id]
  WHERE ses.[is_user_process] = 1
  AND   req.[database_id] = DB_ID()
  AND   (
          req.blocking_session_id IN (req.[session_id], -2, -3, -4)
    OR   (req.[command] IN (N'DELETE', N'UPDATE') AND req.[blocking_session_id] > 0)
        );

-- Get at least session info, if not also request info, on blocking process
INSERT INTO dbo.tmpBlockingResearch_Requests
  SELECT SYSDATETIME() AS [CaptureTime], req.*,
         ses.login_time, ses.[host_name], ses.[program_name], ses.host_process_id,
         ses.client_version, ses.client_interface_name, ses.security_id,
         ses.login_name, ses.nt_domain, ses.nt_user_name, ses.memory_usage,
         ses.total_scheduled_time, ses.endpoint_id, ses.last_request_start_time,
         ses.last_request_end_time, ses.is_user_process, ses.original_security_id,
         ses.original_login_name, ses.last_successful_logon, ses.last_unsuccessful_logon,
         ses.unsuccessful_logons, ses.authenticating_database_id
  FROM   sys.dm_exec_requests req
  RIGHT JOIN sys.dm_exec_sessions ses
          ON ses.[session_id] = req.[session_id]
  WHERE ses.[session_id] IN (SELECT DISTINCT [BlockingSessionID] FROM @SessionIDs);

-- If any rows are captured this time, try to capture their connection info
INSERT INTO dbo.tmpBlockingResearch_Connections
  SELECT SYSDATETIME() AS [CaptureTime], con.*
  FROM   sys.dm_exec_connections con
  WHERE  con.[session_id] IN (
                              SELECT [SessionID]
                              FROM @SessionIDs
                              UNION -- No "ALL" so it does DISTINCT
                              SELECT [BlockingSessionID]
                              FROM @SessionIDs
                             );

/*
-- If any rows are captured this time, try to capture their lock info
INSERT INTO dbo.tmpBlockingResearch_Locks
  SELECT SYSDATETIME() AS [CaptureTime], loc.*
  FROM   sys.dm_tran_locks loc
  WHERE  loc.[request_session_id] IN (
                                      SELECT [SessionID]
                                      FROM @SessionIDs
                                      UNION -- No "ALL" so it does DISTINCT
                                      SELECT [BlockingSessionID]
                                      FROM @SessionIDs
                                     );
 */

I think you should be able to reproduce this by opening one query tab and executing the following:

CREATE TABLE dbo.tmp (Col1 INT);
BEGIN TRAN;
INSERT INTO dbo.tmp (Col1) VALUES (1);

Then, open a second query tab and execute the following:

UPDATE dbo.tmp
SET    Col1 = 2
WHERE  Col1 = 1;

P.S. Just to have it stated, the only thing that does not make sense is that the request & session info – dbo.tmpBlockingResearch_Requests – still never contains rows for the blocking session. Yet I know that the table variable has the blocking session id in it as it did pull in the locks for both SessionIDs. This could point to a scenario in which a Transaction is allowed to stay open after the "connection" from the client is closed but the connection is still maintained due to Connection Pooling.

  • @TomV I have reviewed the newest research data and have a pretty solid theory. I have updated my answer accordingly, including adding a section to my research queries, so please replace the job step SQL with the new queries here (I also commented out the "locks" query since we don't really need that data right now and it's a lot of data). I suggest truncating / dropping the existing research tables to start over from scratch. – Solomon Rutzky Jun 20 '17 at 20:15
  • @TomV Ok. And I have updated my repro query to be an UPDATE instead of a SELECT so it should be more representative of your situation anyway. I also added a note at the end about missing rows in the requests table. Hopefully the new Connections table will at least confirm the continued existence of the blocking SessionID. (PS, I started cleaning up my comments above). – Solomon Rutzky Jun 21 '17 at 15:30
  • Your job is active. I'll need to find some time to test the repro and analyze it next week – Tom V Jun 23 '17 at 8:19
  • Hi Solomon. 2 new examples have been posted on github. Unfortunately I couldn't trigger an empty blocking process BPR using the repro case provided. – Tom V Jul 6 '17 at 12:54
  • Took a very quick look as I don't have much time. It looks like the Connections info shows the blocking session ID still active but it is not in the sessions table. I can test this later, but I am pretty sure that indicates connection pooling (connection is still there) and the connection being closed between commands yet a transaction is clearly open (since the transaction_id is always the same as we saw last time). Will take a closer look later.. – Solomon Rutzky Jul 6 '17 at 13:26
4
+250

Blocked transactions can occur because of lock escalations.

This is explained in the Microsoft Support article:

How to resolve blocking problems that are caused by lock escalation in SQL Server

...
Lock escalation does not cause most blocking problems. To determine whether lock escalation is occurring around the time when you experience blocking issues, start a SQL Profiler trace that includes the Lock:Escalation event. If you do not see any Lock:Escalation events, lock escalation is not occurring on your server and the information in this article does not apply to your situation.

If lock escalation is occurring, verify that the escalated table lock is blocking other users
...

Check the Extended Events (physical file) for lock escalation events that occurred before the blocked process event.

Explaining

There is a Microsoft Blog article that goes into further detail:

SQL Server Lock Escalation and Blocking

...
Step 2: Collect Lock Escalation and Blocked Process Report Events.

Lock escalation and blocked process report events are not automatically captured by SQL Server. In order to know if these events are happening, we need to tell SQL Server to record them. Our team uses the Performance Analyzer for Microsoft Dynamics tool to gather that information. Check out this post by Rod Hansen for more information on the tool and how to collect blocking details with it. If you just want to use SQL Server Profiler, the events you would need to collect are shown below: ...

After you have captured lock escalations and blocked processes you have to determine if the lock escalations are the root cause of the blocked processes:

...
Step 3: Review the Trace in SQL Server Profiler.

There are two main indicators that will tell you if the blocking is related to lock escalation.

First, you see a series of lock escalation events immediately preceding the blocked process report events. Below is an example taken from a trace produced by the Performance Analyzer for Microsoft Dynamics tool. This is one thing to look for in the trace, but this alone doesn’t mean lock escalation is causing the blocking. ...

and further

To verify that the blocking is in fact related to lock escalation, you need to look at the blocked process report details. In the TextData section look for waitresource (see the screenshot below). If waitresource starts with OBJECT, we know the blocked statement is waiting on a table level lock to be released before it can proceed. If waitresource starts with KEY or PAG instead of OBJECT, then lock escalation isn’t involved in that specific block. Lock escalation will always increase the scope of a lock to OJBECT regardless of where it starts

Solution

(only if the above mentioned matches)

The solution is apparently to turn on the trace flag 1224 which will turn off lock escalation:

SQL Server Lock Escalation and Blocking

If you see these two things together, it’s a pretty good bet that lock escalation is causing the blocking and you would probably benefit from implementing SQL Server trace flag 1224.

SQL Server Trace Flags for Dynamics AX

Trace flag 1224 disables lock escalation based on number of locks. Enabling this trace flag can reduce the likelihood of blocking due to lock escalation- something I’ve seen with a number of AX implementations. The most common scenario where this becomes an issue is when there’s a requirement for Master Planning to run during the day

Answer

In the end it could be that lock escalation is the root cause of blocked processes.


Alternate Solution (process node empty)

After further investigation of some blocked_process_reports the following alternate explanation can be made.

The Extended Events are capturing blocked_process_reports which are unrelated to any other processes at the time.

Ergo: They must be blocked for a different reason

I would suggest you capture a time frame of wait types from the sys.dm_os_wait_stats view on your SQL Server and correlate the numbers with the blocked_process_reports happening during your measurements. Paul Randall has a good script: Send me your wait stats and get my advice and 30 days of free Pluralsight in return

The scripts captures the current counters, waits for 23hours (can be modified), recaptures the current counters again and compares them to give you the top 95% of wait types. You could try this out for say 1 hour and have the XEL file handy.

You might find a wait type (e.g. LCK_M_SH, …) that is telling you that your storage is slow in writing. Or that you have some other overhead (e.g. CX_PACKET_WAITS, ….). Something is slowing down your Updates. You can then see if the sys.dm_os_wait_stats relate to the blocked_process_reports with the empty nodes.

There are cases when a blocked SPID is being blocked by the same SPID:

The blocked column in the sysprocesses table is populated for latch waits after you install SQL Server 2000 SP4

When an SPID is waiting for an I/O page latch, you may notice that the blocked column briefly reports that the SPID is blocking itself. This behavior is a side effect of the way that latches are used for I/O operations on data pages. When a thread issues an I/O request, the SPID that issues the I/O request acquires a latch on the page. All SQL Server 2000 I/O operations are asynchronous. Therefore, the SPID will try to acquire another latch on the same page if the SPID that issued the I/O request must wait for the request to finish. This second latch is blocked by the first latch. Therefore, the blocked column reports that the SPID is blocking itself. When the I/O request finishes, the first latch is released. Then, the second latch request is granted.

Alternate Answer

This is a further indication that you might be having IO issues. These issues result in "blocked processes" but without a related foreign SPID. Extended Events might not report the process/SPID in a separate node.

  • I could be misreading this, but doesn't this info prove that the issue is not lock escalation? One quoted section says "look at the blocked process report details.", and the top-most XML in the question is the blocked process report. Next, that same quoted section says, "If waitresource starts with KEY or PAG instead of OBJECT, then lock escalation isn’t involved in that specific block.", and the blocked-process-report XML shows waitresource="KEY: 6:72057..... So that means that "lock escalation isn’t involved" here. – Solomon Rutzky Apr 5 '17 at 21:30
  • No, you are NOT misreading this. The section that is provided in the question is one issue on this server. My answer is a global approach to issues that could occur due to blocking and lock escalation. If you can fix some major issues (blocked_process_reports for OBJECT level locking), then the smaller issues (blocked_process_reports at other levels) may resolve themselves. This is the reason why I have also added a second alternate answer. – hot2use Apr 6 '17 at 6:29

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.