Mapping wait types in dm_os_wait_stats to Extended Events

A few months back I received an email from a member of the community that was trying to filter the sqlos.wait_info event for some of the wait types that are filtered out by Glenn’s diagnostic queries, and to their dismay wasn’t able to find the specific wait types in the wait_types map in sys.dm_xe_map_values.  This scenario is something that I have long known about but never actually blogged about, though this blog post has been sitting in draft form since early 2012.  Now that things have started to slow down at the end of this year I took a little time and built a spreadsheet of the wait_type names in sys.dm_os_wait_stats that don’t match exactly to the map_value in sys.dm_xe_map_values.

I’d like to thank Bob Ward at Microsoft for taking the time to double check the spreadsheet I originally built for this blog post for accuracy and for the corrections on a few of the wait types he provided.  The list of wait types below was generated from SQL Server 2012 Service Pack 1 + Cumulative Update 6.

wait_type in sys.dm_os_wait_stats

map_value in sys.dm_xe_map_values

ASYNC_NETWORK_IONETWORK_IO
BROKER_TASK_STOPSSB_TASK_STOP
CLR_JOINCLR_TASK_JOIN
CLR_MEMORY_SPYCLR_MEMORY_SPY_ACCESS
CREATE_DATINISERVICEGET_DATINISERVICE
DBCC_SCALE_OUT_EXPR_CACHECHECK_EXPRESSION_CACHE
DBSTATEDB_STATE
DLL_LOADING_MUTEXDLL_LOAD
ERROR_REPORTING_MANAGERERROR_REPORTING_MGR
EXECUTION_PIPE_EVENT_INTERNALTWO_THREAD_PIPE_EVENT
FS_FC_RWLOCKFS_GC_RWLOCK
FT_IFTS_RWLOCKFT_RWLOCK
FT_IFTS_SCHEDULER_IDLE_WAITFT_SCHEDULER_IDLE_WAIT
FULLTEXT GATHERERFULLTEXT_GATHERER
HADR_ARCONTROLLER_NOTIFICATIONS_SUBSCRIBER_LISTHADR_ARPROXY_NOTIFICATION_SUBSCRIBER_LIST
HADR_DATABASE_FLOW_CONTROLHADR_PARTNER_FLOW
HADR_DATABASE_VERSIONING_STATEHADR_VERSIONING_STATE
HADR_DATABASE_WAIT_FOR_RESTART__indexMUTEX_HADR_DATABASE_WAIT_FOR_RESTART
HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGHADR_WAIT_FOR_TRANSITION_TO_VERSIONING
HADR_FILESTREAM_BLOCK_FLUSHHADRFS_BLOCK_FLUSH
HADR_FILESTREAM_FILE_CLOSEHADRFS_FILE_CLOSE
HADR_FILESTREAM_FILE_REQUESTHADRFS_FILE_REQUEST
HADR_FILESTREAM_IOMGRHADRFS_IOMGR
HADR_FILESTREAM_IOMGR_IOCOMPLETIONHADRFS_IOMGR_IOCOMPLETION
HADR_FILESTREAM_MANAGERHADRFS_MANAGER
HADR_RECOVERY_WAIT_FOR_CONNECTION__indexMUTEX_HADR_RECOVERY_WAIT_FOR_CONNECTION
HADR_RECOVERY_WAIT_FOR_UNDO__indexMUTEX_HADR_RECOVERY_WAIT_FOR_UNDO
HADR_TRANSPORT_FLOW_CONTROLHADR_TRANSPORT_FLOW
HTBUILDHASH_TABLE_BUILD
HTREPARTITIONHASH_TABLE_REPARTITION
INTERNAL_TESTING 
LAZYWRITER_SLEEPLZW_SLEEP
MD_AGENT_YIELDMETADATA_AGENT_YIELD
MD_LAZYCACHE_RWLOCKMETADATA_LAZYCACHE_RWLOCK
MISCELLANEOUSUNKNOWN
MSSEARCHMSSEARCH_COM
PREEMPTIVE_FSRECOVER_UNCONDITIONALUNDOPREEMPTIVE_FSRECOVER_CONDITIONALUNDO
PREEMPTIVE_OS_SQMLAUNCHPREEMPTIVE_SQMLAUNCH
PWAIT_ALL_COMPONENTS_INITIALIZEDALL_COMPONENTS_INITIALIZED
PWAIT_COOP_SCANCOOP_SCAN
PWAIT_EVENT_SESSION_INIT_MUTEXEVENT_SESSION_INIT_MUTEX
PWAIT_HADR_ACTION_COMPLETEDHADR_ACTION_COMPLETED
PWAIT_HADR_CHANGE_NOTIFIER_TERMINATION_SYNCHADR_ARPROXY_NOTIFICATION_SUBSCRIBER_LIST
PWAIT_HADR_CLUSTER_INTEGRATIONHADR_CHANGE_NOTIFIER_TERMINATION_SYNC
PWAIT_HADR_FAILOVER_COMPLETEDHADR_CLUSTER_INTEGRATION
PWAIT_HADR_OFFLINE_COMPLETEDHADR_FAILOVER_COMPLETED
PWAIT_HADR_ONLINE_COMPLETEDHADR_OFFLINE_COMPLETED
PWAIT_HADR_POST_ONLINE_COMPLETEDHADR_ONLINE_COMPLETED
PWAIT_HADR_SERVER_READY_CONNECTIONSHADR_SERVER_READY_CONNECTIONS
PWAIT_HADR_WORKITEM_COMPLETEDHADR_WORKITEM_COMPLETED
PWAIT_MD_LOGIN_STATSMD_LOGIN_STATS
PWAIT_MD_RELATION_CACHEMD_RELATION_CACHE
PWAIT_MD_SERVER_CACHEMD_SERVER_CACHE
PWAIT_MD_UPGRADE_CONFIGMD_UPGRADE_CONFIG
PWAIT_PREEMPTIVE_AUDIT_ACCESS_WINDOWSLOGPREEMPTIVE_AUDIT_ACCESS_WINDOWSLOG
PWAIT_QRY_BPMEMORYQRY_BPMEMORY
PWAIT_REPLICA_ONLINE_INIT_MUTEXREPLICA_ONLINE_INIT_MUTEX
PWAIT_RESOURCE_SEMAPHORE_FT_PARALLEL_QUERY_SYNCRESOURCE_SEMAPHORE_FT_PARALLEL_QUERY_SYNC
PWAIT_SECURITY_CACHE_INVALIDATIONSECURITY_CACHE_INVALIDATION
QUERY_EXECUTION_INDEX_SORT_EVENT_OPENQUERY_EXEC_INDEXSORT_OPEN
REDO_THREAD_PENDING_WORKREDO_SIGNAL
REDO_THREAD_SYNCREDO_SYNC
RESOURCE_GOVERNOR_IDLE 
SCAN_CHAR_HASH_ARRAY_INITIALIZATIONSCAN_CHAR_HASH_ARRAY_INIT
SERVER_IDLE_CHECKSERVER_IDLE_LOCK
SNI_LISTENER_ACCESSLISTENER_UPDATE
SNI_TASK_COMPLETIONSNI_WAIT_TASK_FINISH
SP_PREEMPTIVE_SERVER_DIAGNOSTICS_SLEEPPREEMPTIVE_SP_SERVER_DIAGNOSTICS_SLEEP
THREADPOOLSOS_WORKER
TRAN_MARKLATCH_DTTRANMARKLATCH_DT
TRAN_MARKLATCH_EXTRANMARKLATCH_EX
TRAN_MARKLATCH_KPTRANMARKLATCH_KP
TRAN_MARKLATCH_NLTRANMARKLATCH_NL
TRAN_MARKLATCH_SHTRANMARKLATCH_SH
TRAN_MARKLATCH_UPTRANMARKLATCH_UP
VIA_ACCEPTVIA_ACCEPT_DONE
WAIT_XTP_GUESTXTP_GUEST
WAIT_XTP_TASK_SHUTDOWNXTP_TASK_SHUTDOWN
WAIT_XTP_TRAN_COMMITXTP_TRAN_COMMIT
WAITFOR_TASKSHUTDOWNTASKSHUTDOWN
XE_CALLBACK_LISTXE_CALLBACK
XTPPROC_PARTITIONED_STACK_CREATE__indexXTPPROC_PARTITIONED_STACK_CREATE

Logging Extended Events changes to the ERRORLOG

A question came up in class today about the difference between SQL Trace and Extended Events for logging information to the ERRORLOG file. Joe and I have both written about the observer overhead of Trace and Extended Events in the past (Observer Overhead and Wait Type Symptoms and Measuring “Observer Overhead” of SQL Trace vs. Extended Events), and one of the things we teach is to check whether a trace or event session may be running and impacting performance as a part of general troubleshooting performance problems in SQL Server. Anytime a user starts or stops a SQL Trace, information is logged in the ERRORLOG.

SQL Trace ID 2 was started by login “SQL2K8R2-IE2\Jonathan Kehayias”.
SQL Trace stopped. Trace ID = ‘2’. Login Name = ‘SQL2K8R2-IE2\Jonathan Kehayias’.

SQL Trace messages

SQL Trace messages

However, for Extended Events nothing is logged when a user starts or stops an event session on the server. The question in class today was whether it was possible to make Extended Events log entries like SQL Trace and the answer is yes, with a DDL Trigger.

CREATE TRIGGER XEventLogging
ON ALL SERVER 
FOR DDL_EVENT_SESSION_EVENTS
AS
BEGIN
    SET NOCOUNT ON;
    DECLARE @EventData XML = EVENTDATA();
    DECLARE @EventType NVARCHAR(256) = @EventData.value('(EVENT_INSTANCE/EventType)[1]', 'NVARCHAR(256)')
    DECLARE @SessionName NVARCHAR(256) = @EventData.value('(EVENT_INSTANCE/ObjectName)[1]', 'NVARCHAR(256)')
    DECLARE @LoginName NVARCHAR(256) = @EventData.value('(EVENT_INSTANCE/LoginName)[1]', 'NVARCHAR(256)')
	DECLARE @Command NVARCHAR(MAX) = @EventData.value('(EVENT_INSTANCE/TSQLCommand/CommandText)[1]', 'NVARCHAR(MAX)');
	DECLARE @msg NVARCHAR(440) = CASE 
		WHEN @EventType = 'CREATE_EVENT_SESSION'
			THEN 'Extended Event session created. Session Name = ''%s''. Login Name = ''%s''.'
		WHEN @EventType = 'ALTER_EVENT_SESSION' AND LOWER(@Command) LIKE LOWER('%STATE%=%START%')
			THEN 'Extended Event session started. Session Name = ''%s''. Login Name = ''%s''.'
		WHEN @EventType = 'ALTER_EVENT_SESSION' AND LOWER(@Command) LIKE LOWER('%STATE%=%STOP%')
			THEN 'Extended Event session stopped. Session Name = ''%s''. Login Name = ''%s''.'
		WHEN @EventType = 'DROP_EVENT_SESSION'
			THEN 'Extended Event session dropped. Session Name = ''%s''. Login Name = ''%s''.'
		END
	
	RAISERROR(@msg, 10, 1, @SessionName, @LoginName) WITH LOG;
END
GO

Now anytime an event session is created, started, stopped, or dropped, information will be logged into the ERRORLOG file.

New Extended Events messages

New Extended Events messages

ALTER DATABASE failed. The default collation of database ‘%.*ls’ cannot be set to %.*ls.

Last week I was working with a client on upgrading one of their systems from SQL Server 2000 to SQL Server 2012, while also performing a collation change of the database and all of the table columns from Latin1_General_BIN to SQL_Latin1_General_CP1_CI_AS.  What started out as a straight forward upgrade, this actually became quite a challenge.  After upgrading to SQL Server 2008R2 since SQL Server doesn’t support direct upgrades from SQL Server 2000 to SQL Server 2012, I found metadata corruption.  We’ve seen and dealt with this before, so back to SQL Server 2000 to fix the orphaned entries, and then another upgrade attempt to SQL Server 2008R2.

At this point I had a corruption free database and started running the scripts I had generated to migrate from Latin1_General_BIN to SQL_Latin1_General_CP1_CI_AS.  When I got to the point of changing the database default collation I was dismayed to get the following error back from SQL Server:

Msg 1505, Level 16, State 1, Line 1
The CREATE UNIQUE INDEX statement terminated because a duplicate key was found for the object name ‘dbo.sysschobjs’ and the index name ‘nc1’. The duplicate key value is (0, 1, person).
Msg 5072, Level 16, State 1, Line 1
ALTER DATABASE failed. The default collation of database ‘TestCollationChange’ cannot be set to SQL_Latin1_General_CP1_CI_AS.

Thinking about the previous metadata corruption, I was certain that there was something wrong with the database still, but I couldn’t find anything with CHECKDB or CHECKCATALOG.  It turns out, there is nothing wrong with the database, there is something wrong with my expectations and assumptions.  To demonstrate this, consider the following example:

CREATE DATABASE [TestCollationChange]
ON  PRIMARY
( NAME = N'TestCollationChange', FILENAME = N'C:\SQLData\TestCollationChange.mdf')
LOG ON
( NAME = N'TestCollationChange_log', FILENAME = N'C:\SQLData\TestCollationChange_log.ldf')
COLLATE Latin1_General_BIN;
GO
USE [TestCollationChange];
GO
CREATE TABLE dbo.Person
(    RowID int NOT NULL IDENTITY (1, 1),
FirstName varchar(30) NOT NULL,
LastName varchar(30) NOT NULL);
GO
ALTER TABLE dbo.Person ADD CONSTRAINT PK_Person PRIMARY KEY CLUSTERED (RowID);
GO
CREATE TABLE dbo.person
(    RowID int NOT NULL IDENTITY (1, 1),
FirstName varchar(30) NOT NULL,
LastName varchar(30) NOT NULL);
GO
ALTER TABLE dbo.person ADD CONSTRAINT PK_person PRIMARY KEY CLUSTERED (RowID);
GO

Under the Latin1_General_BIN collation, this is a completely valid schema because case sensitivity is applied.  However, when you try and switch to a case insensitive collation with:

ALTER DATABASE [TestCollationChange] SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
ALTER DATABASE [TestCollationChange] COLLATE SQL_Latin1_General_CP1_CI_AS;

these immediately become duplicate objects.  So where do we go from here?  First, the error message tells us that the object name is ‘person’, so you might consider doing a query against sys.objects:

SELECT * FROM sys.objects where name = 'person';

The only problem is that this will return 1 row, remember we are still in Latin1_General_BIN so case sensitivity is being applied.  To get around this, we need to change our query to collate the name column using our new collation:

SELECT * FROM sys.objects where name COLLATE SQL_Latin1_General_CP1_CI_AS = 'person';

This will show us both of the objects and it becomes immediately clear why we have a duplication issue, different cases.In the case of the actual database I was working on, the duplicate objects were two stored procedures (actually four if you think about), and the duplicates had object definitions similar to the following:

CREATE PROCEDURE [TestProcedure] AS
BEGIN
SELECT …….
-- Lots more logic, etc
END
GO

CREATE PROCEDURE [TESTProcedure] AS RETURN;
GO

I have no idea what the intent of the second procedure was, but after consulting with the client, it was determined that these duplicate stubs could be dropped, which then allowed the database collation change to SQL_Latin1_General_CP1_CI_AS. This might not be a viable solution if the application actually relies on the case sensitive nature of the naming convention, though I wouldn’t personally ever build a database with duplicate object names regardless of the collation.