SQL Saturday 273 Session Uploaded

Just over two weeks ago I presented a session on Memory Troubleshooting at SQL Saturday 237 here in Tampa. I promised to upload the demo scripts from this session for troubleshooting problems and I guess it is better late than never. They have been uploaded along with a PDF version of the slide deck to the session on the SQL Saturday site and can be downloaded from there.

Looking at read_microsec in sys.dm_os_buffer_descriptors in SQL Server 2012

Last week someone sent Kimberly an email asking what the read_microsec column in the sys.dm_os_buffer_descriptors DMV in SQL Server 2012 showed. The email was passed around our team and to be honest it was the first time I’d even heard of the column existing. The questioner also wanted to know if/how the read_microsec column be used. The Books Online topic for sys.dm_os_buffer_descriptors defines this column as, “The actual time (in microseconds) required to read the page into the buffer. This number is reset when the buffer is reused.”

This would make you think that the counter is per-page in the buffer pool, but I wanted to see what exactly it correlates to, and the results aren’t quite as straightforward as the Books Online description might seem. The read_microsec column isn’t the time required to read a single page in microseconds – it’s the time taken to complete reading into the buffer pool the original I/O block that the page was part of – whether that block was a single 8KB page or a much larger I/O. This is a completely different meaning when you think about the different sizes of I/O that SQL Server can potentially do.

Investigating this further

To look at this further, the first thing to do is identify the Page ID for a specific row in a database that we can use for tracking the I/O associated with bringing that page into the buffer pool. To do this, we can use the fn_PhysLocFormatter function and %%physloc%% as shown by Paul in his blog post, SQL Server 2008: New (undocumented) physical row locator function.

SELECT TOP 1
	sys.fn_PhysLocFormatter(%%physloc%%) AS [Physical_Loc],
	*
FROM AdventureWorks2012_Slow.Production.Product
ORDER BY ProductID;
%%PhysLoc%% formatted results

%%PhysLoc%% formatted results

In my copy of AdventureWorks2012, this returns Page ID 791, as shown in the screenshot above. Using this Page ID we can clear the buffer pool with DBCC DROPCLEANBUFFERS and then rerun our query to read the page back into the buffer pool from disk. However, since we want to track what the meaning of the new column in sys.dm_os_buffer_descriptors is, first let’s create an Extended Events session to track the physical I/O operations and memory operations associated with the session_id that we are running our queries on.

CREATE EVENT SESSION [PageIOLatency]
ON SERVER
    ADD EVENT sqlos.async_io_completed
        (WHERE (sqlserver.session_id=55)),
    ADD EVENT sqlos.async_io_requested
        (WHERE (sqlserver.session_id=55)),
    ADD EVENT sqlos.page_allocated
        (WHERE (sqlserver.session_id=55)),
    ADD EVENT sqlos.page_freed
        (WHERE (sqlserver.session_id=55)),
    ADD EVENT sqlserver.file_read
        (WHERE (sqlserver.session_id=55)),
    ADD EVENT sqlserver.file_read_completed
        (WHERE (sqlserver.session_id=55)),
    ADD EVENT sqlserver.physical_page_read
        (WHERE (sqlserver.session_id=55)),
    ADD EVENT sqlserver.sql_statement_completed
        (WHERE (sqlserver.session_id=55)),
    ADD EVENT sqlserver.sql_statement_starting
        (WHERE (sqlserver.session_id=55))
    ADD TARGET package0.event_file
        (SET filename=N'PageIOLatency.xel')
WITH (TRACK_CAUSALITY=ON);

Now we can clear the buffer pool, start the event session, query the row from the Production.Product table, and then stop the event session and review the information contained in the event_file target. Specifically we want to look at the I/O operations for page_id 791 and what the duration was for reading the page.

Highlighted results for page_id 791

Highlighted results for page_id 791

Here I’ve highlighted the async_io_requested event and the last physical_page_read event associated with the I/O for page_id 791. If we look at the duration of the file_read_completed event, which is in milliseconds, we can see from the image above that it took 10 milliseconds to perform the read operation. The read_microsec column in sys.dm_os_buffer_descriptors is in microseconds, so this may only loosely correlate to the value showing for page_id 791 when we query dm_os_buffer_descriptors.

SELECT
	obd.file_id,
	obd.page_id,
	obd.page_level,
	obd.row_count,
	obd.free_space_in_bytes,
	obd.is_modified,
	obd.numa_node,
	obd.read_microsec
FROM sys.dm_os_buffer_descriptors AS obd
WHERE database_id = DB_ID('AdventureWorks2012_Slow')  AND
	obd.page_id = 791;
page_id 791 buffer_descriptor

page_id 791 buffer_descriptor

If we look at the timestamps for the async_io_requested and async_io_completed events in the event_file output, we can calculate out the delta in microseconds between the I/O request posting and the completing:

2014-02-05 08:37:40.0419342 — async_io_completion timestamp
2014-02-05 08:37:40.0309362 — async_io_requested timestamp
010998 — delta in microseconds

This is an exact match to the read_microsec in sys.dm_os_buffer_descriptors, which proves that the column provides the actual I/O time associated with that page being read into the buffer pool.

However, it is not actually that simple…

If we go back to the event_file results, we’ll notice that we didn’t just read one page into the buffer pool with our request, we read an entire extent, 8 pages, into the buffer pool with our I/O operation. So if we modify our query against sys.dm_os_buffer_descriptors to show all of the pages for the AdventureWorks2012_Slow database, we’ll see that all 8 of the pages that were read in a single read, have the same read_microsec value.

SELECT
	o.name,
	obd.file_id,
	obd.page_id,
	obd.page_level,
	obd.row_count,
	obd.free_space_in_bytes,
	obd.is_modified,
	obd.numa_node,
	obd.read_microsec
FROM sys.dm_os_buffer_descriptors AS obd
JOIN AdventureWorks2012_Slow.sys.allocation_units AS au
	ON obd.allocation_unit_id = au.allocation_unit_id
JOIN AdventureWorks2012_Slow.sys.partitions AS p
	ON au.container_id = p.partition_id
JOIN AdventureWorks2012_Slow.sys.objects AS o
	ON p.object_id = o.object_id
WHERE database_id = DB_ID('AdventureWorks2012_Slow')  AND
	o.is_ms_shipped = 0
ORDER BY obd.page_id, o.name, obd.read_microsec;
All pages read in buffer_descriptors

All pages read in buffer_descriptors

So for a single page, unless it is a single 8KB read that occurred, the read_microsec column doesn’t necessarily show an I/O related problem. We’d have to know the size of the original I/O block that read the page into the buffer pool to know if the amount of read_microsec is actually a problem. The reason for this is that with I/O latency, the size of the I/O operation performed matters. Larger block I/Os take longer to complete than smaller blocks. To demonstrate this, we can perform a query that would perform larger read-ahead reads from the data file and look at the impact to the read_microsec column for the pages that are read in the larger block I/O.

To do this, I used the sys.fn_PhysLocCracker() TVF in a CROSS APPLY against the Sales.SalesOrderDetail table to find the first set of contiguous rows in the table. Using the query below, this happened to be the TOP 2866 in my AdventureWorks2012_Slow database which covered 32 pages contiguously or 256KB starting at page_id 10672 and ending at page_id 10703.

SELECT *
FROM AdventureWorks2012_Slow.Sales.SalesOrderDetail
CROSS APPLY sys.fn_PhysLocCracker(%%physloc%%);

So if we start the event session again, clear the buffer pool, and read the TOP 2866 rows from the Sales.SalesOrderDetail table, the event data will show that all 32 pages were read with a single 256KB read-ahead read, and the duration for the file_read_completed event is 51ms.

256KB read-ahead read

256KB read-ahead read

If we look at the information in the read_microsec column for the 32 pages in sys.dm_os_buffer_descriptors after reading the table, we’ll see again that all of the pages have the same value.

SELECT
	obd.file_id,
	obd.page_id,
	obd.page_level,
	obd.row_count,
	obd.free_space_in_bytes,
	obd.is_modified,
	obd.numa_node,
	obd.read_microsec
FROM sys.dm_os_buffer_descriptors AS obd
WHERE database_id = DB_ID('AdventureWorks2012_Slow')  AND
	obd.page_id BETWEEN 10672 AND 10703
ORDER BY page_id
All pages have the same read_microsec value

All pages have the same read_microsec value

Summary

The read_microsec column of sys.dm_os_buffer_descriptors wouldn’t be my first go-to metric for looking at I/O latency or page-read issues in SQL Server. While the screenshots in this blog post showed that consecutive page_ids retrieved by a single I/O operation have the same read_microsec value, the testing was done on a SQL Server with no other load and doesn’t mimic production activity in any way. In a production server, you can’t rely on looking at consecutive pages in the output of sys.dm_os_buffer_descriptors to correlate whether or not the pages were all read at the same time in most cases. This is especially true if the server has experienced buffer pool memory pressure or has been active for a long period of time, since pages that aren’t actively being used may be removed to make space for new pages being read into the buffer pool, and a single page within a larger block of pages may remain in the buffer pool longer than the pages around it.

For troubleshooting I/O latency problems, I’d recommend reading Erin’s blog post on Monitoring Disk I/O from our Accidental DBA series, which covers other methods for looking at I/O latency including sys.dm_io_virtual_file_stats and the Physical Disk performance counters.

New Article: VMware CPU Hot Plug vNUMA Effects on SQL Server

My latest article on SQLPerformance.com was published today and highlights the potential for performance problems while using the hot-add vCPU feature in ESX 5+ with wide VMs for SQL Server.

http://www.sqlperformance.com/2013/12/system-configuration/vmware-cpu-hot-plug-vnuma-effects-on-sql-server

This is a potentially hidden problem with serious performance implications that should be checked for if you are using VMware to run wide VMs with greater than 8 vCPUs on NUMA hardware.

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_IO NETWORK_IO
BROKER_TASK_STOP SSB_TASK_STOP
CLR_JOIN CLR_TASK_JOIN
CLR_MEMORY_SPY CLR_MEMORY_SPY_ACCESS
CREATE_DATINISERVICE GET_DATINISERVICE
DBCC_SCALE_OUT_EXPR_CACHE CHECK_EXPRESSION_CACHE
DBSTATE DB_STATE
DLL_LOADING_MUTEX DLL_LOAD
ERROR_REPORTING_MANAGER ERROR_REPORTING_MGR
EXECUTION_PIPE_EVENT_INTERNAL TWO_THREAD_PIPE_EVENT
FS_FC_RWLOCK FS_GC_RWLOCK
FT_IFTS_RWLOCK FT_RWLOCK
FT_IFTS_SCHEDULER_IDLE_WAIT FT_SCHEDULER_IDLE_WAIT
FULLTEXT GATHERER FULLTEXT_GATHERER
HADR_ARCONTROLLER_NOTIFICATIONS_SUBSCRIBER_LIST HADR_ARPROXY_NOTIFICATION_SUBSCRIBER_LIST
HADR_DATABASE_FLOW_CONTROL HADR_PARTNER_FLOW
HADR_DATABASE_VERSIONING_STATE HADR_VERSIONING_STATE
HADR_DATABASE_WAIT_FOR_RESTART __indexMUTEX_HADR_DATABASE_WAIT_FOR_RESTART
HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONING HADR_WAIT_FOR_TRANSITION_TO_VERSIONING
HADR_FILESTREAM_BLOCK_FLUSH HADRFS_BLOCK_FLUSH
HADR_FILESTREAM_FILE_CLOSE HADRFS_FILE_CLOSE
HADR_FILESTREAM_FILE_REQUEST HADRFS_FILE_REQUEST
HADR_FILESTREAM_IOMGR HADRFS_IOMGR
HADR_FILESTREAM_IOMGR_IOCOMPLETION HADRFS_IOMGR_IOCOMPLETION
HADR_FILESTREAM_MANAGER HADRFS_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_CONTROL HADR_TRANSPORT_FLOW
HTBUILD HASH_TABLE_BUILD
HTREPARTITION HASH_TABLE_REPARTITION
INTERNAL_TESTING  
LAZYWRITER_SLEEP LZW_SLEEP
MD_AGENT_YIELD METADATA_AGENT_YIELD
MD_LAZYCACHE_RWLOCK METADATA_LAZYCACHE_RWLOCK
MISCELLANEOUS UNKNOWN
MSSEARCH MSSEARCH_COM
PREEMPTIVE_FSRECOVER_UNCONDITIONALUNDO PREEMPTIVE_FSRECOVER_CONDITIONALUNDO
PREEMPTIVE_OS_SQMLAUNCH PREEMPTIVE_SQMLAUNCH
PWAIT_ALL_COMPONENTS_INITIALIZED ALL_COMPONENTS_INITIALIZED
PWAIT_COOP_SCAN COOP_SCAN
PWAIT_EVENT_SESSION_INIT_MUTEX EVENT_SESSION_INIT_MUTEX
PWAIT_HADR_ACTION_COMPLETED HADR_ACTION_COMPLETED
PWAIT_HADR_CHANGE_NOTIFIER_TERMINATION_SYNC HADR_ARPROXY_NOTIFICATION_SUBSCRIBER_LIST
PWAIT_HADR_CLUSTER_INTEGRATION HADR_CHANGE_NOTIFIER_TERMINATION_SYNC
PWAIT_HADR_FAILOVER_COMPLETED HADR_CLUSTER_INTEGRATION
PWAIT_HADR_OFFLINE_COMPLETED HADR_FAILOVER_COMPLETED
PWAIT_HADR_ONLINE_COMPLETED HADR_OFFLINE_COMPLETED
PWAIT_HADR_POST_ONLINE_COMPLETED HADR_ONLINE_COMPLETED
PWAIT_HADR_SERVER_READY_CONNECTIONS HADR_SERVER_READY_CONNECTIONS
PWAIT_HADR_WORKITEM_COMPLETED HADR_WORKITEM_COMPLETED
PWAIT_MD_LOGIN_STATS MD_LOGIN_STATS
PWAIT_MD_RELATION_CACHE MD_RELATION_CACHE
PWAIT_MD_SERVER_CACHE MD_SERVER_CACHE
PWAIT_MD_UPGRADE_CONFIG MD_UPGRADE_CONFIG
PWAIT_PREEMPTIVE_AUDIT_ACCESS_WINDOWSLOG PREEMPTIVE_AUDIT_ACCESS_WINDOWSLOG
PWAIT_QRY_BPMEMORY QRY_BPMEMORY
PWAIT_REPLICA_ONLINE_INIT_MUTEX REPLICA_ONLINE_INIT_MUTEX
PWAIT_RESOURCE_SEMAPHORE_FT_PARALLEL_QUERY_SYNC RESOURCE_SEMAPHORE_FT_PARALLEL_QUERY_SYNC
PWAIT_SECURITY_CACHE_INVALIDATION SECURITY_CACHE_INVALIDATION
QUERY_EXECUTION_INDEX_SORT_EVENT_OPEN QUERY_EXEC_INDEXSORT_OPEN
REDO_THREAD_PENDING_WORK REDO_SIGNAL
REDO_THREAD_SYNC REDO_SYNC
RESOURCE_GOVERNOR_IDLE  
SCAN_CHAR_HASH_ARRAY_INITIALIZATION SCAN_CHAR_HASH_ARRAY_INIT
SERVER_IDLE_CHECK SERVER_IDLE_LOCK
SNI_LISTENER_ACCESS LISTENER_UPDATE
SNI_TASK_COMPLETION SNI_WAIT_TASK_FINISH
SP_PREEMPTIVE_SERVER_DIAGNOSTICS_SLEEP PREEMPTIVE_SP_SERVER_DIAGNOSTICS_SLEEP
THREADPOOL SOS_WORKER
TRAN_MARKLATCH_DT TRANMARKLATCH_DT
TRAN_MARKLATCH_EX TRANMARKLATCH_EX
TRAN_MARKLATCH_KP TRANMARKLATCH_KP
TRAN_MARKLATCH_NL TRANMARKLATCH_NL
TRAN_MARKLATCH_SH TRANMARKLATCH_SH
TRAN_MARKLATCH_UP TRANMARKLATCH_UP
VIA_ACCEPT VIA_ACCEPT_DONE
WAIT_XTP_GUEST XTP_GUEST
WAIT_XTP_TASK_SHUTDOWN XTP_TASK_SHUTDOWN
WAIT_XTP_TRAN_COMMIT XTP_TRAN_COMMIT
WAITFOR_TASKSHUTDOWN TASKSHUTDOWN
XE_CALLBACK_LIST XE_CALLBACK
XTPPROC_PARTITIONED_STACK_CREATE __indexXTPPROC_PARTITIONED_STACK_CREATE

Hyper-V Equivalent to VMware CPU Ready Time

I’ve blogged about CPU Ready Time in VMware in the past, and one of the questions I am often asked is whether there is an equivalent counter in Hyper-V? The definition of CPU Ready time by VMware is:

“Percentage of time that the virtual machine was ready, but could not get scheduled to run on the physical CPU.”

Looking through the Hyper-V performance counters and their description on Windows Server 2012/2012 R2, the Hyper-V Hypervisor Virtual Processor\CPU Wait Time Per Dispatch counter provides the following description:

“The average time (in nanoseconds) spent waiting for a virtual processor to be dispatched onto a logical processor.”

image

Unfortunately this counter is new in Windows Server 2012 Hyper-V and doesn’t exist in Windows Server 2008 or 2008 R2.  However, moving forward this counter should provide similar information about VMs waiting to execute on physical processor resources similar to what we’ve had with VMware CPU Ready.

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

SQL Server 2012 Extended Events Add-in Updates

Back in July I blogged about the SQL Server 2012 Extended Events Add-in to Manage 2008/R2 Instances. Unfortunately, despite having multiple beta testers using the add-in before the release, I started getting reports of the add-in crashing Management Studio. A new version of the add-in is available for download (http://www.sqlskills.com/free-tools/sql-server-2012-extended-events-add-in/) that addresses this and one or two other issues that were reported over the last month. If you have the add-in installed, it should prompt you to update the next time it loads. To install the newer version, you will have to uninstall the add-in and then install the new build.

Using ‘dbghelp.dll’ version ‘4.0.5’ error fixed in SQL Server 2012 SP1 CU6

If you use Extended Events you may have noticed that the ERRORLOG file gets bloated with messages like:

Using ‘dbghelp.dll’ version ‘4.0.5’

every time you query sys.dm_xe_sessions or read a file using Transact-SQL and the sys.fn_xe_file_target_read_file() table-valued function. This issue can be especially problematic on SharePoint 2013 installations, where a timer job queries Extended Events every 15 seconds to monitor the SharePoint SQL Server instance.

This has been fixed in SQL Server 2012 SP1 + CU6 which was just released today (https://support.microsoft.com/kb/2878139).  The specifics of this “feature” are contained in the following KB article (https://support.microsoft.com/kb/2878139).

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.

Updated Availability Group Demonstrator

Since the first release of the SQLskills Availability Group Demonstrator, I’ve had an number of requests to add the ability to enable MultiSubnetFailover in the connection string, and to specify a Timeout value. I made these changes months ago but never got around to actually releasing the newer build on my blog. However, after releasing the two add-ins yesterday, I took a few minutes and ran through testing the demonstrator application against my local Availability Group and then uploaded the latest build for download.

Availability Group Demonstrator