CSS SQL Server Engineers

Why won't my PowerPivot for Excel 2010 workbook upgrade to Excel 2013?

2013-05-23T17:35:00Z

Recently we've seen an issue where some Excel 2010 workbooks containing PowerPivot models encounter errors when attempting to upgrade to Excel 2013.

When opening a PowerPivot model that was created in Excel 2010 in Excel 2013 you will be prompted to upgrade with the following message:

This workbook has a PowerPivot data model created using a previous version of
the PowerPivot add-in. You will need to upgrade this data model with PowerPivot
for Excel 2013.

After clicking OK to upgrade to model the following error message is displayed:

============================
Error Message:
============================

The handle is invalid
----------------------------
The '' local cube file cannot be opened.
----------------------------
A connection cannot be made. Ensure that the server is running.
----------------------------
Sorry, PowerPivot couldn't connect to server A connection cannot be made. Ensure that the server is running..

============================
Call Stack:
============================

   at Microsoft.AnalysisServices.LocalCubeStream..ctor(String cubeFile, OpenFlags settings, Int32 timeout, String password, String serverName)
----------------------------
   at Microsoft.AnalysisServices.LocalCubeStream..ctor(String cubeFile, OpenFlags settings, Int32 timeout, String password, String serverName)
   at Microsoft.AnalysisServices.XmlaClient.OpenLocalCubeConnection(ConnectionInfo connectionInfo)
   at Microsoft.AnalysisServices.XmlaClient.OpenConnection(ConnectionInfo connectionInfo, Boolean& isSessionTokenNeeded)
   at Microsoft.AnalysisServices.XmlaClient.Connect(ConnectionInfo connectionInfo, Boolean beginSession)
----------------------------
   at Microsoft.AnalysisServices.XmlaClient.Connect(ConnectionInfo connectionInfo, Boolean beginSession)
   at Microsoft.AnalysisServices.Server.Connect(String connectionString, String sessionId, ObjectExpansion expansionType)
   at Microsoft.AnalysisServices.BackEnd.DataModelingSandboxConnection.OpenAMOConnection()
----------------------------
   at Microsoft.AnalysisServices.BackEnd.DataModelingSandboxConnection.OpenAMOConnection()
   at Microsoft.AnalysisServices.BackEnd.DataModelingSandboxConnection.Open()
   at Microsoft.Office.PowerPivot.ExcelAddIn.InProcServer.LoadSandboxAfterConnection(String errorCache)
   at Microsoft.Office.PowerPivot.ExcelAddIn.InProcServer.LoadSafeSandboxAfterConnection(String errorCache)
   at Microsoft.Office.PowerPivot.ExcelAddIn.InProcServer.LoadOLEDBConnection(Boolean raiseCompleteEvent, String errorCache)

============================

This issue occurs when a Pivot Table in the workbook has an invalid set or calculated field definition.

When the attempt to upgrade begins, Excel opens the PowerPivot model and executes the commands in the pivotcache for the pivot tables in the workbook, including creating session sets or calculated items. If a definition contains an error then the embedded PowerPivot engine returns an error and Excel disconnects from the PowerPivot embedded engine, returning the message saying the server connection could not be opened.

We are working with the Excel team to address this issue, but for now one option to work around this problem is to use the following steps:

Open the workbook in Excel 2010
Click on a PivotTable
In the PivotTable Tools, Options, menu click on the "Fields, Items, and Sets" button and choose Manage Sets.
Delete any invalid set definitions.
Save the file then open it in Excel 2013. It should upgrade successfully.

-Wayne Robertson

SharePoint Adventures : Claims, Named Pipes and Kerberos

2013-05-17T21:17:15Z

I ran into a new Kerberos Scenario that I hadn’t hit before when I was working on the cases related to this blog post. It’s rare that I actually see a case related to the Named Pipes protocol. When I do, it is usually a customer trying to get it setup with a Cluster deployment. I have never had a Named Pipes case related to Kerberos. On top of that, I’ve never had a SQL related Kerberos issue that looked like an actual network related issue. I usually see a traditional “Login failed for user” type error from the SQL Server itself.

As part of my troubleshooting for the other blog post with the Claims configuration, I stumbled upon some information and theories about how Named Pipes responds when Kerberos is in the picture that I hadn’t ever seen or dealt with before. I love when I see new things! It is very humbling and always reminds me there are a lot of things that I don’t know. And, if you have read my other blog posts, or have seen me present at conferences like PASS, you know I have a passion for Kerberos!

Here is what I saw from an error perspective using SharePoint 2013 and Reporting Services 2012 SP1.

System.Data.SqlClient.SqlException: A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server) ---> System.ComponentModel.Win32Exception: Access is denied

This is a typical error if we can’t connect to SQL. Think of this like a “Server doesn’t exist” type error. We didn’t get the normal “Login failed for user” error that would possibly point towards Kerberos. In this error, we didn’t even make it to SQL. The interesting piece here though is the “Access is denied” inner exception. That does possibly point to a permission issue.

I had talked in the last Blog Post about protocol order with connecting to SQL and that the default was TCP. In this case, I was forcing Named Pipes, so the fact that the error is a Named Pipes error is expected.

I dropped down to a network trace to see how far we actually got and to see if that revealed any other information. One thing to keep in mind here is that we are in a Claims to Windows Token Service (C2WTS) scenario with the SharePoint/RS 2012 integration. So, Kerberos/Constrained Delegation will be in the picture here. A lot of people aren’t necessarily familiar with how Named Pipes actually works. Named Pipes actually uses the SMB (simple message block) protocol from a network perspective. This is the same protocol used for file shares and you’ll see the traffic on port 445. It can be a little confusing because SMB sits on top of TCP, but we aren’t actually using the TCP 1433 port. It is just a different way to connect to SQL Server. The IP 10.0.0.20 was the SharePoint Server hosting the Reporting Services Service.

300    9:04:40 AM 5/17/2013    10.0.0.20    captthrace.battlestar.local    SMB    SMB:C; Negotiate, Dialect = PC NETWORK PROGRAM 1.0, LANMAN1.0, Windows for Workgroups 3.1a, LM1.2X002, LANMAN2.1, NT LM 0.12, SMB 2.002, SMB 2.???    {SMBOverTCP:42, TCP:41, IPv4:1}

302    9:04:40 AM 5/17/2013    captthrace.battlestar.local    10.0.0.20    SMB2    SMB2:R   NEGOTIATE (0x0), Revision: (0x2ff) - SMB2 wildcard revision number., ServerGUID={97B805C2-296C-477B-82B4-DEB6170A2A01} Authentication Method: GSSAPI,     {SMBOverTCP:42, TCP:41, IPv4:1}

303    9:04:40 AM 5/17/2013    10.0.0.20    captthrace.battlestar.local    SMB2    SMB2:C   NEGOTIATE (0x0), ClientGUID= {9CB563F9-BEF4-11E2-9403-00155D4CB97B},     {SMBOverTCP:42, TCP:41, IPv4:1}

304    9:04:40 AM 5/17/2013    captthrace.battlestar.local    10.0.0.20    SMB2    SMB2:R   NEGOTIATE (0x0), Revision: (0x300) - SMB 3.0 dialect revision number., ServerGUID={97B805C2-296C-477B-82B4-DEB6170A2A01} Authentication Method: GSSAPI,     {SMBOverTCP:42, TCP:41, IPv4:1}

323    9:04:40 AM 5/17/2013    10.0.0.20    captthrace.battlestar.local    SMB2    SMB2:C   SESSION SETUP (0x1) Authentication Method: GSSAPI,     {SMBOverTCP:42, TCP:41, IPv4:1}

326    9:04:40 AM 5/17/2013    captthrace.battlestar.local    10.0.0.20    SMB2    SMB2:R - NT Status: System - Error, Code = (22) STATUS_MORE_PROCESSING_REQUIRED SESSION SETUP (0x1), SessionFlags=0x0 Authentication Method: GSSAPI,     {SMBOverTCP:42, TCP:41, IPv4:1}

327    9:04:40 AM 5/17/2013    10.0.0.20    captthrace.battlestar.local    SMB2    SMB2:C   SESSION SETUP (0x1) Authentication Method: GSSAPI,     {SMBOverTCP:42, TCP:41, IPv4:1}
     - ResponseToken: NTLM AUTHENTICATE MESSAGE Version:NTLM v2, Workstation: CAPTHELO
          Signature: NTLMSSP

328    9:04:40 AM 5/17/2013    captthrace.battlestar.local    10.0.0.20    SMB2    SMB2:R - NT Status: System - Error, Code = (34) STATUS_ACCESS_DENIED SESSION SETUP (0x1) ,     {SMBOverTCP:42, TCP:41, IPv4:1}

329    9:04:40 AM 5/17/2013    10.0.0.20    captthrace.battlestar.local    TCP    TCP:Flags=...A.R.., SrcPort=49665, DstPort=Microsoft-DS(445), PayloadLen=0, Seq=2945236632, Ack=2852397926, Win=0 (scale factor 0x8) = 0    {TCP:41, IPv4:1}

In the Network Trace we can see that we were trying to connect via NTLM. I already know that that will be a problem as we have to go Kerberos. We started supporting Kerberos with Named Pipes starting in SQL 2008, so it should work. At this point, I’m thinking we actually have a Kerberos issue even though it looked like a network issue from the original error message. So, lets go see if we can validate that. I already had Kerberos Event Logging enabled. These entries will be located in the System Event Log. You can ignore errors that show “KDC_ERR_PREAUTH_REQUIRED”. That is just noise and expected. Also realize that errors may be cached and if they are, you will not see them in the Event Log or a Network Trace. It may require an IISRESET, a reset of the C2WTS Windows Service, or even a reboot of the box to get the items to show in the Event log or Network Trace. See this Blog Post.

Log Name:      System
Source:        Microsoft-Windows-Security-Kerberos
Date:          5/17/2013 9:04:40 AM
Event ID:      3
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      CaptHelo.battlestar.local
Description:
A Kerberos error message was received:
on logon session
Client Time:
Server Time: 14:4:40.0000 5/17/2013 Z
Error Code: 0xd KDC_ERR_BADOPTION
Extended Error: 0xc0000225 KLIN(0)
Client Realm:
Client Name:
Server Realm: BATTLESTAR.LOCAL
Server Name: cifs/captthrace.battlestar.local
Target Name: cifs/captthrace.battlestar.local@BATTLESTAR.LOCAL
Error Text:
File: 9
Line: 12be
Error Data is in record data.

This entry was the only non-PREAUTH_REQUIRED error. Two things that were interesting about this. First was KDC_ERR_BADOPTION. When I see this, especially in a Claims type configuration, it tells me we have a Constrained Delegation issue. The other item that was interesting was the CIFS SPN. CIFS is used for File Sharing. It stands for “Common Internet File System”. This was our SMB traffic. We can also see this in the Network Trace.

319 9:04:40 AM 5/17/2013 10.0.0.20 10.0.0.1 KerberosV5 KerberosV5:TGS Request Realm: BATTLESTAR.LOCAL Sname: cifs/captthrace.battlestar.local {TCP:44, IPv4:14}

321 9:04:40 AM 5/17/2013 10.0.0.1 10.0.0.20 KerberosV5 KerberosV5:KRB_ERROR - KDC_ERR_BADOPTION (13) {TCP:44, IPv4:14}

This was interesting, because I never gave Constrained Delegation rights to CIFS for the C2WTS or the Computer Account. When we talk about SPN’s and Delegation and placement, we talk about that the SPN should be on the account that is running the servers. For CIFS, it will be the system itself and therefore on the machine account of the SQL Server that we are trying to connect to.

CIFS is one of those special Service Classes, similar to HTTP. It is covered by the HOST SPN on the Machine Account and we won’t see an actual CIFS SPN defined, but when we go to the delegation side of things you will see it.

I added this to both the Claims Service account and the Computer Account. I say computer account, because the actual SMB request will come from the machine and not directly from the RS Process. Under the hoods, it is affectively making a call to the CreateFile Windows API.

After resetting IIS and cycling the C2WTS Service, I still saw the same exact error. This was one of those reboot moments. After rebooting the server, I then got the following:

I didn’t necessarily expect this as I expected to fail on the Kerb side to SQL. So, I ran a report and stuck a WAITFOR DELAY in there so I could see the connection. had a look at dm_exec_connections on the SQL Server and saw that we had connected with NTLM:

For our purposes this will work as I’m not going further than SQL. This is technically a single hop between the SharePoint Server System context and the SQL Server. You can configure it for Kerberos if you really want that auth_scheme by creating the appropriate Named Pipes SPN and configuring the appropriate Delegation for the C2WTS Service Account and the Machine Account for where the SMB request is originating from. Also realize that if you have a misplaced Named Pipes SQL SPN, you will encounter a “Cannot Generate SSPI Context” similar to the following:

Adam W. Saxton | Microsoft Escalation Services
http://twitter.com/awsaxton

SharePoint Adventures : When connectivity is not connectivity

2013-05-17T13:07:29Z

I’m always amazed that issues usually come in batches. I was looped into a few cases that had the following symptoms. They were running SharePoint 2010 and Reporting Services 2012 SP1. When they went to use a data source with Windows Authentication, they were seeing the following error:

System.Data.SqlClient.SqlException: A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)

This caused me to raise an eyebrow (visions of Spock as the new Star Trek movie is opening today <g>). A lot of thoughts were floating in my head that all told me that this error didn’t make sense, for a bunch of reasons.

The default protocol order for connecting to SQL from a client is TCP and then Named Pipes. So, because we failed with a Named Pipes error, that meant something was either wrong with TCP or someone changed the Protocol order (which I have never seen in a customer case – so very unlikely)
This is RS 2012, which means we are a Shared Service and rely on the Claims to Windows Token Service (C2WTS). This forces Constrained Delegation. Pretty sure most people would not have created the delegation requirements for the Named Pipes SQL SPN as most people go down the TCP route. You can read more about SQL’s SPNs being Protocol based here. Also more on this related aspect in a later post as I found some interesting things about this as well.
This error tells me that we couldn’t establish a connection to SQL via Named Pipes. Think of this as a “Server Not Found” type error. I immediately tossed out any Kerberos/Claims related issue due to that thinking – again more on the kerb piece of this in a later post.
This is really the first time I’ve had someone hit me up with a Named Pipes connection failure from an RS/SharePoint Integration perspective ever. And I just got hit with 3 of them within the same week. Something is up.

Being this told me we had an actual connection issue via Named Pipes, I started down the normal connectivity troubleshooting path. With any connectivity issue, I started with a UDL (Universal Data Link) file. Basically just a text file renamed with an extension of UDL. It’s important to run this from the same machine that is hitting the SqlException. In my case it was my SharePoint App server, not the WFE server.

You’ll notice the “np:” in front of the server name. This forces the Named Pipes Protocol and ignores the default protocol order. And this worked. I also tried “tcp:” to force TCP in the UDL and this worked to. I went back to my data source and tried forcing TCP there.

System.Data.SqlClient.SqlException: A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: TCP Provider, error: 0 - The requested name is valid, but no data of the requested type was found.)

This made no sense. I even made sure I was logged in as the RS Service Account as that is the context in which we would have been connecting to SQL. Same result. Also, within a network trace, I saw nothing on either the TCP or Named Pipes side of the house in the trace that related to this connection attempt. Which meant we never hit the wire.

As I was going to collect some additional diagnostic logging (Kerberos ETW tracing and LSASS Logging) I ended up doing an IISRESET and a recycle of the C2WTS service. We went to reproduce the issue, but got a different error this time.

System.IO.FileLoadException: Could not load file or assembly 'System.EnterpriseServices, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a' or one of its dependencies. Either a required impersonation level was not provided, or the provided impersonation level is invalid. (Exception from HRESULT: 0x80070542) File name: 'System.EnterpriseServices, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a' ---> System.Runtime.InteropServices.COMException (0x80070542): Either a required impersonation level was not provided, or the provided impersonation level is invalid. (Exception from HRESULT: 0x80070542)

This error I did know and can work with. I had blogged about this error last July here. Checking the “Act as part of the operating system” showed that the C2WTS service account in fact was not given that right. Adding that account to that policy right and restarting the C2WTS Windows Service and performing an IISRESET then yielded the following:

The connectivity errors were clearly related to the lack of the Policy Setting. It was unexpected and didn’t line up with normal connectivity related issues and also wasn’t very helpful with regards of where to go look for more information as all of the normal paths didn’t show anything useful.

Of note, I tried reproducing this on SharePoint 2013, but only got the FileLoadException. I think this is partly a timing issue with how IIS AppPools are started and the C2WTS service is started. Doesn’t mean you won’t see this on SharePoint 2013 necessarily. Even on SharePoint 2010, the first time I hit the FileLoadException.

Adam W. Saxton | Microsoft Escalation Services
http://twitter.com/awsaxton

SQL Server–Storage Spaces/VHDx and 4K Sector Size

2013-05-15T14:40:25Z

This blog outlines a new twist to my previous blog outlining issues with 4K sector sizes.

SQL Server - New Drives Use 4K Sector Size: http://blogs.msdn.com/b/psssql/archive/2011/01/13/sql-server-new-drives-use-4k-sector-size.aspx

In the previous post I discussed that it was unsafe for the I/O subsystem to present a sector size that was smaller than the actual, physical sector size. This leads to unsupported, Read-Modify-Write (RMW) behavior.

I was doing testing on a Windows 2012 Server - Storage Space setup and found that both Storage Spaces and the VHDx format can report a 4K sector size to the SQL Server. This allows the various drives setup in the pool for Storage Spaces to be of disparate sector sizes (Drive 1 = 512 bytes, 1K, 2K, and Drive 4 = 4K.)

Is this safe for SQL Server?

The answer is yes. An I/O subsystem can return a larger sector size than actual, physical sector size as long as all reported values can be evenly divided by 512 bytes.

As the diagram below shows, SQL Server maintains parity on 512 byte boundaries, for the log, regardless of the reported sector size. This allows SQL Server to detect a partial write (torn behavior.) For example, if the system reported a sector size of 4K but the physical sector size was 512 bytes, the I/O subsystem is only guaranteed to flush to a 512 byte mark. If the first 4, physical sectors are flushed (2K of the 4K aligned block) and a power outage occurs, SQL Server will be able to detect the entire 4K was not properly flushed.

Without the logical parity every 512 bytes SQL Server would be unable to detect the torn situation, leading to unexpected recovery and logging behavior(s).

WARNING: While SQL Server protects your data against such a failure the reporting of sector size, larger than physical sector size, can lead to unwanted/unexpected space usage. SQL Server will align the log writes to the reported sector size (4K in this example.)

SQL Server packs records within the log blocks and then aligns/pads the writes on the reported sector boundary. Lots of small transactions, leading to many log flushes, can result in wasted log space for a system reporting larger sector sizes. Moving the scenario to an I/O subsystem reporting smaller sector sizes can reduce space usage.

The easiest way to see this in action is a single worker doing tiny transactions.

while(1=1)

begin

insert into tblTest values (1) // Each insert is a transaction and a log flush

end

Each insert is a separate commit transaction, causing the log to be flushed for each iteration. In this example each insert will require at least 4K of log space to properly align during the flush. Wrapping a transaction around the while loop or only committing at reasonable boundaries (say 10,000 inserts) reduces the log flushing behavior and uses the log space more effectively.

Bob Dorr - Principal SQL Server Escalation Engineer

Using PowerShell to discover Reporting Services 2012 in SharePoint

2013-04-30T18:58:46Z

I was recently going through an exercise of documenting how to discover certain aspects of Reporting Services for some Kerberos work. RS 2012 in SharePoint is a totally different game though. The easiest way I could discover certain items about Reporting Services within SharePoint was with PowerShell. For previous versions, and RS 2012 in Native Mode, we can use other avenues such as WMI to discover configuration of Reporting Services.

Service Enumeration

One of the big things we want to do when we are discovering what is out there is to be able to tell if we even have the service installed. This may also lead to multiple services within SharePoint. Within SQL 2012, Reporting Services is a Shared Service within SharePoint and is deployed as such. We could run the following to see the Service Applications that are configured.

Get-SPServiceApplication |where {$_.TypeName -like "SQL Server Reporting*"}

This aligns with what we see in Central Admin as well.

From the Kerberos/Claims configuration perspective, we are also interested in the Service Account for the Reporting Services Application. Also keeping in mind that there may be more than one.

$apps = Get-SPServiceApplication |where {$_.TypeName -like "SQL Server Reporting*"}
foreach ($app in $apps){"{0,-20} {1,-20}" -f $app.name, $app.ApplicationPool.ProcessAccountName}

We can see that the name is “Reporting Services” and the AppPool Process Account is “BATTLESTAR\rsservice”. The next piece of information we want to know is which SharePoint boxes is this service running on? We could have any number of App Servers that we need to go check.

$services = Get-SPServiceInstance |where {$_.TypeName –like "*Reporting*"}
foreach ($service in $services){"{0,-20} {1,-20}" -f $service.parent.address, $service.status}

In this example, I only have one server that has the Reporting Services Service started within SharePoint and that is on the CAPTHELO server. We can then compare with the Claims to Windows Token Service (C2WTS).

Claims to Windows Token Service (C2WTS)

As part of SQL 2012 with SharePoint Integration, the Claims to Windows Token Service plays a big part in our functionality when it comes to Kerberos. As such, if we are going to validate RS 2012 in SharePoint configuration, we need to look at C2WTS as well. We can use the following PowerShell command to get the C2WTS instances:

Get-SPServiceInstance |where {$_.TypeName -like "*Claims*"}

One thing to remember is that C2WTS is not a service app. You may see multiple items here if they have more than one SharePoint Server. For example, in my environment I have two SharePoint Servers:

The service only needs to be started on the SharePoint Box where the Reporting Services Shared Service is started as well. In the Reporting Services example above, we know that Reporting Services is only active on CAPTHELO, so that is where C2WTS needs to be started.

$services = Get-SPServiceInstance |where {$_.TypeName –like "*Claims*"}
foreach ($service in $services){"{0,-20} {1,-20} {2}" -f $service.parent.address, $service.status, $service.Service.ProcessIdentity.username}

We can see that we have two SharePoint servers here. C2WTS is started on LTBOOMER but it is not running on CAPTHELO. This will result in an error such as the following:

Throwing Microsoft.ReportingServices.Diagnostics.Utilities.ClaimsToWindowsTokenLoginTypeException: , Microsoft.ReportingServices.Diagnostics.Utilities.ClaimsToWindowsTokenLoginTypeException: Can not convert claims identity to windows token. This may be due to user not logging in using windows credentials.;

From the last command above, we can also see the Process Identity for the C2WTS. So, this will provide the service accounts for both Reporting Services and C2WTS as well as let us know which servers Reporting Services is enabled on and which servers C2WTS needs to be enabled on. This could be very helpful when it comes to automation.

Adam W. Saxton | Microsoft Escalation Services
http://twitter.com/awsaxton

AlwaysON - HADRON Learning Series: lock_redo_blocked/redo worker Blocked on Secondary Replica

2013-04-26T18:34:06Z

The topic I received most in my inbox this week was redo blocked on a secondary while attempting to acquire SCH-M (schema modify) lock.

First of all, this is expected behavior and you can monitor for this with your standard blocking activities (sys.dm_exec_requests, blocked process TRC event, blocked process threshold configuration setting(s) and the log_redo_blocked XEvent.)

The SQL Server 2012 implementation of Always On extended the database mirroring (DBM) capabilities by allowing read only queries and backups against a secondary replica. With this new activity comes additional overhead.

1. When a replica is marked for read only capabilities the updated/inserted rows on primary add additional overhead for the row versioning to help support snapshot isolation activities of the read only connections.

2. When queries are run against the secondary the SCH-S (schema stability) lock is held during the query to make sure the schema of the object can’t be changed during the processing of results.

In the case of the blocked, redo the read only clients typically have long running queries and the object is changed (ALTER, create index, …) on the primary. When the DDL activity arrives on the secondary the SCH-M is required to complete the requested, redo change. This causes the redo worker to become blocked on the long running, read only query(s).

You can monitor the redo queue size and other performance counters to determine the relative impact of redo being blocked and make any necessary business decisions to KILL the head blocker(s). It will look no different than a production server with a head blocker that you resolve today.

Microsoft is evaluating, for future builds, the ability to configure a replica to automatically kill a redo blocker, allowing redo to progress.

Bob Dorr - Principal SQL Server Escalation Engineer

AlwaysON - HADRON Learning Series: HADR_SYNC_COMMIT vs WRITELOG wait

2013-04-26T16:54:25Z

The distinction between these two wait types is subtle but very helpful in tuning your Always On environment.

The committing of a transaction means the log block must be written locally as well as remotely for synchronous replicas. When in synchronized state this involves specific waits for both the local and remote, log block, harden operations.

HADR_SYNC_COMMIT = Waiting on response from remote replica that the log block has been hardened. This does not mean the remote, redo has occurred but instead that the log block as been successfully stored on stable media at the remote, replica. You can watch the remote, response behavior using the XEvent: hadr_db_commit_mgr_update_harden.

WRITELOG = Waiting on local I/O to complete for the specified log block.

The design puts the local and remote log block writes in motion at the same time (async) and then waits for their completion. The wait order is 1) remote replica(s) and 2) the local log.

The HADR_SYNC_COMMIT is usually the longer of the waits because it involves shipping the log block to the replica, writing to stable media on the replica and getting a response back. By waiting on the longer operation first the wait for the local write is often avoided.

Once the response is received any wait on the local (primary), log (WRITELOG) occurs as necessary.

Accumulation of HADR_SYNC_COMMIT wait time is the remote activity and you should look at the network and log flushing activities on the remote replica.

Accumulation of WRITELOG wait time is the local log flushing and you should look at the local I/O path constraints.

Reference: http://blogs.msdn.com/b/psssql/archive/2011/04/01/alwayson-hadron-learning-series-how-does-alwayson-process-a-synchronous-commit-request.aspx

Reference: http://blogs.msdn.com/b/psssql/archive/2013/04/22/how-it-works-always-on-when-is-my-secondary-failover-ready.aspx

Bob Dorr - Principal SQL Server Escalation Engineer

How It Works: Always On–When Is My Secondary Failover Ready?

2013-04-22T14:35:21Z

I keep running into the question: “When will my secondary allow automatic failover?” Based on the question I did some extended research and I will try to summarize in is blog post. I don’t want to turn this post into a novel so I am going to take some liberties and assume you have read SQL Server Books Online topics related to Always On failover.

The easy answer: Only when the secondary is marked SYNCHRONIZED. - End of blog right? – not quite!

At a 10,000 foot level that statement is easy enough to understand but the issue is really understanding what constitutes SYNCHRONIZED. There are several state machines that determine the NOT vs SYNCHRONIZED state. These states are maintained using multiple worker threads and at different locations to keep the system functional and fast.

Secondary Connection State
End Of Log Reached State

To understand these states I need to discuss a few concepts to make sure we are all on the same page.

Not Replicating Commits – Log Blocks Are The Replication Unit

The first concept is to remember SQL Server does not ship transactions. It ships log blocks.

The design is not really different than a stand alone server. On a stand alone server a commit transaction issues (FlushToLSN/StartLogFlush) to make sure all LSN’s up to and including the commit LSN flushed. This causes the commit to block the session, waiting for the log manager to indicate that all blocks of the log have been properly flushed to stable media. Once the LSN has been reached any pending transaction(s) can be signaled to continue.

Let’s use the diagram on the left for discussion.   The ODD LSNs are from Session 1 and the EVEN LSNs are from Session 2.

The Log Block is a contiguous, chunk of memory (often 64K and disk sector size aligned), maintained by the Log Manager. Each database has multiple log blocks maintained in LSN order. As multiple workers are processing they can use various portions of the log block, as shown here.

To make this efficient a worker requests space in the block to store its record. This request returns the current location in the log block, increments the next write position in the log block (to be used by the next caller) and acquires a reference count.   This makes the allocation of space for a log record only a few CPU instructions. The storage position movement is thread safe and the reference count is used to determine when the log block can be closed out.

In general, closing out a log block means all the space has been reserved and new space is being handed out for another log block. When all references are released the block can be compressed, encrypted, … and flushed to disk.

Note: A commit transaction (FlushToLSN/StartLogFlush) can trigger similar behavior, even when the block is not full, so a commit transaction does not have to wait for the block to become full.   Reference: http://support.microsoft.com/kb/230785

In this example both commits would be waiting on the log block to be written to stable media.

Session 1 – FlushToLSN (05)
Session 2 – FlushToLSN (06)

The log writer’s completion routine is invoked when the I/O completes for the block.   The completion routine checks for errors and when successful, signals any sessions waiting on a LSN <= 6.   In this case both session 1 and 2 are signaled to continue processing.

Write Log Waits accumulate during this wait for the flush activities.   You can read more about write log waits at: http://blogs.msdn.com/b/psssql/archive/2009/11/03/the-sql-server-wait-type-repository.aspx

Misconception

I had a discussion on an e-mail where the individual was thinking we only shipped committed transactions. Not true (for Always On or Database Mirroring). If I only shipped committed transactions it would require a different set of log blocks for EACH transaction. This would be terrible performance impacting overhead.   It would also be extremely difficult to handle changes on the same page.   If SQL Server doesn’t have the ACID series of log records how would SQL Server ever be able to run recovery, both redo and undo.   Throw in row versioning and shipping just the committed log records becomes very cumbersome.

We don’t ship log records, we ship log blocks and optimize the recovery needs.

Parallel Flushing / Hardening

Always On is a bit different than database mirroring (DBM) with respect to sending the log blocks to the secondary replica(s). DBM flushes the log block to disk and once completed locally, sends the block to the secondary.

Always On changed this to flush the block(s) in parallel. In fact, a secondary could have hardened log block(s) before the primary I/O completes. This design increases performance and narrows the NOT IN SYNC window(s).

SQL Server uses an internal, callback mechanism with the log manager. When a log block is ready to be flushed (fully formatted and ready to write to disk) the notification callbacks are fired. A callback you might expect is Always On. These notifications start processing in parallel with the actual flushing of the log to the local (LDF) stable media.

As the diagram shows, the race is on. One worker (log writer) is flushing to the local media and the secondary consumer is reading new blocks and flushing on the secondary. A stall in the I/O on the primary can allow the secondary to flush before the primary just as a delay on the secondary could cause the primary to flush the I/O before the secondary.

My first reaction to this was, oh no, not in sync this is bad. However, the SQL Server developers didn’t stop at this juncture, Always On is built to handle this situation from the ground up.

Not shown in the diagram are the progress messages. The secondary sends messages to the primary indicating the hardened LSN level. The primary uses that information to help determine synchronization state. Again, these messages execute in parallel to the actual log block shipping activities.

Cluster Registry Key for the Availability Group

The cluster, AG resource is the central location used to maintain the synchronization states. Each secondary has information stored in the AG resource key (binary blob) indicating information about the current LSN levels, synchronization state and other details. This registry key is already replicated, atomically across the cluster so as long as we use the registry at the front of our WAL protocol design the AG state is maintained.

Note: We don’t update the registry for every transaction. In fact, it is seldom updated, only at required state changes. What I mean by WAL protocol here is that the registry is atomically updated before further action is taken on the database so the actions taken in the database are in sync with the registry across the cluster.

Secondary Connection State (Key to Synchronized State)

The design of Always On is a pull, not a push model. The primary does NOT connect to the secondary, the secondary must connect to the primary and ask for log blocks.

Whenever the secondary is NOT connected the cluster registry is immediately updated to NOT SYNCHRONIZED. Think if it this way. If we can’t communicate with the secondary we are unable to guarantee the state remains synchronized and we protect the system by marking it NOT SYNCHRONIZED.

Primary Database Startup

Whenever a database is taken offline/shutdown the secondary connections are closed. When the database is started we immediately set the state of the secondary to NOT SYNCHRONIZED and then recover the database on the primary. Once recovery has completed the secondary(s) are allowed to connect and start the log scanning activity.

Note: There is an XEvent session, definition included at the end of this blog, that you can be use to track several of the state changes.

Connected

Once the secondary is connected it asks (pull) for a log scan to begin. As the XEvents show, you can see the states change for the secondary scanner on the primary.

Uninitialized	The secondary has connected SQL Server but it has not sent LSN information yet.
WaitForWatermark	Waiting for the secondary to reconcile the hardened log LSN position on the secondary with the cluster key and recovery information. The secondary will send its end-of-log (EOL) LSN to the primary.
SendingLog	The primary has received the end-of-log position from the secondary so it can send log from the specified LSN on the primary to the secondary.

Note: None of these states alone dictate that the secondary is IN SYNC. The secondary is still marked as NOT SYNCHRONIZED in the cluster registry.

Hardened Log On Secondary

You will notice the 3rd column is indicating the commit, harden policy. The harden policy indicates how a commit transaction should act on the primary database.

DoNothing	There is no active ‘SendingLog’ so the commits on the primary don’t wait for acknowledgement from the secondary. There is no secondary connected so it can’t wait for an acknowledgement even if it wanted to. The state of the secondary must remain NOT SYNCHRONIZED as the primary is allowed to continue. I tell people this is why it is called HADR and not DRHA. High Availability (HA) is the primary goal so if a secondary is not connected the primary is allowed to continue processing. While this does put the installation in danger of data loss it allows production uptime and alternate backup strategies to compensate.
Delay	When a secondary is not caught up to the primary end–of-log (EOL) the transaction commits are held for a short delay period (sleep) helping the secondary catch up. This is directly seen while the secondary is connected and catching up (SYNCHRONIZING.)
WaitForHarden	As mentioned earlier the secondary sends progress messages to the primary. When the primary detects that the secondary has caught up to the end of the log the harden policy is changed to WaitForHarden. SYNCHRONIZING – DMVs will show synchronizing state until the end-of-log (EOL) is reached. Think of as a catch up phase. You can’t be synchronizing unless you are connected. SYNCHRONIZED – This is the point at which the secondary is marked as SYNCHRONIZED. (Secondary is connected and known to have achieved log block hardening with the primary EOL point.) !!! SYNCHRONIZED IS THE ONLY STATE ALLOWING AUTOMATIC FAILOVER !!! From this point forward all transactions have to wait for the primary (log writer) and secondary to advance the LSN flushes to the desired harden location. Going back to the first example, Session 2 waits for all LSNs up to and including 06 to be hardened. When involving the synchronous replica this is a wait for LSNs up to 06 to be hardened on the primary and the secondary. Until the progress of both the primary and secondary achieve LSN 06 the committing session is held (Wait For Log Flush.)

Clean vs Hard Unexpected Database Shutdowns

When you think about database shutdown there are 2 main scenarios, clean and unexpected (hard). When a clean shutdown occurs the primary does not change the synchronized state in the cluster registry. Whatever the current synchronization state is at the time the shutdown was issued remains sticky. This allows clean failovers, AG moves and other maintenance operations to occur cleanly.

Unexpected, can’t change the state if the unexpected action occurs at the service level (SQL Server process terminated, power outage, etc..). However, if the database is taken offline for some reason (log writes start failing) the connection to the secondary(s) are terminated and terminating the connection immediately updates the cluster registry to NOT SYNCHRONIZED. Something like failure to write to the log (LDF) could be as simple as an administrator incorrectly removing a mount point. Adding the mount point back to the system and restarting the database restores the system quickly.

Scenarios

Now I started running scenarios on my white board. I think a few of these are applicable to this post to help solidify understanding.

In Synchronized State
Primary flushed LSN but not flushed on Secondary

Primary experiences power outage.
Automatic failover is allowed.
The primary has flushed log records that the secondary doesn’t have and the commits are being held.
Secondary will become the new primary and recovers.
When old primary is restarted the StartScan/WaitForHarden logic will rollback to the same location that the new primary, effectively ignoring the commits flushed but never acknowledged.

In Synchronized State
Secondary flushed LSN but not flushed on Primary

Primary experiences power outage.
Automatic failover is allowed.
Secondary has committed log records that primary doesn’t have.
Secondary becomes new primary and recovers.
When old primary is restarted the StartScan/WaitForHarden logic will detect a catch up is required.

Note: This scenario is no different than a synchronized secondary that has not hardened as much as the primary. If the primary is restarted on the same node, upon connect, the secondary will start the catch up activity (SYNCHRONIZING), get back to end of log parity and return to SYNCHRNONED state.

The first reaction when I draw this out for my peers is, we are loosing transactions. Really we are not. We never acknowledge the transaction until the primary and secondary indicate the log has been hardened to LSN at both locations.

If you take the very same scenarios to a stand alone environment you have the same timing situations. The power outage could happen right after the log is hardened but before the client is sent the acknowledgement. It looks like a connection drop to the client and upon restart of the database the committed transaction is redone/present. In contrast, the flush may not have completed when the power outage occurred so the transaction would be rolled back. In neither case did the client receive an acknowledgement of success or failure for the commit.

SYNCHRONIZED – AUTOMATIC FAILOVER ALLOWED

Going back to the intent of this blog, only when the cluster registry has the automatic, targeted secondary, marked SYNCHRONIZED is automatic failover allowed. You can throw all kinds of other scenarios at this but as soon as you drop the connection (restart the log scan request, …) the registry is marked NOT SYNCHRONIZED and it won’t be marked SYNCHRONIZED again until the end-of-log (EOL) sync point is reached.

Many customers have experienced failure to allow fail over because they stopped the secondary and then tried a move. They assumed that because they no longer had primary, transaction activity it was safe. Not true as ghost, checkpoint and other processes can still be adding log records. As soon as you stop the secondary, by definition you no longer have HA so the primary marks the secondary NOT SYNCHRONIZED.

As long as the AG failover detection can use proper, cluster resource offline behaviors, SQL Server is shutdown cleanly or SQL Server is terminated harshly, while the secondary is in the SYNCHRONIZED state, automatic failover is possible. If the SQL Server is not shutdown but a database is taken offline the state is updated to NOT SYNCHRONIZED.

Single Failover Target

Remember that you can only have a single, automatic failover target. To help your HA capabilities you may want to setup a second, synchronous replica. While it can’t be the target of automatic failover it could help High Availability (HA).

For example, the automatic failover, secondary target machine has a power outage. Connection on primary is no longer valid so the secondary is marked NOT SYNCHRONIZED. The alternate synchronous, replica can still be SYNCHRONIZED and a target for a manual move WITHOUT DATA LOSS. The automatic failover target, in this example, is only a move WITH ALLOW DATA LOSS target.

Don’t forget that to enable true HA for this example the replica(s) should have redundant hardware. Second network cards, cabling and such. If you use the same network and a networking problem arises the connections on the primary are dropped and that immediately marks the replica(s) NOT SYNCHRONIZED.

Resolving State

Most of the time the question addressed in this post comes up because the secondary is NOT becoming the primary and is in Resolving state. Looking at the state changes leading up to the issue the secondary was in SYNCHRONIZING. When the primary goes down the secondary knows it was not SYNCHRONIZED. The secondary is attempting to connect to the a primary and the primary is down so the state is RESOLVING.

-------------------------------------------------------------------------------------------------------

Customizing Failover – All Kinds of Options

A secondary question that always follows this main question is: “If a disk fails on my database, within an AG why does automatic failover not occur?”

The short answer is that the secondary connections are dropped during database shutdown – NOT SYNCHRONIZED. (SQL Server development is looking into keeping the SYNCHRONIZED state in this situation instead of forcing NOT SYNCHRONIZED in vNext, opening up the window for automatic failover possibilities.)

The other part of the answer is that the built-in, failover logic is not designed to detect a single database failure. If you look at the failure conditions in SQL Server Books Online none of these are database level detections.

I was part of the work we did to enhance the failover diagnostics and decision conditions/levels. We specifically considered the custom solution needs. We evaluated dozens of scenarios, ranked and targeted those conditions safe for the broad customer base using Always On. This design specifically involved allowing any customer to extend the logic for your specific business needs. We made sure the mechanisms, the SQL Server and resource DLL use, were using publicly consumable interfaces and documented in SQL Server Books Online.

Note: All of the following can be done with PowerShell.

XEvents

For XEvents you can use the XEvent Linq Reader and monitor a live feed from the SQL Server. The easiest way to accomplish this would be to setup a SQL Agent job (continuous running so if the processes exits it restarts itself) which launches a C# executable or Powershell script.

The job can make sure it is only starting the executable on the primary server.
The executable can make sure the proper XEvent sessions are running (these sessions can even be defined to startup during SQL Server, service startup).
The executable can monitor the steam of events for the custom trigger points you consider critical to your business needs and when the parameters fall out of the desired boundary(s) issue the Cluster command to MOVE the AG to another node.
The XEvent session can also write to a file (.XEL) so the system has history of the event stream as well.

Note: The executable should be drop connection resilient. The design of the XEvent live stream is to terminate the connection for the stream if the server detects the event stream is stalled (client not processing events fast enough.) This means the client needs to detect the connection failure and reset. This usually means actions are posted to a worker thread in the application and the main reader only accepts the events and hands them to background tasks.

Example: http://sqlblog.com/blogs/extended_events/archive/2011/07/20/introducing-the-extended-events-reader.aspx

sp_server_diagnostics (http://msdn.microsoft.com/en-us/library/ff878233.aspx)

This was specifically designed to flow across a T-SQL connection (TDS) so anyone using a SQL Server client (.NET, ODBC, OLDEB, …) can execute the procedure and process the results. You don’t want dozens of these running on the SQL Server but you could easily monitor this stream as well and take any custom actions necessary.

Note: The I/O result row is NOT used by the SQL Server resource dll to make failover decisions. It is used for logging purposes only. It is not safe assumption that an I/O stall would be resolved by a failover of the system or even restart of the service. We have many examples of virus scanners and such components that can cause this issue and it would lead to a Ping-Pong among nodes if we trigger automated failover to occur.

DMVs and Policy Based Management (PBM)

In most cases it will be more efficient to setup an XEvent to monitor various aspects of the system. (Specific errors, database status changes, AG status changes, ….). However, the DMVs are also useful and a great safety net. We use many of the DMVs and the PBM rules to drive the Always On dashboard. You can create your own policies and execute them as well as using the XEvent predicates to limit the events produced.

Between some DMV queries and the policies you can easily detect things like corruption errors occurring, loss of a drive, etc…

External Factor Detections

Using PowerShell and WMI you can query information about the machine. For example you can check each drive for reported failure conditions, such as too many sector remaps or temperature problems. When detected you can take preemptive action to move the AG and pause the node, marking it for proper maintenance.

Example
$a = get-wmiobject win32_DiskDrive
$a[0] | get-member

Loss of LDF (No Automatic Failover)

A specific tenant of Always On is – protect the data- don’t automate things that can lead to data loss.

The scenario is a mount point, used to hold the LDF, is mistakenly removed from the primary node. This causes the SQL Server database to become suspect, missing log file but does not trigger automatic failover.

If the mount point can simply be added back to the node the database can be brought back online and business continues as usual, no data loss. If we had forced failover (ALLOW DATA LOSS) it could have led to data loss for a situation that the administrators could have cleanly resolved.

When the secondary drops a connection (loss of network, database LDF is damaged, …) the state is updated to ‘not synchronized’, preventing automatic failover. We are careful because allowing anything else may lead to split brain and other such scenarios that cause data loss. Furthermore, if you change a primary to a secondary it goes into recovery state and at that point if we had serious damage and needed to recover the data it is much more difficult to access the database.

A situation like this requires a business decision. Can the issue be quickly resolved or does it require a failover with allow data loss?

To help in preventing data loss the replicas are marked suspended. As described in the following link you can use a snapshot database, before resuming, to capture the changes that will be lost. http://msdn.microsoft.com/en-us/library/ff877957.aspx Then using T-SQL queries and facilities such as TableDiff one can determine the best reconciliation.

Also reference: http://download.microsoft.com/download/D/2/0/D20E1C5F-72EA-4505-9F26-FEF9550EFD44/Building%20a%20High%20Availability%20and%20Disaster%20Recovery%20Solution%20using%20AlwaysOn%20Availability%20Groups.docx

Note: You want to make sure the snapshot has a short life span to avoid the additional overhead for a long period of time and the fact that is can hold up other operations, such as File Stream garbage collection actions.

One could build additional monitoring to:

Make sure primary was marked suspended
Force the failover with allow data loss
Create snapshot on OLD primary
Resume OLD primary as a new secondary

Then take appropriate business steps to use the data in the snapshot to determine what the data loss would/could be. This is likely to involve a custom, data resolver design (much like the custom conflict resolution options of database replication) to determine how the data should be resolved.

Don’t Kill SQL

Killing SQL Server is a dangerous practice. It is highly unlikely but I can never rule out that it may be possible to introduce unwanted behavior, such as when SQL Server is attempting to update the cluster registry key, leaving the key corrupted. A corrupted registry key, blob for the Availability Group (AG) would then render every replica of the AG damaged because the AG configuration is damaged, not the data! You would then have to carefully drop and recreate the AG in a way that did not require you to rebuild the actual databases but instead allows the cluster configuration to be corrected. It is only few minute operation, once discovered, to fix it but immediate downtime and is usually a panic stricken situation.

SQL Server is design to handle power outages and tested well to accommodate this. Kill is a bit like simulating a power outage and not something Microsoft would recommend as a business practice. Instead you should be using something like PowerShell and issuing a ‘move’ of the availability group in a clean and designed way.

Example: (Move-ClusterResource) http://technet.microsoft.com/en-us/library/ee461049.aspx

XEvent Session

CREATE EVENT SESSION [HadronSyncStateChanges_CommitHardenPolicies] ON SERVER

ADD EVENT sqlserver.hadr_db_commit_mgr_set_policy( ACTION(package0.callstack,sqlserver.database_name)),

ADD EVENT sqlserver.hadr_db_commit_mgr_update_harden( ACTION(package0.callstack,sqlserver.database_name)),

ADD EVENT sqlserver.hadr_db_partner_set_sync_state( ACTION(package0.callstack,sqlserver.database_name)),

ADD EVENT sqlserver.hadr_db_manager_state (ACTION(package0.callstack,sqlserver.database_name)),

ADD EVENT sqlserver.hadr_ag_wsfc_resource_state(ACTION(package0.callstack,sqlserver.database_name)),

ADD EVENT sqlserver.hadr_scan_state( ACTION(package0.callstack,sqlserver.database_name))

ADD TARGET package0.event_file(SET filename=N'C:\temp\SyncStates',max_rollover_files=(100))

WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=NO_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=PER_CPU,TRACK_CAUSALITY=ON,STARTUP_STATE=ON)

Bob Dorr - Principal SQL Server Escalation Engineer

SQLIOSim Checksum Validations

2013-04-05T14:57:16Z

I had a very specific question asked of me related to the SQLIOSIM.exe, checksum validation logic. It is pretty simple logic (on purpose) but effective so here are the basics.

The key is that there are multiple memory locations used to hold the data and do the comparison.

1. Allocate a buffer in memory of 8K.
Stamp the page with random data using Crypto Random function(s)
Save Page Id, File Id, Random seed and calculated checksum values in the header of the page

2. Send the page to stable media (async I/O)
Check for proper write completion success

3. Sometime after successful write(s). Allocate another buffer and read the data from stable media.
(Note: This is a separate buffer from that of the write call)

4. Validate the bytes read.

Do header checks for file id, page id, seed and checksum values

Expected CheckSum: 0xEFC6D39C ---------- Checksum stored in the WRITE buffer

Received CheckSum: 0xEFC6D39C ---------- Checksum stored in the READ buffer (what stable media is returning)

Calculated CheckSum: 0xFBD2A468 --------- Checksum as calculated on the READ buffer

The detailed (.TXT) output file(s) show the WRITE image, the READ image and the DIFFERENCES found between them (think memcmp). When only a single buffer image is added to the detailed TXT file this indicates that the received header data was damaged or the WRITE buffer is no longer present in memory so only the on disk checksum vs calculated checksum are being compared.

If there appears to be damage SQLIOSim will attempt to read the same data 15 more times and validate before triggering the error condition. Studies from SQL Server and Exchange showed success of read-retries in some situations. SQL Server and Exchange will perform up to 4 read-retries in the same situation.

The window for damage possibilities is from the time the checksum is calculated to the time the read is validated. While this could be SQLIOSim the historical evidence shows this is a low probability. The majority of the time is in kernel and I/O path components and the majority of bugs over the last 8 years have been non-SQL related.

For vendor debugging the detailed TXT file contains the various page images as well as the sequence of Win32 API calls, thread ids and other information. Using techniques such as a bus analyzer or detailed I/O tracing the vendor can assist at pin-pointing the component causing the damage.

The top of the 8K page header is currently the following (Note: This may change with future versions of SQLIOSim.exe)

DWORD       Page Number     (Take * 8192 for file offset)

DWORD       File Id

DWORD       Seed value

DWORD       Checksum CRC value

BYTE             Data[8192 – size(HEADER)]   <--------- Checksum protects this data

Bob Dorr - Principal SQL Server Escalation Engineer

The Case of Anti-Virus filter drive interference with File Stream Restore

2013-03-29T21:47:06Z

"Denzil and I were working on this issue for a customer and Denzil has been gracious enough to write-up a blog for all of us." – Bob Dorr

From Denzil:

I recently worked with a customer on a Database restore issue where the database being restored had 2TB of File stream data. The restore in this case would just not complete successfully and would fail with the error below.

10 percent processed.

20 percent processed.

30 percent processed.

40 percent processed.

Msg 3634, Level 16, State 1, Line 1

The operating system returned the error '32(The process cannot access the file because it is being used by another process.)' while attempting 'OpenFile' on 'F:\SQLData11\DataFiles\535cc368-de43-4f03-9a64-f5506a3f532e\547fc3ed-da9f-44e0-9044-12babdb7cde8\00013562-0006edbb-0037'.

Msg 3013, Level 16, State 1, Line 1

RESTORE DATABASE is terminating abnormally.

Subsequent restore attempts would fail with the same error though on "different" files and at a different point in the restore cycle.

Given that this was "not" the same file or the same point of the restore on various attempts my thoughts immediately went to some filter driver under the covers wreaking some havoc. I ran an a command to see what filter drivers were loaded (trimmed output below.)

C:\>fltmc instances

Filter Volume Name Altitude Instance Name

-------------------- ----------------------- ------------ ---------------------- -----

BHDrvx64 F:\SQLData11 365100 BHDrvx64 0

eeCtrl F:\SQLData11 329010 eeCtrl 0

SRTSP F:\SQLData11 329000 SRTSP 0

SymEFA F:\SQLData11 260600 SymEFA 0

RsFx0105 \Device\Mup 41001.05 RsFx0105 MiniFilter Instance 0

SymEFA         = Symantec extended file attributes driver
SRTSP        = Symantec Endpoint protection
RsFx0105     = SQL Server File Stream filter driver.

In discussing this with the customer, Anti-virus exclusions were controlled by GPO so he had put in a request to exclude the respective folders, yet the issue still continued.

In order to do my due diligence, the other question was whether we "released" the file handle after we created it, and whether someone else grabbed it? So we (Venu, Bob and I) did take a look at the code and this can be the case. On SQL Server 2008 R2 when we call the CreateFile API and we hardcode the shareAccess parameter to 0 which is exclusive access while we have it open to prevent secondary access.

http://msdn.microsoft.com/en-us/library/windows/desktop/aa363858(v=vs.85).aspx

If this parameter is zero and CreateFile succeeds, the file or device cannot be shared and cannot be opened again until the handle to the file or device is closed. For more information, see the Remarks section.

Once the file is created, we release the EX latch and can close the file handle, on the file, but sqlservr.exe continues to hold the lock on the file itself during the restore process. Once the restore operation is completed, we no longer hold an exclusive lock to the file.

We can reopen file handles during the Recovery process so the other thought was perhaps it was a transaction affected by recovery and GC and potentially some race condition but in this case we know that the restore was failing prior to that as it didn't reach 100% so that could be ruled out as well.

Getting a dump at the failure time showed me the same Restore Stack but different dumps showed multiple different files in question so it wasn't a particular Log record sequence per say causing this.

sqlservr!ex_raise
sqlservr!HandleOSError

sqlservr!FileHandleCache::OpenFile
sqlservr!FileHandleCache::ProbeForFileHandle
sqlservr!FileHandleCache::GetFileHandle
sqlservr!RestoreCopyContext::RestoreFilesystemData
BackupIoRequest::StartDatabaseScatteredWrite

Given now that it was unlikely it was SQL Server, I concentrated more on the Filter driver theory. I tried to capture Process monitor, but given the time it took and amount of files touched, Process monitor was not all that useful. I couldn't filter on a specific folder as it failed on different folders and there were 10 + mount points involved.

However from Process monitor while the restore was going on, I looked at the stack for some I/O operations (not ones that failed by any means) and I still saw fltmgr.sys sitting there for an OpenFile Call on a file in the filestream directory

fltmgr.sys + 0x2765	0xfffffa6001009765	C:\Windows\system32\drivers\fltmgr.sys
fltmgr.sys + 0x424c	0xfffffa600100b24c	C:\Windows\system32\drivers\fltmgr.sys
fltmgr.sys + 0x1f256	0xfffffa6001026256	C:\Windows\system32\drivers\fltmgr.sys
ntoskrnl.exe + 0x2c8949	0xfffff80002918949	C:\Windows\system32\ntoskrnl.exe
ntoskrnl.exe + 0x2c0e42	0xfffff80002910e42	C:\Windows\system32\ntoskrnl.exe
ntoskrnl.exe + 0x2c19d5	0xfffff800029119d5	C:\Windows\system32\ntoskrnl.exe
ntoskrnl.exe + 0x2c6fb7	0xfffff80002916fb7	C:\Windows\system32\ntoskrnl.exe
ntoskrnl.exe + 0x2b61a8	0xfffff800029061a8	C:\Windows\system32\ntoskrnl.exe
ntoskrnl.exe + 0x57573	0xfffff800026a7573	C:\Windows\system32\ntoskrnl.exe
ntdll.dll + 0x471aa	0x77b371aa	C:\Windows\System32\ntdll.dll  ZwOpenFile
kernel32.dll + 0x10d48	0x779d0d48	C:\Windows\system32\kernel32.dll
kernel32.dll + 0x10a7c	0x779d0a7c	GetVolumeNameForRoot
_____SQL______Process______Available + 0x695c7e	0x1a080fe	GetVolumeDeviceNameAndMountPoint
_____SQL______Process______Available + 0x6d6898	0x1a48d18	ParseContainerPath
_____SQL______Process______Available + 0x6d714a	0x1a495ca	sqlservr!CFsaShareFilter::RsFxControlContainerOwnership

Also looking at some other Symantec related issues, I found an article not necessarily to do with any SQL restores but the fact that this was a possibility – again this has to do with a specific issue on a specific build, but am illustrating that Filter drivers can cause some unexpected behaviors.

As far as Anti-virus exclusions go, we actually have guidance in the article below: http://support.microsoft.com/kb/309422

And also in our File stream best practices article: http://msdn.microsoft.com/en-us/library/dd206979(v=SQL.105).aspx

When you set up FILESTREAM storage volumes, consider the following guidelines:

•Turn off short file names on FILESTREAM computer systems. Short file names take significantly longer to create. To disable short file names, use the Windows fsutil utility.

•Regularly defragment FILESTREAM computer systems.

•Use 64-KB NTFS clusters. Compressed volumes must be set to 4-KB NTFS clusters.

•Disable indexing on FILESTREAM volumes and set disablelastaccess to set disablelastaccess, use the Windows fsutil utility.

•Disable antivirus scanning of FILESTREAM volumes when it is not unnecessary. If antivirus scanning is necessary, avoid setting policies that will automatically delete offending files.

•Set up and tune the RAID level for fault tolerance and the performance that is required by an application.

Looking at another run of "fltmc instances" command output and still saw the Anti-virus components on the list for those mount points. Given we "thought" we had put an exclusion in for the whole drive, and it was showing up, it was time to look at this closer

Excluded the drives where the data was being stored – Restore still failed
Stopped the AV Services - Restore still failed
Uninstalled Anti-virus – Restore now succeeded

Voila once we uninstalled AV on this machine, the restore succeeded. The customer is broaching this this with the AV vendor to figure out more of the root cause.

Denzil Ribeiro – Senior PFE