Get the Source of PREEMPTIVE_OS_PIPEOPS Waits

A client reached out to me for help about a wait_type they were seeing. That’s not terribly uncommon, but the specific wait_type was something that was fairly obscure.

Every day, they could see the delta on this wait_type continue to climb higher and higher. The problem was not in their ability to capture the deltas for the biggest wait_types. The problem as it were, was in figuring out what exactly was the root cause of their biggest wait_type.

What was the wait_type? Well, the obscure wait_type was called PREEMPTIVE_OS_PIPEOPS. What causes this wait? As it turns out, this is a generic wait that is caused by SQL pipe related activities such as xp_cmdshell.

Knowing this much information however does not get us to the root cause of this particular problem for this client. How do we get there? This is another case for Extended Events (XEvents).

Tracking Pipe Ops

Knowing which wait_type needs attention is most of the battle in figuring out what precisely is causing the specific wait. The second piece of the puzzle is to understand whether the wait is an internal or external. This is essential because a different event is triggered depending on whether the wait is internal or external. There will be more on that in a future article.

Since I happen to know already that the PREEMPTIVE_OS_PIPEOPS wait is an external wait, then I also know that I will want to use the sqlos.wait_info_external. The downside to this method is that conventional wisdom teaches us that we must use the integer value for the wait in order to monitor for it. To find that integer value, one can query the sys.dm_xe_map_values dmv. Since the values of many of the waits change from CU to CU, then one should validate this value on every server instead of using the same value on all servers without regard.

SELECT *
FROM sys.dm_xe_map_values ws
WHERE ws.map_value = 'PREEMPTIVE_OS_PIPEOPS'
AND ws.name = 'wait_types';

Depending on which server I run that code on, I may receive different results.

As you can see, I have a small sample showing five different values for this specific wait. Using the wrong value on the wrong server could result in a bit of hair tugging since nothing may be trapped.

Due to this potential for change, writing a script to monitor for the session gets a little bit trickier and a lot more dynamic – for now.

USE master;
GO
DECLARE @XelFilePath VARCHAR(256) = 'C:DatabaseXE'; --be sure to include the trailing slash as shown here

/* why?
 well as it turns out, many wait_types change from CU to CU of SQL Server
 */-- Create the Event Session
EXECUTE xp_create_subdir @XelFilePath;
GO
DECLARE @mapkey VARCHAR(4)
, @XESessionName VARCHAR(128) = 'PREEMPTIVE_OS_PIPEOPS'
,@SQLString VARCHAR(4096)
,@XelFilePath VARCHAR(256) = 'C:DatabaseXE';
SELECT @mapkey = ws.map_key
FROM sys.dm_xe_map_values ws
WHERE ws.map_value = 'PREEMPTIVE_OS_PIPEOPS'
AND ws.name = 'wait_types';

SET @SQLString = 'IF EXISTS
(
SELECT
  *
FROM  sys.server_event_sessions
WHERE name = ''' + @XESessionName + '''
)
DROP EVENT SESSION ' + @XESessionName + ' ON SERVER;
--GO
'
SET @SQLString = @SQLString + '
CREATE EVENT SESSION [' + @XESessionName + ']
ON SERVER
ADD EVENT sqlos.wait_info_external
(ACTION
 (
 package0.callstack
   , package0.collect_system_time
   , package0.event_sequence
   , sqlserver.client_app_name
   , sqlserver.client_connection_id
   , sqlserver.client_hostname
   , sqlserver.context_info
   , sqlserver.database_id
   , sqlserver.database_name
   , sqlserver.nt_username
   , sqlserver.server_principal_name
   , sqlserver.session_id
   , sqlserver.session_nt_username
   , sqlserver.sql_text
   , sqlserver.username
 )
 WHERE ([wait_type] = ('+ @mapkey + ')) --PREEMPTIVE_OS_PIPEOPS
)
ADD TARGET package0.event_file
(SET filename = N''' + @XelFilePath + 'PREEMPTIVE_OS_PIPEOPS.xel'')
WITH
(
MAX_MEMORY = 4096KB
  , EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS
  , MAX_DISPATCH_LATENCY = 5 SECONDS
  , TRACK_CAUSALITY = ON
  , STARTUP_STATE = ON
);
--GO
ALTER EVENT SESSION ' + @XESessionName + ' ON SERVER
STATE = START;
--GO
'
PRINT @SQLString;
EXECUTE (@SQLString)

After executing that script, the session will be created with the appropriate wait_type as well as the session will be started. To verify it is working, then I can execute a query that will use xp_cmdshell.

With that information in hand, we now have a tool that will help us identify the root cause of this wait climbing to the top of the waits list. Once I am able to identify the root cause, then I can start applying an appropriate fix (or do nothing if the situation deems that necessary).

But what about this map_key that keeps on changing with updates to SQL Server? Surely there is a better method than figuring out the integer value. As luck would have it, conventional wisdom is wrong in this case. There is a much easier method of creating this event session. So much easier in fact that I don’t need to worry about the map_key value. All I need to know is the wait_type I wish to monitor. So let’s look at a better version of the script.

USE master;
GO
-- Create the Event Session
IF EXISTS
(
SELECT
  *
FROM  sys.server_event_sessions
WHERE name = 'PREEMPTIVE_OS_PIPEOPS'
)
DROP EVENT SESSION PREEMPTIVE_OS_PIPEOPS ON SERVER;
GO
EXECUTE xp_create_subdir 'C:DatabaseXE';
GO
CREATE EVENT SESSION [PREEMPTIVE_OS_PIPEOPS]
ON SERVER
ADD EVENT sqlos.wait_info_external
(ACTION
 (
 package0.callstack
   , package0.collect_system_time
   , package0.event_sequence
   , sqlserver.client_app_name
   , sqlserver.client_connection_id
   , sqlserver.client_hostname
   , sqlserver.context_info
   , sqlserver.database_id
   , sqlserver.database_name
   , sqlserver.nt_username
   , sqlserver.server_principal_name
   , sqlserver.session_id
   , sqlserver.session_nt_username
   , sqlserver.sql_text
   , sqlserver.username
 )
 WHERE ([wait_type] = 'PREEMPTIVE_OS_PIPEOPS')
)
ADD TARGET package0.event_file
(SET filename = N'C:DatabaseXEPREEMPTIVE_OS_PIPEOPS.xel')
WITH
(
MAX_MEMORY = 4096KB
  , EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS
  , MAX_DISPATCH_LATENCY = 5 SECONDS
  , TRACK_CAUSALITY = ON
  , STARTUP_STATE = ON
);
GO

This will yield the same results as the first script, but without the dynamic sql and with a more friendly script for the DBA to understand. This method is actually employed in the system_health system default session if you ever decide to peruse that session.

Wrapping it Up

Extended Events is a powerful tool with plenty of ease of use and flexibility. This flexibility allows the DBA to capably monitor the server for any issue be it small or large. This article demonstrated how to use Extended Events to monitor for a specific wait_type and the same principles can be applied to any of the waits you may need to investigate. If you are in need of a little tune-up for your XE skiils, I recommend reading a bit on Extended Events to get up to date. For other basics related articles, feel free to read here.