Tag Archives: troubleshoot

Application timing out due to excessive blocking on tempdb PFS

Problem

Applications Connecting to SQL Server timing out

Symptoms

  1. Excessive blocking with the wait resource being tempdb PFS page
  2. High CPU utilization on the server

Troubleshooting

sys.dm_exec_requests reported blocking and the head blocker looked like this

session_id ecid wait_type resource
---------- ----- --------------- --------------------
58 4 PAGELATCH_UP 2:7:32352
58 1 CXPACKET
58 5 CXPACKET
58 6 CXPACKET
58 3 CXPACKET
58 2 CXPACKET
58 0 CXPACKET exchangeEvent id=Pipe7dd014b80

The wait resource was always reported at tempdb PFS page (2:7:(8088*x)).

The head blocker and the blocking session were executing a SELECT against a XML document.

As explained here parsing a XML document would create work table in tempdb. In this situation the application was parsing a lot of XML documents. Hence the contention on tempdb was justified.

  • tempdb had 5 data files and the data files had initial size of 100 MB (with autogrowth of 10%). As per the recommendations here, increased the tempdb files to 8 and increased the initial size to a higher value to reduce the auto growth.
  • Also enabled trace flag 1118. This forces uniform extent allocations instead of mixed page allocations.
  • Enabled trace flag 1117. This will auto grow all the files in the filegroup whenever one of the files tries to auto grow.
  • Since this instance was running on SQL Server 2012, applied the latest Service Pack + CU as recommended in http://support.microsoft.com/kb/2964518

The tempdb contention got reduced to some extent still the CPU utilization was very high(above 85%). Because of this the application was still timing out.

  • Changed the Power Plan to “High Performance” as explained in http://support.microsoft.com/kb/2207548. This didn’t help much.
  • As you notice in the sys.dm_exec_requests output, all threads in the session are waiting on CXPACKET wait type for one thread to complete its work. Hence set the appropriate value for max degree of parallelism (3 in this case) as explained here.

CPU utilization came down from 85% + to 20-30%

Status

Mission accomplished!

SQL Server Cluster resource fails with “Data source name not found and no default driver specified” error

Last week I had worked on SQL Server 2008 R2 installation on a Windows Cluster. The installation would go fine until the installer tries to bring the SQL Server resource online. At that time it would fail with the following error message,

The cluster resource 'SQL Server' could not be brought online. Error: The group or resource is not in the correct state to perform the requested operation. (Exception from HRESULT: 0x8007139F)

On clicking OK, the installation would not fail but the SQL Server resource would continue to remain in failed state. Looking at System/Application Event Logs wasn’t of much help. From the SQL Server error logs it was evident that the Service was getting started successfully but it was getting stopped after the Cluster Manager failed to bring the resource online after 10 attempts.

The cluster log revealed that the resource was failing to come online with the following error

ERROR [IM002] [Microsoft][ODBC Driver Manager] Data source name not found and no default driver specified

Since SQL Server service is working fine, the problem is for sure outside SQL Server. The resolutions mentioned here and here, did not help.

As we already know, the Windows Failover Cluster manager uses SQSRVRES.dll to connect and manage the SQL Server Cluster resource. Hence looked at the properties of SQSRVRES.dll to check if there was any problems with it. This DLL was just fine but its version was 11.0.2100. This is strange since the version of SQL Server that we were trying to install was SQL Server 2008 R2 (10.50.xxxx). On checking customer informed that he had tried installing SQL Server 2012 earlier on this server but it was uninstalled for some reasons.

This clearly seemed to be the root cause. Hence copied the SQSRVRES.dll from a server which already had SQL Server 2008 R2 installed and overwrote it on the server in question. After this the installation succeeded and the SQL Sever cluster resource also came online just fine.

CDC job failing with “Unable to add entries to the Change Data Capture LSN time mapping table to reflect dml changes applied to the tracked tables” error

I got a chance work on CDC job failure issue recently. The customer had configured CDC on the database but it wasn’t working as expected. Hence he had disabled/enabled CDC multiple times on this database.

The “cdc.[DBName]_capture” job was failing with the following error

Message: 22858, Level 16, State 1
Unable to add entries to the Change Data Capture LSN time mapping table to reflect dml changes applied to the tracked tables. Refer to previous errors in the current session to identify the cause and correct any associated problems. [SQLSTATE 42000] (Error 22858) The statement has been terminated. [SQLSTATE 01000] (Error 3621). NOTE: The step was retried the requested number of times (10) without succeeding. The step failed.

Since the error message had reference to “Change Data Capture LSN time mapping table”, I looked into the cdc.lsn_time_mapping table. On a normal CDC configuration this table would have an entry for each transaction that was captured. But in this case, there was only one entry but the “tran_begin_time” and “tran_end_time” columns had a value which was a couple of days old. Also the tran_begin_lsn was printed as 0x00000000000000000000 and tran_id was 0x00. This isn’t normal.

To get more details about this error, I added a verbose log to the CDC capture job.

The verbose log printed the following message when the job was running.

session_id error_message
----------- ----------------------------------------------
5 Violation of PRIMARY KEY constraint 'lsn_time_mapping_clustered_idx'. Cannot insert duplicate key in object 'cdc.lsn_time_mapping'. The duplicate key value is (0x0008236700032c170001). CF8:0005
5 Unable to add entries to the Change Data Capture LSN time mapping table to reflect dml changes applied to the tracked tables.

From the verbose log it was evident that the CDC capture job was trying to insert a duplicate row the object cdc.lsn_time_mapping and failing.

The sys.databases DMV reported that the log_reuse_wait_desc was REPLICATION.

name database_id log_reuse_wait_desc
---------------- ----------- ---------------------
master 1 NOTHING
tempdb 2 NOTHING
model 3 LOG_BACKUP
msdb 4 NOTHING
CDC_DB_NAME 5 REPLICATION

This indicated that another CDC or replication was active on this database. Since there was no replication configured on this instance, it had to be a CDC job.

DBCC OPENTRAN reported that there was another CDC transaction was active on this database

Transaction information for database 'cdc_db_name'.
Replicated Transaction Information:
Oldest distributed LSN : (0:0:0)
Oldest non-distributed LSN : (533351:207666:1)
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Since customer had attempted enabling/disabling CDC multiple there was a possibility that a stale CDC transaction was still active on the database. To clear the article cache of CDC, executed sp_replflush against the database in question.

After restarting the job, it again failed but with a different error message now.

Another connection is already running 'sp_replcmds' for Change Data Capture in the current database.

DBCC OPENTRAN reported that there was a open transaction on the database but it was a user transaction which wasn’t running sp_replcmds.

Executed sp_replflush one more time and restarted the job again. This time it didn’t fail and also we started seeing rows getting inserted into all the CDC related tables.

Since the issue at hand was resolved, didn’t delve into the root cause. Most likely it was a stale CDC transaction which wasn’t cleaned up when CDC was disabled on the database.

Export the Event Logs without opening MMC

I recently worked on a database corruption issue. In order to troubleshoot this I had to collect all the Event Logs from the server. But when I tried to open Event Viewer, MMC would fail with the following error.

MMC could not create the snap-in.
Name: Event Viewer
CLSID: FX:{b05566ad-fe9c-7a4cbb7cb510}

For that matter any MMC snap-in on the server would fail with the same error. But getting the event logs was critical to get troubleshooting going. Thats when Wevtutil.exe which ships with the Windows Operating System came to the rescue.

Wevtutil.exe is by default located in the C:\windows\system32 folder.

I had to just execute the following command to export the System Event Log to C:\SystemLogBackup.evtx

wevtutil.exe epl System C:\SystemLogBackup.evtx

The “epl” parameter exports the event log specified (System in this case) to the destination file.
All I had to do is copy the exported file to my local desktop and double click it to open in the Event Viewer snap-in.

SavedLogs

This is indeed a good tool to have in a DBA’s armory.

Log reader fails with “The process could not execute ‘sp_replcmds’ ” error

Recently I worked on an issue in which the Replication wasn’t working right after setting it up. The Publication and the subscriptions were created successfully but the subscription was still uninitialized.

As a first step checked the status of the Snapshot Agent under Replication Monitor. It was failing with the following error message.

The concurrent snapshot for publication 'Sitecore_301_Redirect' is not available because it has not been fully generated or the Log Reader Agent is not running to activate it.

The Snapshot agent was correct that the snapshot was not generated and also the Log Reader agent wasn’t running. The Log Reader agent was failing with the error below.

The process could not execute 'sp_replcmds' on {ServerName}

The above message a very generic in nature. Hence I added a verbose log to the Log Reader Agent as explained in this KB article.

-Continuous -Output "D:\VerboseLog\Log.txt" -Outputverboselevel 3
LogReader_VerboseLog

 

Here is what was recorded in the Log Reader agent when the job failed the next time

Status: 0, code: 15517, text: 'Cannot execute as the database principal because the principal "dbo" does not exist, this type of principal cannot be impersonated, or you do not have permission.'.

sys.databases DMV reported that the current owner of the job wasn’t a DBO on the Publication Database. Hence the next logical step was to make the job owner the DBO of the database by executing

sp_changedbowner '{LoginName}'

After this change, all the replication agents worked without any problems and data started flowing to the subscriber.

SQL Server Agent failing to start with the error “StartServiceCtrlDispatcher failed (error 6)”

Recently I worked on an issue where SQL Server Agent was failing to start. Before this there was some problems with the disks on the server and the databases were restored from backups.

I started looking for errors in few of the logs

  • System Event Log – No errors
  • SQL Server Error Log- No errors

Looked for the SQL Server Agent logs in the directory where SQL Server Error Logs are located but could not find any. The attempts to start the service from services.msc and SQL Server Configuration Manager failed with a generic error message.

Hence I took the SQL Server Agent service’s binary path from the service properties.

BinaryPath

Then typed “…..Binn\SQLAGENT.EXE” -i MSSQLSERVER” the same command in the command prompt.

ErrorMessage_StartServiceCtrlDispatcher

Error message “StartServiceCtrlDispatcher failed (error 6).” doesn’t help! Hence I started sqlserveragent.exe with the “-c” parameter which indicates SQL Server Agent is running in console mode.

“…..Binn\SQLAGENT.EXE” -i MSSQLSERVR -c”

Now the details came out!

CannotFindPath

SQL Server Agent is trying to rename D:\Data3\SQLAGENT.OUT to D:\Data3\SQLAGENT.1
It is failing to start since the file doesn’t exist because the drive isn’t there!

Now time to change the SQL Server Agent Log path. Tried executing the following command but it failed

EXEC msdb.dbo.sp_set_sqlagent_properties @errorlog_file=N’C:\Program Files\Microsoft SQL Server\MSSQL10_50.MSSQLSERVER\MSSQL\Log\SQLAGENT.OUT’

Msg 15281, Level 16, State 1, Procedure sp_set_sqlagent_properties, Line 0
SQL Server blocked access to procedure ‘dbo.sp_set_sqlagent_properties’ of component ‘Agent XPs’ because this component is turned off as part of the security configuration for this server. A system administrator can enable the use of ‘Agent XPs’ by using sp_configure. For more information about enabling ‘Agent XPs’, see “Surface Area Configuration” in SQL Server Books Online.

The only option left was to modify the SQL Server Agent Error Log path in the Registry.
Navigated to the following registry key and modified it to point to the correct path.

RegistryPath

As expected now the SQL Server Agent started successfully.

Add node fails with Attempted to read or write protected memory error

Recently I had worked on an issue where the end user was trying to add a third Node to an existing 2 node cluster. Soon after the setup is intiated, it would fail with the following error message (snippet from the Summary.txt).

Exception type: System.AccessViolationException
    Message: 
        Attempted to read or write protected memory. This is often an indication that other memory is corrupt.
    Data: 
      DisableWatson = true
    Stack: 
        at Microsoft.SqlServer.Chainer.Infrastructure.MsiNativeMethods.MsiOpenPackageEx(String szPackagePath, UInt32 dwOptions, UInt32& hProduct)
        at Microsoft.SqlServer.Configuration.MsiExtension.InstallPackage.SetCommonProperties()
        at Microsoft.SqlServer.Configuration.MsiExtension.InstallPackage.RunMsiCore(String commandLine)
        at Microsoft.SqlServer.Configuration.MsiExtension.InstallPackage.RunMsiWithRetry(String commandline)
        at Microsoft.SqlServer.Configuration.MsiExtension.InstallPackage.RunMsi(IEnumerable`1 commandLineProps)
        at Microsoft.SqlServer.Configuration.SetupExtension.MSIInstallerEngine.InstallPackage(PackageId pkg, InstallAction pkgAction)
        at Microsoft.SqlServer.Configuration.MsiExtension.PackageInstallAction.Execute(String actionId, TextWriter errorStream)
        at Microsoft.SqlServer.Setup.Chainer.Workflow.ActionInvocation.ExecuteActionHelper(TextWriter statusStream, ISequencedAction actionToRun)

“Attempted to read or write protected memory. This is often an indication that other memory is corrupt.” Scary little error message! Since this is a setup related issue, the best place to start troubleshooting it is from the Setup Logs.  This article has more details on how to read SQL Server Setup logs.

Detail.txt pointed in the right direction as seen below.

Opening existing patch 'c:WindowsInstaller97363c.msp'.
Couldn't find local patch 'c:WindowsInstaller97363c.msp'. Looking for it at its source.
Resolving Patch source.
SOURCEMGMT: Looking for sourcelist for product {D7C6A337-F6BB-46CB-AE32-204DD6A8825D}
SOURCEMGMT: Trying source c:7cb5fee2d4775f9d53c7f95659x64setup.
Note: 1: 2203 2: c:7cb5fee2d4775f9d53c7f95659x64setupsql_ssms.msp 3: -2147287037 
SOURCEMGMT: Source is invalid due to missing/inaccessible package.
Unable to create a temp copy of patch 'sql_ssms.msp'.
Searching provided command line patches for patch code {D7C6A337-F6BB-46CB-AE32-204DD6A8825D}
Could not find source for missing patch {D7C6A337-F6BB-46CB-AE32-204DD6A8825D} -- orphaning this patch
SequencePatches starts. Product code: {72AB7E6F-BC24-481E-8C45-1AB

Now it was very clear that the issue is the classic missing MSI/MSP file issue. It was just matter of copying the right files to C:WindowsInstaller as explained here and here.

Once the missing files were replaced, the setup completed without any further errors.