We have two production SQL Servers running SQL Server 2005 SP4 with cumulative update 3. Both servers run on physical machines that are identical. DELL PowerEdge R815 with 4 x 12 core CPUs and 512GB (yes GB) of ram, with 10GB iSCSI SAN connected drives for all SQL databases and logs. OS is Microsoft Windows Server 2008 R2 Enterprise edition with all SP's and windows updates. OS drive is a RAID 5 array of 3 x 72GB 2.5" 15k SAS drives. SAN is a Dell EqualLogic 6510 with 48 x 10K SAS 3.5" drives, configured in RAID 50, sliced into various LUNs for the 2 SQL Servers, and also shared with an Exchange machine and several VMWare servers.
We have over 20 databases, 11 of which are mirrored with high availability using a witness server. The witness server is a lower powered machine running a SQL Server instance that is used for nothing other than providing witness services. The biggest mirrored database is 450GB and generates around 100-300 iops. Database Mirroring Monitor reports a current send rate around 100kb to 10mb per second, and a mirror commit overhead of (typically) 0 milliseconds. The mirror server has no problem keeping up with the principal.
We are consistently experiencing mirroring failovers. Sometimes a single database will failover, other times almost all databases will failover simultaneously. For instance, last night, we had 10 of 11 databases failover, the remaining database stayed accessible until I manually failed it over.
I have gone through several troubleshooting steps to attempt to identify the problem, but have so far not been able to resolve the issue:
1) The machine came with a Broadcom BCM5709C NetXtreme II 4 port Gigabit network adapter which we initially used as the primary network connection. We have since installed an Intel(R) PRO/1000 PT Dual Port Server Adapter on both machines to eliminate the NIC as the issue.
2) All databases have an automatic full backup nightly along with a log backup for databases involved in mirroring. Log file useage is monitored and rarely gets above 15% used. The log file for the main database is 125GB, consisting of 159 virtual log files that range in size from 511MB to 1GB. TempDB is on it's own LUN, and consists of 24 x 2GB files.
3) SQL Server log on the witness shows no errors other than: The mirroring connection to "TCP://SQL02.DOMAIN.INET:5022" has timed out for database "Data" after 30 seconds without a response. Check the service and network connections.
SQL Server log on the primary and secondary servers show messages relating to mirroring:
The mirroring connection to "TCP://SQL01.DOMAIN.INET:5022" has timed out for database "Data" after 30 seconds without a response. Check the service and network connections.
The mirrored database "Data" is changing roles from "PRINCIPAL" to "MIRROR" due to Role Syncronization. (Synchronization is misspelled here on purpose since that is precisely how the actual message is display.)
The mirrored database "Data" is changing roles from "PRINCIPAL" to "MIRROR" due to Failover.
The mirrored database "Data" is changing roles from "MIRROR" to "PRINCIPAL" due to Failover from partner.
The SQL Server services continue to run and network connections seem to stay up. We consistently have between 500 to 2500 sessions connected to each server (primarily robotic applications that connect to service broker queues on a single database).
4) TCP Chimney and RSS etc are disabled using NET SH syntax.
5) I have ran the SQL Server 2005 Best Practices Analyzer against both machines and find nothing other than the very occasional Application Event Log error 833, none of which are coincident with the failover events:
SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [F:\Data.MDF] in database [Data] (9). The OS file handle is 0x00000000000010A0. The offset of the latest long I/O is: 0x000007d4b10000).
6) Occasionally we see "The client was unable to reuse a session with SPID XXX, which had been reset for connection pooling. This error may have been caused by an earlier operation failing. Check the error logs for failed operations immediately before this error message." generated by both servers. There appears to be no "earlier" messages that indicate any issue.
7) Occasionally database mail writes an error to the Application event log:
Exception Type: Microsoft.SqlServer.Management.SqlIMail.Server.Common.BaseException Message: There was an error on the connection. Reason: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding., connection parameters: Server Name: MGSQL02, Database Name: msdb Data: System.Collections.ListDictionaryInternal TargetSite: Void OpenConnection(Microsoft.SqlServer.Management.Common.SqlConnectionInfo) HelpLink: NULL Source: DatabaseMailEngine
StackTrace Information at Microsoft.SqlServer.Management.SqlIMail.Server.DataAccess.ConnectionManager.OpenConnection(SqlConnectionInfo ci) at Microsoft.SqlServer.Management.SqlIMail.Server.DataAccess.DataAccessAdapter.OpenConnection(String dbServerName, String dbName, String userName, String password) at Microsoft.SqlServer.Management.SqlIMail.IMailProcess.QueueItemProcesser.ProcessQueueItems(String dbName, String dbServerName, Int32 lifetimeMinimumSec, LogLevel loggingLevel)
I believe the Timeouts are causing the failover; what could cause these timeouts? Obviously if there was an actual network issue such as a bad cable, or a bad switch, that might cause packet loss and therefore a timeout, however what other things could cause timeouts? Blocking? If MSDB, or some other system database had an I/O timeout could that cause the mirroring failover?
Thanks for any advice!
netsh interface tcp show global shows:
Receive-Side Scaling State : disabled Chimney Offload State : disabled NetDMA State : enabled Direct Cache Acess (DCA) : disabled Receive Window Auto-Tuning Level : disabled Add-On Congestion Control Provider : ctcp ECN Capability : disabled RFC 1323 Timestamps : disabled
netsh interface ipv4 show dynamicportrange tcp
Protocol tcp Dynamic Port Range Start Port : 1025 Number of Ports : 64510
SELECT name, value_in_use FROM sys.configurations
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 awe enabled 0 blocked process threshold 5 c2 audit mode 0 clr enabled 1 common criteria compliance enabled 0 cost threshold for parallelism 4 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 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 6 max full-text crawl range 4 max server memory (MB) 393216 max text repl size (B) 65536 max worker threads 0 media retention 0 min memory per query (KB) 2048 min server memory (MB) 52427 nested triggers 1 network packet size (B) 1400 Ole Automation Procedures 1 open objects 0 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) 20 remote proc trans 0 remote query timeout (s) 600 Replication XPs 0 scan for startup procs 0 server trigger recursion 1 set working set size 0 show advanced options 1 SMO and DMO XPs 1 SQL Mail XPs 0 transform noise words 0 two digit year cutoff 2049 user connections 0 user options 4216 Web Assistant Procedures 0 xp_cmdshell 1
A while ago, I manually modified the
mirroring_connection_timeout value for all mirrored databases to 30 seconds to attempt to remediate the problem; this has simply increased the amount of time between failover events. With the
mirroring_connection_timeout setting set at the default of 10 seconds, we see a lot more failovers.
A comment had asked me to ensure IPSec is disabled, so I'm posting the contents of several
netsh commands that display the IPSec configuration of the operating system:
C:\>netsh ipsec dynamic show all No currently assigned Policy Mainmode Policies not available. Quickmode Policies not available. Generic Mainmode Filters not available. Specific Mainmode Filters not available. Generic Quickmode Filters not available. Specific Quickmode Filters not available. IPsec MainMode Security Associations not available. IPsec QuickMode Security Associations not available. IPsec Configuration Parameters ------------------------------ StrongCRLCheck : 1 IPsecexempt : 3 IPsec Statistics ---------------- Active Assoc : 0 Offload SAs : 0 Pending Key : 0 Key Adds : 0 Key Deletes : 0 ReKeys : 0 Active Tunnels : 0 Bad SPI Pkts : 0 Pkts not Decrypted : 0 Pkts not Authenticated : 0 Pkts with Replay Detection : 0 Confidential Bytes Sent : 0 Confidential Bytes Received : 0 Authenticated Bytes Sent : 0 Authenticated Bytes Received: 0 Transport Bytes Sent : 0 Transport Bytes Received : 0 Bytes Sent In Tunnels : 0 Bytes Received In Tunnels : 0 Offloaded Bytes Sent : 0 Offloaded Bytes Received : 0 C:\>netsh ipsec static show all ERR IPsec : No Policies in Policy Store
We've now moved our production systems onto SQL Server 2012. We've been running this since the morning of December 17th - so far no failovers. However, a couple of days is well within what we saw with the 2005-based systems.
In an effort to document the performance of our new systems, I've been looking at
sys.dm_os_wait_stats more carefully; and noticed
DBMIRROR_DBM_EVENT, which is an undocumented wait type. Graham Kent at Microsoft has an interesting article regarding troubleshooting unexpected failovers and this wait type. I shall recap his findings here:
The customer was experiencing a huge blocking chain built on a high volume OLTP database where all the head blockers were waiting on DBMIRROR_DBM_EVENT. Here is the sequence of events I went through:
Review the blocking chain itself - ho help here as all we can see is that we're waiting on DBMIRROR_DBM_EVENT
Review the source for the undocumented wait type. Obviously you can't do this outside of MS, but I can say that at the time of writing this wait type represents the wait used when the principal is waiting for the mirror to harden an LSN, meaning that the transaction it's part of cannot commit. This immediately points quite specifically to the problem that the principal cannot commit transactions as it's waiting on the mirror. Now we need to investigate why the mirror is not committing transactions or why the principal doesn't know whether it is.
Review the msdb system tables
(a) Look at the [backupset] table to see if the size of the logs produced at the time of the problem are significantly higher then normal. If they were exceptionally large it may be that the mirror was flooded with transactions and could simply not keep up with the volume. This is why books online will tell you sometimes to disable mirroring if you need to do an exceptionally large logged operation such as an index rebuild. (reference for why this is at http://technet.microsoft.com/en-us/library/cc917681.aspx). Here i used the following TSQL
SELECT backup_set_id,backup_start_date,database_name,has_bulk_logged_data,backup_size / 1000 FROM [backupset] where backup_start_date between '2011-01-05 14:00:00' and '2011-01-05 19:30:00' go select round((AVG(backup_size)/1000),0) FROM [backupset] where database_name = 'mydatabase'
(b) secondly I looked at the data in the tables [dbm_monitor_data]. The key here is to locate the timeframe in which we had a problem and then see if we were significant experiencing changes in any of the following:
log_flush_rate send_queue_size send_rate redo_queue_size redo_rate
These are all indicators similar to part (a) in that they might show a component or piece of architecture that wasn't responding. For example if the send_queue suddenly starts to grow but the re_do queue doesn't grow, then it would imply that the the principal cannot send the log records to the mirror so you'd want to look at connectivity maybe, or the service broker queues dealing with the actual transmissions.
In this particular scenario we noted that all the counters appeared to have strange values, in that there were log backups going on of normal sizes, but there were no status changes, 0 send queue, 0 redo queue, a flat send rate and a flat redo rate. This is very strange as it implies that the DBM Monitor could not record any values from anywhere over the problem period.
Review the SQL Server error logs. In this case there were no errors or information messages whatsoever, but in other scenarios such as this, it’s very common for errors in the 1400 range to be reported, examples of which you can find in other places in my other mirroring blogs, such as this Error 1413 example
Review the default trace files – in this scenario I was not provided the default traces, however they are fantastic sources of DBM problem information, as they record state change events on all the partners.This is documented here:
This often gives you a great picture of scenarios such as when network connectivity failed between one or all of the partners and then what the state of the partnership became afterwards.
In this particular scenario I’m currently missing 2 key points of data, but that apart I can still make a reasonable hypothesis on the above information. We certainly can say that the blocking was caused by the fact that DBM was enabled to the due the blockers all waiting on the DBMIRROR_DBM_EVENT wait type. Since we know we didn’t flood the mirror with a large logged operation and that this deployment normally runs happily in this mode, we can exclude unusual large operations. This means that we have 2 potential candidates at this stage:
Hardware problems on the connectivity between some or all of the partners.
CPU exhaustion on the mirror server – simply unable to keep up with redos – the CPU exhaustion could itself be from a process outside of SQL Server or outside of the this mirror partnership.
A problem with the mirroring code itself (we’d really need some memory dumps to confirm this though).
Based upon experience I’d suspect 1 or 2, but I always keep an open mind about 3 as well, we’re trying to collect some more data now to look at this problem in more detail.