TLOG Backup hangs with "MSQL_XP" Wait Type

stedun · November 2, 2009 10:42AM

SQL Backup 6.2.0.134 will occasionally have a transaction log backup hang indefinitely. The sqbstatus proc returns nothing. There is no error in the logs I can find. SQL Server's activity monitor shows a status of 'Execute' with a very high wait time and a wait type of MSQL_XP. When this happens, I can restart the Redgate backup service and the SQL Agent service to get the job to terminate without restarting SQL Server's engine. Any thoughts on troubleshooting?

Many thanks.

stedun · November 2, 2009 11:24AM

I tried running exec master..sqbutility 9997; but it did not produce an SQBCoreService_bugreport.txt file as I saw recommended in another post.

stedun · November 4, 2009 9:07AM

I've enabled the trace flag to capture additional information to the sql errorlog using:

DBCC TRACEON (3004, 3605, -1)

I'll try to update my post when I capture the next incident.

HJoyce · November 4, 2009 9:45AM

Thanks, would appreciate to know the outcome.

stedun · November 6, 2009 10:44AM

Date,Source,Severity,Message
11/06/2009 08:01:48,spid117,Unknown,BackupLog: Finished
11/06/2009 08:01:48,spid117,Unknown,Writing backup history records
11/06/2009 08:01:48,Backup,Unknown,Log was backed up. Database: NetPerfMon<c/> creation date(time): 2009/08/19(08:40:51)<c/> first LSN: 300915:5846:1<c/> last LSN: 301029:24346:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=VIRTUAL_DEVICE: {'SQLBACKUP_26AB7443-72D9-4C8A-A77D-EF752ABA31D4'}). This is an informational message only. No user action is required.
11/06/2009 08:01:48,spid117,Unknown,BackupLog: Writing history records
11/06/2009 08:01:48,spid117,Unknown,BackupLog: MBC done
11/06/2009 08:01:48,spid117,Unknown,BackupLog: Final configuration done
11/06/2009 08:01:48,spid117,Unknown,BackupLog: Log files done
11/06/2009 08:00:47,spid117,Unknown,BackupLog: Configuration section done
11/06/2009 08:00:47,spid117,Unknown,BackupLog: Work estimate done
11/06/2009 08:00:47,spid117,Unknown,Backup: Streams open
11/06/2009 08:00:46,spid117,Unknown,BackupLog: SafeCheckpoint done
11/06/2009 08:00:45,spid117,Unknown,BackupLog: database NetPerfMon
11/06/2009 08:00:13,spid125,Unknown,FileHandleCache: 0 files opened. CacheSize: 12
11/06/2009 08:00:13,spid125,Unknown,Restore: Configuration section loaded
11/06/2009 08:00:13,spid125,Unknown,Opening backup set
11/06/2009 08:00:12,spid117,Unknown,BackupLog: Finished
11/06/2009 08:00:12,spid117,Unknown,Writing backup history records
11/06/2009 08:00:12,Backup,Unknown,Log was backed up. Database: DBA<c/> creation date(time): 2009/04/15(08:22:11)<c/> first LSN: 614:392:1<c/> last LSN: 614:392:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=VIRTUAL_DEVICE: {'SQLBACKUP_115D2226-1BF7-478F-952D-3F9C65E8AE77'}). This is an informational message only. No user action is required.
11/06/2009 08:00:12,spid117,Unknown,BackupLog: Writing history records
11/06/2009 08:00:12,spid117,Unknown,BackupLog: MBC done
11/06/2009 08:00:12,spid117,Unknown,BackupLog: Final configuration done
11/06/2009 08:00:12,spid117,Unknown,BackupLog: Log files done
11/06/2009 08:00:12,spid117,Unknown,BackupLog: Configuration section done
11/06/2009 08:00:12,spid117,Unknown,BackupLog: Work estimate done
11/06/2009 08:00:12,spid117,Unknown,Backup: Streams open
11/06/2009 08:00:12,spid117,Unknown,BackupLog: SafeCheckpoint done
11/06/2009 08:00:12,spid117,Unknown,BackupLog: database DBA
11/06/2009 08:00:09,spid125,Unknown,FileHandleCache: 0 files opened. CacheSize: 12
11/06/2009 08:00:09,spid125,Unknown,Restore: Configuration section loaded
11/06/2009 08:00:09,spid125,Unknown,Opening backup set
11/06/2009 08:00:07,spid117,Unknown,BackupLog: Finished
11/06/2009 08:00:05,spid117,Unknown,Writing backup history records
11/06/2009 08:00:05,Backup,Unknown,Log was backed up. Database: model<c/> creation date(time): 2003/04/08(09:13:36)<c/> first LSN: 83:120:1<c/> last LSN: 83:120:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=VIRTUAL_DEVICE: {'SQLBACKUP_2A05F4E8-A9B3-492F-9CA7-EA7E32504BCF'}). This is an informational message only. No user action is required.
11/06/2009 08:00:05,spid117,Unknown,BackupLog: Writing history records
11/06/2009 08:00:04,spid117,Unknown,BackupLog: MBC done
11/06/2009 08:00:04,spid117,Unknown,BackupLog: Final configuration done
11/06/2009 08:00:04,spid117,Unknown,BackupLog: Log files done
11/06/2009 08:00:04,spid117,Unknown,BackupLog: Configuration section done
11/06/2009 08:00:04,spid117,Unknown,BackupLog: Work estimate done
11/06/2009 08:00:04,spid117,Unknown,Backup: Streams open
11/06/2009 08:00:03,spid117,Unknown,BackupLog: SafeCheckpoint done
11/06/2009 08:00:03,spid117,Unknown,BackupLog: database model

stedun · November 6, 2009 10:46AM

The previous post is the output from my SQL errorlog where I captured a transaction log backup that starts at 8:00 AM and hangs. It's been running for over 2 hours 45 minutes.

stedun · November 6, 2009 10:54AM

Windows Server 2003 + Service Pack 2

SQL Server 2005 Standard Edition version 9.00.3077.00

This is from the Windows application event log:

Date,Source,Severity,Message,Category,Event,User,Computer
11/06/2009 08:01:48,MSSQL$SQL1,Information,Log was backed up. Database: NetPerfMon<c/> creation date(time): 2009/08/19(08:40:51)<c/> first LSN: 300915:5846:1<c/> last LSN: 301029:24346:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=VIRTUAL_DEVICE: {'SQLBACKUP_26AB7443-72D9-4C8A-A77D-EF752ABA31D4'}). This is an informational message only. No user action is required.,Backup,1073760089,MVCIAD\svc-mssql,LALFIMVD0DBS06
11/06/2009 08:00:12,MSSQL$SQL1,Information,Log was backed up. Database: DBA<c/> creation date(time): 2009/04/15(08:22:11)<c/> first LSN: 614:392:1<c/> last LSN: 614:392:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=VIRTUAL_DEVICE: {'SQLBACKUP_115D2226-1BF7-478F-952D-3F9C65E8AE77'}). This is an informational message only. No user action is required.,Backup,1073760089,MVCIAD\svc-mssql,LALFIMVD0DBS06
11/06/2009 08:00:05,MSSQL$SQL1,Information,Log was backed up. Database: model<c/> creation date(time): 2003/04/08(09:13:36)<c/> first LSN: 83:120:1<c/> last LSN: 83:120:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=VIRTUAL_DEVICE: {'SQLBACKUP_2A05F4E8-A9B3-492F-9CA7-EA7E32504BCF'}). This is an informational message only. No user action is required.,Backup,1073760089,MVCIAD\svc-mssql,LALFIMVD0DBS06

petey · November 18, 2009 2:13AM

The logs indicate that the backup was successful. That would suggest that a post-backup process within SQL Backup has failed.

Could you please look at this article, and try to generate the stack trace of the SQL Backup process for us to troubleshoot further?

Thanks.

mdgraves · November 30, 2010 10:54AM

I was running backup ver. 6.2.0.134, and had no issues with this wait type. Yesterday, I upgraded to ver. 6.4.0.56, and overnight I got the wait "MSQL_XP". Since this happened at 11:00 PM - 12:10 AM (US, Eastern), when I run "sqbutility 9997" I get NULL. Any suggestions on what I can look at next? This happened on one of my ultra-critical 24x7 production clusters.

petey · December 1, 2010 1:51AM

When you run 'sqbutility 9997', the output is NULL, but a stack trace should have been generated. This stack trace is then stored in a file named SQBCoreService_<instance name>_bugreport.txt, and is located in 'C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\' on Windows 2003 and older, and 'C:\ProgramData\Red Gate\SQL Backup\Log\' on Windows Vista and newer.

Also, what is the backup command that you are running?

Thanks.

mdgraves · December 1, 2010 12:16PM

Here are my commands, and the output "bug report txt".

This is only happening during my 11 PM run of TRAN backup. This runs hourly from 2 AM - 11 PM. I am looking for anything that could be running at same time and conflicting...

EXEC master..sqlbackup -SQL "BACKUP LOG LISA_ONE TO DISK = [<AUTO>] WITH NAME = [<AUTO>], DESCRIPTION = [<AUTO>], ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536"
EXEC master..sqlbackup -SQL "BACKUP LOG LISA_ONE_REFERENCE TO DISK = [<AUTO>] WITH NAME = [<AUTO>], DESCRIPTION = [<AUTO>], ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536"
EXEC master..sqlbackup -SQL "BACKUP LOG LISA_ONE_TEST TO DISK = [<AUTO>] WITH NAME = [<AUTO>], DESCRIPTION = [<AUTO>], ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536"
EXEC master..sqlbackup -SQL "BACKUP LOG LISA_SP TO DISK = [<AUTO>] WITH NAME = [<AUTO>], DESCRIPTION = [<AUTO>], ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536"
EXEC master..sqlbackup -SQL "BACKUP LOG LISA_Tagging TO DISK = [<AUTO>] WITH NAME = [<AUTO>], DESCRIPTION = [<AUTO>], ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536"
EXEC master..sqlbackup -SQL "BACKUP LOG LISAINTRDB_ONE TO DISK = [<AUTO>] WITH NAME = [<AUTO>], DESCRIPTION = [<AUTO>], ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536"
EXEC master..sqlbackup -SQL "BACKUP LOG PIPELINE_ONE TO DISK = [<AUTO>] WITH NAME = [<AUTO>], DESCRIPTION = [<AUTO>], ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536"
EXEC master..sqlbackup -SQL "BACKUP LOG SP_LISA_CONVERT TO DISK = [<AUTO>] WITH NAME = [<AUTO>], DESCRIPTION = [<AUTO>], ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536"

date/time : 2010-11-30, 10:38:41, 830ms
computer name : BPGBYQPC25A
user name : svc_clstr_qpc25 <admin>
registered owner : Georgia-Pacific / Georgia-Pacific
operating system : Windows 2003 R2 x64 Service Pack 2 build 3790
system language : English
system up time : 8 days 18 hours
program up time : 1 day
processors : 16x Quad-Core AMD Opteron(tm) Processor 8358 SE
physical memory : 13989/32766 MB (free/total)
free disk space : (C:) 53.49 GB
display mode : 800x600, 16 bit
process id : $1668
allocated memory : 18.66 MB
command line : "C:\Program Files (x86)\Red Gate\SQL Backup 6\WPLISA\SQBCoreService.exe" -i WPLISA
executable : SQBCoreService.exe
exec. date/time : 2010-03-08 11:46
version : 6.4.0.56
compiled with : Delphi 7
madExcept version : 3.0i beta 2
callstack crc : $835fda28, $77a9acca, $08cd21d0
exception number : 1
exception class : EConversionError
exception message : Dump callstack for Red Gate support purposes. Please ignore the EConversionError code.

thread $1fcc (TSQBUtilityThread):
0068c6e9 +011 SQBCoreService.exe ConvUtils RaiseConversionError
00695325 +005 SQBCoreService.exe uSvcUtility 2007 TSQBUtilityThread.TriggerExceptionToCreateCallStack
0068cee1 +3fd SQBCoreService.exe uSvcUtility 190 TSQBUtilityThread.Execute
0044fc0b +02b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +034 SQBCoreService.exe Classes ThreadProc
00404bc8 +028 SQBCoreService.exe System ThreadWrapper
0044faed +00d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +037 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1ae0 (TSQBListenerThread) at:
0068c980 +038 SQBCoreService.exe uSvcUtility 86 TSQBUtilityThread.Create

main thread ($83c):
7d4d8c98 +082 kernel32.dll WaitForSingleObjectEx
7d4d8c08 +00d kernel32.dll WaitForSingleObject
00433f11 +041 SQBCoreService.exe madExcept PauseMeEventually
00450547 +003 SQBCoreService.exe madExcept PeekMessageCallbackA
004af66b +013 SQBCoreService.exe Forms TApplication.ProcessMessage
004af6fa +00a SQBCoreService.exe Forms TApplication.HandleMessage
004b3047 +177 SQBCoreService.exe SvcMgr TServiceApplication.Run
006a233a +0de SQBCoreService.exe SQBCoreService 81 initialization

thread $2398 (TServiceStartThread):
7d4d08a6 +61 kernel32.dll ReadFile
7d247662 +8e ADVAPI32.dll StartServiceCtrlDispatcherA
004b2e83 +07 SQBCoreService.exe SvcMgr TServiceStartThread.Execute
0044fc0b +2b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +34 SQBCoreService.exe Classes ThreadProc
00404bc8 +28 SQBCoreService.exe System ThreadWrapper
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by main thread ($83c) at:
004b2e1b +4f SQBCoreService.exe SvcMgr TServiceStartThread.Create

thread $448:
7d4d8c98 +82 kernel32.dll WaitForSingleObjectEx
7d4d8c08 +0d kernel32.dll WaitForSingleObject
0047627c +7c SQBCoreService.exe Classes TThread.WaitFor
004b2355 +75 SQBCoreService.exe SvcMgr TService.DoStart
004b2284 +90 SQBCoreService.exe SvcMgr TService.Main
004b2767 +83 SQBCoreService.exe SvcMgr TServiceApplication.DispatchServiceMain
004b2586 +0e SQBCoreService.exe SvcMgr ServiceMain
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $2398 (TServiceStartThread) at:
7d1f6085 +00 ADVAPI32.dll

thread $1978 (TServiceThread):
7d947bba +45 user32.dll GetMessageA
004b1ae3 +47 SQBCoreService.exe SvcMgr TServiceThread.ProcessRequests
0069cc21 +95 SQBCoreService.exe uSvcCore 697 TSQLBackupAgent.ServiceExecute
004b1953 +cf SQBCoreService.exe SvcMgr TServiceThread.Execute
0044fc0b +2b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +34 SQBCoreService.exe Classes ThreadProc
00404bc8 +28 SQBCoreService.exe System ThreadWrapper
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $448 at:
004b1863 +1b SQBCoreService.exe SvcMgr TServiceThread.Create

thread $2184:
0044faed +00d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +037 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1978 (TServiceThread) at:
71c50fe5 +261 NetAPI32.dll Netbios

thread $1ae0 (TSQBListenerThread):
7d4d8c98 +82 kernel32.dll WaitForSingleObjectEx
7d4d8c08 +0d kernel32.dll WaitForSingleObject
0069cfd1 +35 SQBCoreService.exe uSvcCore 802 TSQBListenerThread.Execute
0044fc0b +2b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +34 SQBCoreService.exe Classes ThreadProc
00404bc8 +28 SQBCoreService.exe System ThreadWrapper
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1978 (TServiceThread) at:
0069ccbc +18 SQBCoreService.exe uSvcCore 707 TSQBListenerThread.Create

thread $20e4 (TCopyManager):
7d4d0ec3 +047 kernel32.dll SleepEx
7d4d14ea +00a kernel32.dll Sleep
00655432 +2ea SQBCoreService.exe u_CopyManager 339 TCopyManager.Execute
0044fc0b +02b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +034 SQBCoreService.exe Classes ThreadProc
00404bc8 +028 SQBCoreService.exe System ThreadWrapper
0044faed +00d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +037 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1978 (TServiceThread) at:
00653e35 +031 SQBCoreService.exe u_CopyManager 56 TCopyManager.Create

thread $460 (TCopyThread):
7d4d8c98 +82 kernel32.dll WaitForSingleObjectEx
7d4d8c08 +0d kernel32.dll WaitForSingleObject
00581114 +2c SQBCoreService.exe u_CopyThread 115 TCopyThread.Execute
0044fc0b +2b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +34 SQBCoreService.exe Classes ThreadProc
00404bc8 +28 SQBCoreService.exe System ThreadWrapper
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1978 (TServiceThread) at:
0058102d +19 SQBCoreService.exe u_CopyThread 81 TCopyThread.Create

thread $1644 (TCopyThread):
7d4d8c98 +82 kernel32.dll WaitForSingleObjectEx
7d4d8c08 +0d kernel32.dll WaitForSingleObject
00581114 +2c SQBCoreService.exe u_CopyThread 115 TCopyThread.Execute
0044fc0b +2b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +34 SQBCoreService.exe Classes ThreadProc
00404bc8 +28 SQBCoreService.exe System ThreadWrapper
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1978 (TServiceThread) at:
0058102d +19 SQBCoreService.exe u_CopyThread 81 TCopyThread.Create

thread $6c (TCopyThread):
7d4d8c98 +82 kernel32.dll WaitForSingleObjectEx
7d4d8c08 +0d kernel32.dll WaitForSingleObject
00581114 +2c SQBCoreService.exe u_CopyThread 115 TCopyThread.Execute
0044fc0b +2b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +34 SQBCoreService.exe Classes ThreadProc
00404bc8 +28 SQBCoreService.exe System ThreadWrapper
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1978 (TServiceThread) at:
0058102d +19 SQBCoreService.exe u_CopyThread 81 TCopyThread.Create

thread $1140 (TCopyThread):
7d4d8c98 +82 kernel32.dll WaitForSingleObjectEx
7d4d8c08 +0d kernel32.dll WaitForSingleObject
00581114 +2c SQBCoreService.exe u_CopyThread 115 TCopyThread.Execute
0044fc0b +2b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +34 SQBCoreService.exe Classes ThreadProc
00404bc8 +28 SQBCoreService.exe System ThreadWrapper
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1978 (TServiceThread) at:
0058102d +19 SQBCoreService.exe u_CopyThread 81 TCopyThread.Create

thread $1bd4 (TCopyThread):
7d4d8c98 +82 kernel32.dll WaitForSingleObjectEx
7d4d8c08 +0d kernel32.dll WaitForSingleObject
00581114 +2c SQBCoreService.exe u_CopyThread 115 TCopyThread.Execute
0044fc0b +2b SQBCoreService.exe madExcept HookedTThreadExecute
00475d5c +34 SQBCoreService.exe Classes ThreadProc
00404bc8 +28 SQBCoreService.exe System ThreadWrapper
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $1978 (TServiceThread) at:
0058102d +19 SQBCoreService.exe u_CopyThread 81 TCopyThread.Create

thread $2018:
7d5066ee +23 kernel32.dll GetQueuedCompletionStatus
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $894 at:
3381d85d +00 sqlncli.dll

thread $110c:
7d947bba +45 user32.dll GetMessageA
0044faed +0d SQBCoreService.exe madExcept CallThreadProcSafe
0044fb57 +37 SQBCoreService.exe madExcept ThreadExceptFrame
>> created by thread $894 at:
2503daa2 +00 sqlcese30.dll

modules:
00400000 SQBCoreService.exe 6.4.0.56 C:\Program Files (x86)\Red Gate\SQL Backup 6\WPLISA
00820000 oleaut32.dll 5.2.3790.4202 C:\WINDOWS\syswow64
03300000 sqlceoledb30.dll 3.0.5300.0 C:\Program Files (x86)\Common Files\Red Gate\SQL Backup\SSCE3.1
03d30000 SQLCEER30EN.DLL 3.0.5300.0 C:\Program Files (x86)\Common Files\Red Gate\SQL Backup\SSCE3.1
03d60000 sqlceqp30.dll 3.0.5300.0 C:\Program Files (x86)\Common Files\Red Gate\SQL Backup\SSCE3.1
05a70000 NTMARTA.DLL 5.2.3790.3959 C:\WINDOWS\system32
10000000 zlib1.dll 1.2.3.0 C:\Program Files (x86)\Red Gate\SQL Backup 6\WPLISA
25000000 sqlcese30.dll 3.0.5300.0 C:\Program Files (x86)\Common Files\Red Gate\SQL Backup\SSCE3.1
337a0000 sqlncli.dll 2005.90.4035.0 C:\WINDOWS\SysWOW64
34510000 sqlvdi.dll 2000.85.2312.0 C:\Program Files (x86)\Microsoft SQL Server\80\COM
35000000 SQLNCLIR.RLL 2005.90.1399.0 C:\WINDOWS\SysWOW64
4c850000 oledb32.dll 2.82.3959.0 C:\Program Files (x86)\Common Files\System\Ole DB
4dbb0000 OLEDB32R.DLL 2.82.1830.0 C:\Program Files (x86)\Common Files\System\Ole DB
5f270000 hnetcfg.dll 5.2.3790.3959 C:\WINDOWS\system32
68000000 rsaenh.dll 5.2.3790.3959 C:\WINDOWS\system32
68100000 dssenh.dll 5.2.3790.3959 C:\WINDOWS\system32
71ae0000 wshtcpip.dll 5.2.3790.3959 C:\WINDOWS\System32
71bb0000 wsock32.dll 5.2.3790.0 C:\WINDOWS\system32
71bd0000 mpr.dll 5.2.3790.3959 C:\WINDOWS\syswow64
71bf0000 WS2HELP.dll 5.2.3790.1830 C:\WINDOWS\system32
71c00000 WS2_32.dll 5.2.3790.3959 C:\WINDOWS\system32
71c40000 NetAPI32.dll 5.2.3790.4392 C:\WINDOWS\syswow64
71ca0000 Kerberos.DLL 5.2.3790.3959 C:\WINDOWS\SysWOW64
71e00000 msapsspc.dll 6.0.0.7755 C:\WINDOWS\system32
71e20000 msnsspc.dll 6.1.1825.0 C:\WINDOWS\system32
71f60000 security.dll 5.2.3790.0 C:\WINDOWS\system32
74a50000 MSDART.DLL 2.82.3959.0 C:\WINDOWS\system32
76190000 MSASN1.dll 5.2.3790.4584 C:\WINDOWS\syswow64
761b0000 CRYPT32.dll 5.131.3790.3959 C:\WINDOWS\syswow64
762b0000 comdlg32.dll 6.0.3790.3959 C:\WINDOWS\syswow64
766e0000 cryptdll.dll 5.2.3790.3959 C:\WINDOWS\system32
766f0000 ntdsapi.dll 5.2.3790.3959 C:\WINDOWS\system32
76750000 schannel.dll 5.2.3790.4724 C:\WINDOWS\SysWOW64
76920000 USERENV.dll 5.2.3790.3959 C:\WINDOWS\system32
76b70000 PSAPI.DLL 5.2.3790.3959 C:\WINDOWS\system32
76c90000 msv1_0.DLL 5.2.3790.4587 C:\WINDOWS\SysWOW64
76cf0000 iphlpapi.dll 5.2.3790.3959 C:\WINDOWS\system32
76ed0000 DNSAPI.dll 5.2.3790.4318 C:\WINDOWS\system32
76f10000 WLDAP32.dll 5.2.3790.3959 C:\WINDOWS\syswow64
76f70000 winrnr.dll 5.2.3790.3959 C:\WINDOWS\System32
76f80000 rasadhlp.dll 5.2.3790.3959 C:\WINDOWS\system32
77010000 COMRes.dll 2001.12.4720.3959 C:\WINDOWS\system32
770e0000 SETUPAPI.dll 5.2.3790.3959 C:\WINDOWS\system32
77530000 comctl32.dll 5.82.3790.4770 C:\WINDOWS\WinSxS\x86_Microsoft.Windows.Common-Controls_6595b64144ccf1df_5.82.3790.4770_x-ww_A689AB02
77670000 ole32.dll 5.2.3790.4750 C:\WINDOWS\syswow64
777b0000 CLBCatQ.DLL 2001.12.4720.3959 C:\WINDOWS\system32
77b90000 version.dll 5.2.3790.1830 C:\WINDOWS\syswow64
77ba0000 msvcrt.dll 7.0.3790.3959 C:\WINDOWS\syswow64
78080000 MSVCRT40.dll 5.2.3790.0 C:\WINDOWS\system32
78130000 MSVCR80.dll 8.0.50727.4053 C:\WINDOWS\WinSxS\x86_Microsoft.VC80.CRT_1fc8b3b9a1e18e3b_8.0.50727.4053_x-ww_E6967989
7c8d0000 shell32.dll 6.0.3790.4751 C:\WINDOWS\syswow64
7d180000 SHLWAPI.dll 6.0.3790.4603 C:\WINDOWS\syswow64
7d1e0000 ADVAPI32.dll 5.2.3790.4455 C:\WINDOWS\syswow64
7d4c0000 kernel32.dll 5.2.3790.4480 C:\WINDOWS\syswow64
7d600000 ntdll.dll 5.2.3790.4455 C:\WINDOWS\system32
7d800000 GDI32.dll 5.2.3790.4396 C:\WINDOWS\syswow64
7d8d0000 Secur32.dll 5.2.3790.4455 C:\WINDOWS\syswow64
7d930000 user32.dll 5.2.3790.4033 C:\WINDOWS\syswow64
7da20000 RPCRT4.dll 5.2.3790.4759 C:\WINDOWS\syswow64
7db30000 mswsock.dll 5.2.3790.4318 C:\WINDOWS\System32
7dbd0000 comctl32.dll 6.0.3790.4770 C:\WINDOWS\WinSxS\WOW64_Microsoft.Windows.Common-Controls_6595b64144ccf1df_6.0.3790.4770_x-ww_8D2E3180
7e020000 SAMLIB.dll 5.2.3790.3959 C:\WINDOWS\system32

processes:
0000 Idle
0004 System normal
017c smss.exe normal
01ac csrss.exe
01c8 winlogon.exe high
01f8 services.exe normal
0204 lsass.exe normal
02dc svchost.exe normal
0314 svchost.exe
0354 svchost.exe
0380 svchost.exe
0390 svchost.exe normal
0420 spoolsv.exe normal
0440 adcscm.nt_intel.exe normal C:\WINDOWS\ADCAgent
0464 BESClient.exe normal C:\Program Files (x86)\BigFix Enterprise\BES Client
04a8 cissesrv.exe normal
04b8 cpqrcmc.exe normal
0528 vcagent.exe normal C:\hp\hpsmh\data\cgi-bin\vcagent
0554 dlmmgr.exe normal C:\Program Files (x86)\HITACHI\DynamicLinkManager\bin
057c ECCService_MasterAgent.exe normal C:\ecc\exec
05ac PowMigSrvc.exe normal C:\Program Files (x86)\EMC\PowerPath
05b4 mstragent.exe normal C:\ecc\exec
05c0 EmcPowSrv.exe normal C:\Program Files (x86)\EMC\PowerCommon
05e8 svchost.exe normal
05f0 mstragent.exe normal C:\ecc\exec
060c cvd.exe normal
0624 hbsa_service.exe normal C:\Program Files (x86)\HDVM\HBaseAgent\agent\bin
06e8 hntr2srv.exe normal C:\Program Files (x86)\Hitachi\HNTRLib2\bin
0700 hntr2mon.exe normal C:\Program Files (x86)\Hitachi\HNTRLib2\bin
070c mdm.exe normal C:\Program Files (x86)\Common Files\Microsoft Shared\VS7Debug
072c Naviagent.exe normal C:\Program Files (x86)\EMC\Navisphere Agent
0754 NetIQccm.exe
0770 NetIQmc.exe
0798 NTRtScan.exe normal
084c portmap.exe normal C:\Program Files (x86)\QLogic Corporation\SANsurfer
0860 qlremote.exe normal C:\PROGRA~2\QLOGIC~1\SANSUR~1
0888 RemoteExec.exe normal C:\Program Files (x86)\CommVault Systems\QSM\System
08b8 svchost.exe
08d4 SMagent.exe normal C:\PROGRA~2\STORAG~1\agent
090c SMmonitor.exe normal C:\Program Files (x86)\StorageManager\client\monitor
091c snmp.exe normal
094c sqlbrowser.exe
0974 sqlwriter.exe normal
099c storapid.exe normal C:\Program Files (x86)\EMC\SYMCLI\daemons
09dc storevntd.exe normal C:\Program Files (x86)\EMC\SYMCLI\daemons
09f4 storgnsd.exe normal C:\Program Files (x86)\EMC\SYMCLI\daemons
0a54 storsrmd.exe normal C:\Program Files (x86)\EMC\SYMCLI\daemons
0aa8 storsrvd.exe normal C:\Program Files (x86)\EMC\SYMCLI\daemons
0ad0 SIUService.exe normal C:\WINDOWS\SysWOW64
0b08 sysdown.exe normal
0b18 smhstart.exe normal C:\hp\hpsmh\bin
0b40 TmListen.exe normal
0b50 hpsmhd.exe normal C:\hp\hpsmh\bin
0bc4 rotatelogs.exe normal C:\hp\hpsmh\bin
0bcc rotatelogs.exe normal C:\hp\hpsmh\bin
0bf4 cpqnimgt.exe normal
0684 cqmgserv.exe normal
06e0 cqmgstor.exe normal
0794 EvMgrC.exe normal
00c4 hpsmhd.exe normal C:\hp\hpsmh\bin
0c38 ClusSvc.exe
0c68 rotatelogs.exe normal C:\hp\hpsmh\bin
0c74 rotatelogs.exe normal C:\hp\hpsmh\bin
1054 cqmghost.exe normal
10c8 wmiprvse.exe
1154 ResrcMon.exe high
1208 CNTAoSMgr.exe normal C:\Program Files (x86)\Trend Micro\OfficeScan Client
1214 AEB0CE.EXE normal
123c ResrcMon.exe high
125c ResrcMon.exe high
128c ResrcMon.exe high
12ac ResrcMon.exe high
12d0 ResrcMon.exe high
12f0 ResrcMon.exe high
1340 svchost.exe normal
1330 wmiprvse.exe
19c0 msdtc.exe
1708 msftesql.exe
11b0 RemoteExec.exe normal E:\Program Files (x86)\CommVault Systems\QSM\System
10b8 GxWinClusterPlugin.exe normal
0334 sqlservr.exe
1d0c SQLAGENT90.EXE
1e98 logon.scr
1ff0 HealthService.exe normal
1138 MonitoringHost.exe
1ee4 MonitoringHost.exe
1e0c MonitoringHost.exe
239c dfrgifc.exe
18b8 dfrgntfs.exe
164c wmiprvse.exe
1fdc _iu14D2N.tmp normal C:\DOCUME~1\mdgraves\LOCALS~1\Temp
0cbc _iu14D2O.tmp normal C:\DOCUME~1\mdgraves\LOCALS~1\Temp
1838 svchost.exe normal
1668 SQBCoreService.exe normal C:\Program Files (x86)\Red Gate\SQL Backup 6\WPLISA
1714 wmiprvse.exe
1088 wmiprvse.exe

hardware:
+ Computer
- ACPI Multiprocessor x64-based PC
+ Disk drives
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 Multi-Path Disk Device (driver 5.1.0.460)
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- DGC RAID 5 SCSI Disk Device
- HITACHI OPEN-V Multi-Path Disk Device
- HITACHI OPEN-V Multi-Path Disk Device
- HITACHI OPEN-V SCSI Disk Device
- HITACHI OPEN-V SCSI Disk Device
- HITACHI OPEN-V SCSI Disk Device
- HITACHI OPEN-V SCSI Disk Device
- HP LOGICAL VOLUME SCSI Disk Device
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
- PowerDevice by PowerPath
+ Display adapters
- ATI ES1000 (driver 8.240.50.2000)
+ DVD/CD-ROM drives
- TEAC DW-224E-V
+ Human Interface Devices
- USB Human Interface Device
- USB Human Interface Device
+ IDE ATA/ATAPI controllers
- Primary IDE Channel
- Secondary IDE Channel
- Standard Dual Channel PCI IDE Controller
+ Keyboards
- HID Keyboard Device
- Standard 101/102-Key or Microsoft Natural PS/2 Keyboard
+ Mice and other pointing devices
- HID-compliant mouse
- PS/2 Compatible Mouse
+ Monitors
- Default Monitor
- Plug and Play Monitor
+ Multifunction adapters
- HP iLO Management Channel Interface Driver (driver 1.13.0.0)
+ Network adapters
- HP NC371i Multifunction Gigabit Server Adapter (driver 4.5.4.0)
- HP NC371i Multifunction Gigabit Server Adapter #2 (driver 4.5.4.0)
+ Ports (COM & LPT)
- Communications Port (COM1)
- Communications Port (COM2)
+ Processors
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
- Quad-Core AMD Opteron(tm) Processor 8358 SE
+ SCSI and RAID controllers
- EMS Device Bus (driver 5.1.0.460)
- Multi-Path Support
- QLogic Fibre Channel Adapter (driver 9.1.7.16)
- QLogic Fibre Channel Adapter (driver 9.1.7.16)
- RDAC Multi-Path Pseudo-Bus (driver 9.1.32.36)
- Smart Array P400 Controller (driver 6.13.0.64)
+ Sound, video and game controllers
- Audio Codecs
- Legacy Audio Drivers
- Legacy Video Capture Devices
- Media Control Devices
- Video Codecs
+ System devices
- ACPI Fixed Feature Button
- Advanced programmable interrupt controller
- Advanced programmable interrupt controller
- Advanced programmable interrupt controller
- Advanced programmable interrupt controller
- AMD-8132 HyperTransport IOAPIC Controller (driver 2.0.1.0)
- AMD-8132 HyperTransport IOAPIC Controller (driver 2.0.1.0)
- Direct memory access controller
- EMC PowerPath Consistency Group Extension for Symmetrix (driver 5.1.0.460)
- EMC PowerPath Data Migration Manager (driver 5.1.0.460)
- EMC PowerPath Generic Device Specific Module (driver 5.1.0.460)
- EMC PowerPath Generic Purpose Extension (driver 5.1.0.460)
- EMC PowerPath SymmApi Extension for Symmetrix (driver 5.1.0.460)
- Extended IO Bus
- HDLM Alert Driver (driver 5.80.0.21)
- HDLM Multi-Path Device Specific Module (driver 5.80.0.21)
- High precision event timer
- HP NC371i Virtual Bus Device (driver 4.4.24.0)
- HP NC371i Virtual Bus Device (driver 4.4.24.0)
- HP NULL IPMI Controller (driver 1.0.0.0)
- HP ProLiant iLO 2 Legacy Support Function (driver 1.8.0.0)
- HP ProLiant iLO 2 Management Controller Driver (driver 1.8.0.0)
- HP Virtual LUN
- Logical Disk Manager
- Microcode Update Device
- Microsoft ACPI-Compliant System
- Microsoft System Management BIOS Driver
- Motherboard resources
- NVIDIA nForce4 HyperTransport Bridge
- NVIDIA nForce4 HyperTransport Bridge
- NVIDIA nForce4 Low Pin Count Controller
- PCI bus
- PCI bus
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard host CPU bridge
- PCI standard ISA bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- PCI standard PCI-to-PCI bridge
- Plug and Play Software Device Enumerator
- RDAC Multi-Path Virtual Disk Manager (driver 9.1.32.36)
- System speaker
- System timer
- Terminal Server Device Redirector
- Terminal Server Keyboard Driver
- Terminal Server Mouse Driver
- Volume Manager
+ Universal Serial Bus controllers
- Generic USB Hub
- Generic USB Hub
- Standard Enhanced PCI to USB Host Controller
- Standard OpenHCD USB Host Controller
- Standard Universal PCI to USB Host Controller
- USB Composite Device
- USB Root Hub
- USB Root Hub
- USB Root Hub

cpu registers:
eax = 010972f0
ebx = 00695334
ecx = 00000000
edx = 0068c6ee
esi = 010972f0
edi = 00000000
eip = 0068c6ee
esp = 00eefe80
ebp = 00eefefc

stack dump:
00eefe80 ee c6 68 00 de fa ed 0e - 01 00 00 00 07 00 00 00 ..h.............
00eefe90 94 fe ee 00 ee c6 68 00 - f0 72 09 01 34 53 69 00 ......h..r..4Si.
00eefea0 f0 72 09 01 00 00 00 00 - fc fe ee 00 b0 fe ee 00 .r..............
00eefeb0 e4 ca 68 00 2a 53 69 00 - e6 ce 68 00 c8 fe ee 00 ..h.*Si...h.....
00eefec0 d4 44 40 00 fc fe ee 00 - 04 ff ee 00 d4 44 40 00 .D@..........D@.
00eefed0 fc fe ee 00 00 00 00 00 - f0 72 09 01 e4 ca 68 00 .........r....h.
00eefee0 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 ................
00eefef0 00 00 00 00 00 00 00 00 - 40 10 f8 00 2c ff ee 00 ........@...,...
00eeff00 0d fc 44 00 10 ff ee 00 - f4 42 40 00 2c ff ee 00 ..D......B@.,...
00eeff10 34 ff ee 00 76 fc 44 00 - 2c ff ee 00 00 00 00 00 4...v.D.,.......
00eeff20 f0 72 09 01 7c ff ee 00 - 40 10 f8 00 5c ff ee 00 .r..|...@...\...
00eeff30 5f 5d 47 00 40 ff ee 00 - 69 5d 47 00 5c ff ee 00 _]G.@...i]G.\...
00eeff40 64 ff ee 00 be 5d 47 00 - 5c ff ee 00 00 00 00 00 d....]G.\.......
00eeff50 f0 72 09 01 7c ff ee 00 - 40 10 f8 00 70 ff ee 00 .r..|...@...p...
00eeff60 ca 4b 40 00 90 ff ee 00 - 04 47 40 00 70 ff ee 00 .K@......G@.p...
00eeff70 80 ff ee 00 ef fa 44 00 - f0 72 09 01 a0 4b 40 00 ......D..r...K@.
00eeff80 b8 ff ee 00 5c fb 44 00 - a0 4b 40 00 f0 72 09 01 ....\.D..K@..r..
00eeff90 9c ff ee 00 69 fb 44 00 - b8 ff ee 00 dc ff ee 00 ....i.D.........
00eeffa0 cd fb 44 00 b8 ff ee 00 - 00 00 00 00 00 00 00 00 ..D.............
00eeffb0 40 6f 09 01 00 00 19 83 - ec ff ee 00 37 fe 4d 7d @o..........7.M}

disassembling:
[...]
0068c6d9 ebx, eax
0068c6db ecx, ebx
0068c6dd dl, 1
0068c6df eax, [$68c4cc]
0068c6e4 -$2313b9 ($45b330) ; SysUtils.Exception.Create
0068c6e9 > -$28814e ($4045a0) ; System.@RaiseExcept
0068c6ee ebx
0068c6ef

petey · December 2, 2010 8:45PM

The stack trace seems to have been generated on 2010-11-30, 10:38. You mentioned that the backup usually hangs at 11 pm. Was this after one of the times when the backup hanged?

Is so, the stack trace doesn't show any backups running or waiting to run. Could you please check if a log was generated for the backup process that started at 11 pm? The default folder where the logs are stored is C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\<instance name> on Windows 2003 and older, and C:\ProgramData\Red Gate\SQL Backup\Log\<instance name> on Windows Vista and newer.

Thanks.

mdgraves · December 6, 2010 3:35PM

Below I have provided the 8 database backup log files from 11/29/10, 11 PM.

Yes, the prior posted output "bug report txt" file was generated on 11/30 at 10:38 AM, the morning after I discovered the issue with 11 PM TRAN backups.

Thanks for your help......

THE ISSUE CONTINUES DAILY.

Can I send you a chart image via email (I don't have it on external HTTP site to use link)?

#####################################################################################

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOG LISA_ONE TO DISK = '<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536 "

PROCESSES COMPLETED SUCCESSFULLY

11/29/2010 11:00:00 PM: Backing up LISA_ONE (transaction log) on WPLISA instance to:
11/29/2010 11:00:00 PM: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_LISA_ONE_20101129_230000.sqb

11/29/2010 11:00:01 PM: Deleting old backup file: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_LISA_ONE_20101128_230000.sqb
11/29/2010 11:00:01 PM: BACKUP LOG [LISA_ONE] TO VIRTUAL_DEVICE = 'SQLBACKUP_C8345F8C-09F7-468F-894A-3A3CEDAE5407' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 65536, NAME = N'Database (LISA_ONE), 11/29/2010 11:00:00 PM', DESCRIPTION = N'Backup on 11/29/2010 11:00:00 PM Server: BPGBYQPL01\WPLISA Database: LISA_ONE', FORMAT

11/29/2010 11:00:02 PM: Backup data size : 8.438 MB
11/29/2010 11:00:02 PM: Compressed data size: 2.298 MB
11/29/2010 11:00:02 PM: Compression rate : 72.76%

11/29/2010 11:00:02 PM: Processed 919 pages for database 'LISA_ONE', file 'LISA_SP_CONV_Log' on file 1.
11/29/2010 11:00:02 PM: BACKUP LOG successfully processed 919 pages in 0.185 seconds (40.666 MB/sec).
11/29/2010 11:00:02 PM: SQL Backup process ended.

11/29/2010 11:00:02 PM: Deleted msdb entries older than 11/19/2010 11:00:02 PM
11/29/2010 11:00:02 PM: Deleted local history entries older than 11/19/2010 11:00:02 PM

#####################################################################################

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOG LISA_ONE_REFERENCE TO DISK = '<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536 "

PROCESSES COMPLETED SUCCESSFULLY

11/29/2010 11:00:02 PM: Backing up LISA_ONE_REFERENCE (transaction log) on WPLISA instance to:
11/29/2010 11:00:02 PM: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_LISA_ONE_REFERENCE_20101129_230002.sqb

11/29/2010 11:00:02 PM: BACKUP LOG [LISA_ONE_REFERENCE] TO VIRTUAL_DEVICE = 'SQLBACKUP_BB27525B-2460-44F6-BD46-4D3F61151522' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 65536, NAME = N'Database (LISA_ONE_REFERENCE), 11/29/2010 11:00:02 PM', DESCRIPTION = N'Backup on 11/29/2010 11:00:02 PM Server: BPGBYQPL01\WPLISA Database: LISA_ONE_REFERENCE', FORMAT

11/29/2010 11:00:02 PM: Backup data size : 512.000 KB
11/29/2010 11:00:02 PM: Compressed data size: 4.000 KB
11/29/2010 11:00:02 PM: Compression rate : 99.22%

11/29/2010 11:00:02 PM: Processed 0 pages for database 'LISA_ONE_REFERENCE', file 'LISA_IWP_REFERENCE_Log' on file 1.
11/29/2010 11:00:02 PM: BACKUP LOG successfully processed 0 pages in 0.004 seconds (0.000 MB/sec).
11/29/2010 11:00:03 PM: SQL Backup process ended.

11/29/2010 11:00:03 PM: Deleted msdb entries older than 11/19/2010 11:00:03 PM
11/29/2010 11:00:03 PM: Deleted local history entries older than 11/19/2010 11:00:03 PM

#####################################################################################

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOG LISA_ONE_TEST TO DISK = '<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536 "

PROCESSES COMPLETED SUCCESSFULLY

11/29/2010 11:00:03 PM: Backing up LISA_ONE_TEST (transaction log) on WPLISA instance to:
11/29/2010 11:00:03 PM: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_LISA_ONE_TEST_20101129_230003.sqb

11/29/2010 11:00:03 PM: BACKUP LOG [LISA_ONE_TEST] TO VIRTUAL_DEVICE = 'SQLBACKUP_38EE06CC-FC69-4C77-806B-0AD8E43BE03A' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 65536, NAME = N'Database (LISA_ONE_TEST), 11/29/2010 11:00:03 PM', DESCRIPTION = N'Backup on 11/29/2010 11:00:03 PM Server: BPGBYQPL01\WPLISA Database: LISA_ONE_TEST', FORMAT

11/29/2010 11:00:03 PM: Backup data size : 512.000 KB
11/29/2010 11:00:03 PM: Compressed data size: 4.500 KB
11/29/2010 11:00:03 PM: Compression rate : 99.12%

11/29/2010 11:00:03 PM: Processed 0 pages for database 'LISA_ONE_TEST', file 'LISA_SP_CONV_Log' on file 1.
11/29/2010 11:00:03 PM: BACKUP LOG successfully processed 0 pages in 0.004 seconds (0.000 MB/sec).
11/29/2010 11:00:03 PM: SQL Backup process ended.

11/29/2010 11:00:03 PM: Deleted msdb entries older than 11/19/2010 11:00:03 PM
11/29/2010 11:00:03 PM: Deleted local history entries older than 11/19/2010 11:00:03 PM

#####################################################################################

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOG LISA_SP TO DISK = '<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536 "

PROCESSES COMPLETED SUCCESSFULLY

11/29/2010 11:00:04 PM: Backing up LISA_SP (transaction log) on WPLISA instance to:
11/29/2010 11:00:04 PM: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_LISA_SP_20101129_230004.sqb

11/29/2010 11:00:04 PM: BACKUP LOG [LISA_SP] TO VIRTUAL_DEVICE = 'SQLBACKUP_0BD9675B-F318-472E-9CBF-99BAD6262303' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 65536, NAME = N'Database (LISA_SP), 11/29/2010 11:00:04 PM', DESCRIPTION = N'Backup on 11/29/2010 11:00:04 PM Server: BPGBYQPL01\WPLISA Database: LISA_SP', FORMAT

11/29/2010 11:00:04 PM: Backup data size : 512.000 KB
11/29/2010 11:00:04 PM: Compressed data size: 4.000 KB
11/29/2010 11:00:04 PM: Compression rate : 99.22%

11/29/2010 11:00:04 PM: Processed 0 pages for database 'LISA_SP', file 'LISA_SP_CONV_Log' on file 1.
11/29/2010 11:00:04 PM: BACKUP LOG successfully processed 0 pages in 0.003 seconds (0.000 MB/sec).
11/29/2010 11:00:04 PM: SQL Backup process ended.

11/29/2010 11:00:04 PM: Deleted msdb entries older than 11/19/2010 11:00:04 PM
11/29/2010 11:00:04 PM: Deleted local history entries older than 11/19/2010 11:00:04 PM

#####################################################################################

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOG LISA_Tagging TO DISK = '<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536 "

PROCESSES COMPLETED SUCCESSFULLY

11/29/2010 11:00:04 PM: Backing up LISA_Tagging (transaction log) on WPLISA instance to:
11/29/2010 11:00:04 PM: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_LISA_Tagging_20101129_230004.sqb

11/29/2010 11:00:05 PM: BACKUP LOG [LISA_Tagging] TO VIRTUAL_DEVICE = 'SQLBACKUP_1EAC8B86-9897-4042-88F9-69366CE2EA8A' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 65536, NAME = N'Database (LISA_Tagging), 11/29/2010 11:00:04 PM', DESCRIPTION = N'Backup on 11/29/2010 11:00:04 PM Server: BPGBYQPL01\WPLISA Database: LISA_Tagging', FORMAT

11/29/2010 11:00:05 PM: Backup data size : 2.438 MB
11/29/2010 11:00:05 PM: Compressed data size: 358.500 KB
11/29/2010 11:00:05 PM: Compression rate : 85.64%

11/29/2010 11:00:05 PM: Processed 178 pages for database 'LISA_Tagging', file 'LISA_Tagging_Log' on file 1.
11/29/2010 11:00:05 PM: BACKUP LOG successfully processed 178 pages in 0.091 seconds (16.023 MB/sec).
11/29/2010 11:00:05 PM: SQL Backup process ended.

11/29/2010 11:00:05 PM: Deleted msdb entries older than 11/19/2010 11:00:05 PM
11/29/2010 11:00:05 PM: Deleted local history entries older than 11/19/2010 11:00:05 PM

#####################################################################################

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOG LISAINTRDB_ONE TO DISK = '<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536 "

PROCESSES COMPLETED SUCCESSFULLY

11/29/2010 11:00:05 PM: Backing up LISAINTRDB_ONE (transaction log) on WPLISA instance to:
11/29/2010 11:00:05 PM: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_LISAINTRDB_ONE_20101129_230005.sqb

11/29/2010 11:00:06 PM: BACKUP LOG [LISAINTRDB_ONE] TO VIRTUAL_DEVICE = 'SQLBACKUP_B9B44CF8-B884-4A4A-8D21-63C3F9B6173F' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 65536, NAME = N'Database (LISAINTRDB_ONE), 11/29/2010 11:00:05 PM', DESCRIPTION = N'Backup on 11/29/2010 11:00:05 PM Server: BPGBYQPL01\WPLISA Database: LISAINTRDB_ONE', FORMAT

11/29/2010 11:00:06 PM: Backup data size : 2.625 MB
11/29/2010 11:00:06 PM: Compressed data size: 477.000 KB
11/29/2010 11:00:06 PM: Compression rate : 82.25%

11/29/2010 11:00:06 PM: Processed 199 pages for database 'LISAINTRDB_ONE', file 'LISAINTRDB_ONE_Log' on file 1.
11/29/2010 11:00:06 PM: BACKUP LOG successfully processed 199 pages in 0.093 seconds (17.512 MB/sec).
11/29/2010 11:00:06 PM: SQL Backup process ended.

11/29/2010 11:00:06 PM: Deleted msdb entries older than 11/19/2010 11:00:06 PM
11/29/2010 11:00:06 PM: Deleted local history entries older than 11/19/2010 11:00:06 PM

#####################################################################################

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOG PIPELINE_ONE TO DISK = '<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536 "

PROCESSES COMPLETED SUCCESSFULLY

11/29/2010 11:00:06 PM: Backing up PIPELINE_ONE (transaction log) on WPLISA instance to:
11/29/2010 11:00:06 PM: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_PIPELINE_ONE_20101129_230006.sqb

11/29/2010 11:00:07 PM: BACKUP LOG [PIPELINE_ONE] TO VIRTUAL_DEVICE = 'SQLBACKUP_A2744453-B4BF-49D9-859B-37ADBEC91BE7' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 65536, NAME = N'Database (PIPELINE_ONE), 11/29/2010 11:00:06 PM', DESCRIPTION = N'Backup on 11/29/2010 11:00:06 PM Server: BPGBYQPL01\WPLISA Database: PIPELINE_ONE', FORMAT

11/29/2010 11:00:07 PM: Backup data size : 512.000 KB
11/29/2010 11:00:07 PM: Compressed data size: 4.000 KB
11/29/2010 11:00:07 PM: Compression rate : 99.22%

11/29/2010 11:00:07 PM: Processed 0 pages for database 'PIPELINE_ONE', file 'PIPELINE_DEV_Log' on file 1.
11/29/2010 11:00:07 PM: BACKUP LOG successfully processed 0 pages in 0.003 seconds (0.000 MB/sec).
11/29/2010 11:00:07 PM: SQL Backup process ended.

11/29/2010 11:00:07 PM: Deleted msdb entries older than 11/19/2010 11:00:07 PM
11/29/2010 11:00:07 PM: Deleted local history entries older than 11/19/2010 11:00:07 PM

#####################################################################################

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOG SP_LISA_CONVERT TO DISK = '<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', ERASEFILES_ATSTART = 23h, COMPRESSION = 1, THREADS = 1, MAXTRANSFERSIZE = 65536 "

PROCESSES COMPLETED SUCCESSFULLY

11/29/2010 11:00:07 PM: Backing up SP_LISA_CONVERT (transaction log) on WPLISA instance to:
11/29/2010 11:00:07 PM: G:\Microsoft SQL Server\MSSQL.1\MSSQL\Backup\LOG_WPLISA_SP_LISA_CONVERT_20101129_230007.sqb

11/29/2010 11:00:08 PM: BACKUP LOG [SP_LISA_CONVERT] TO VIRTUAL_DEVICE = 'SQLBACKUP_56A1FE53-05C5-45CC-87DB-71B406066DFF' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 65536, NAME = N'Database (SP_LISA_CONVERT), 11/29/2010 11:00:07 PM', DESCRIPTION = N'Backup on 11/29/2010 11:00:07 PM Server: BPGBYQPL01\WPLISA Database: SP_LISA_CONVERT', FORMAT

11/29/2010 11:00:08 PM: Backup data size : 512.000 KB
11/29/2010 11:00:08 PM: Compressed data size: 4.000 KB
11/29/2010 11:00:08 PM: Compression rate : 99.22%

11/29/2010 11:00:08 PM: Processed 0 pages for database 'SP_LISA_CONVERT', file 'LISA_SP_CONV_Log' on file 1.
11/29/2010 11:00:08 PM: BACKUP LOG successfully processed 0 pages in 0.003 seconds (0.000 MB/sec).
11/29/2010 11:00:08 PM: SQL Backup process ended.

11/29/2010 11:00:08 PM: Deleted msdb entries older than 11/19/2010 11:00:08 PM
11/29/2010 11:00:08 PM: Deleted local history entries older than 11/19/2010 11:00:08 PM

#####################################################################################

mdgraves · December 6, 2010 3:43PM

I was running backup ver. 6.2.0.134, and had no issues with this wait type. Yesterday, I upgraded to ver. 6.4.0.56, and overnight I got the wait "MSQL_XP".

Is it possible to reverse out the 6.4.0.56, back to 6.2.0.134, to see if issue goes away?

petey · December 6, 2010 7:12PM

Those 8 backups appear to have run to completion, but for some reason, the last backup isn't returning results to SQL Server. Are the BACKUP commands all that is being run in the job, or are there subsequent commands?

You can send the image to the following e-mail address: peter.yeoh@red-gate.com.

Yes, it would be worth a try reverting to 6.2 to see if the same error occurs.

Thanks.

mdgraves · December 14, 2010 9:55AM

I reverted to 6.2 last week to see if the same error occurs. It does. Not sure if the back-out reversed any previously updated DLLs, etc. I am sending you email with chart showing how behavior started when initial updated happened.

petey · December 18, 2010 10:00PM

Could you please check the version of xp_sqlbackup.dll that's currently installed on your system? It's installed in SQL Server's Binn folder e.g.

\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\Binn. Could you also please check the version of the SQL Backup Agent service (SQBCoreService.exe) that's installed? The default installation folder is C:\Program Files\Red Gate\SQL Backup 6\<instance name>.

Also, the next time this occurs, could you please run sp_who2, and see if there is any backup process running/pending, and if it's blocked by another process?

Thanks.

mdgraves · January 3, 2011 11:32AM

Peter,
I have emailed you the info on the files (printscreen with locations). V6.2.0.134.

Is there a seperate process that backup runs at some period to handle work for clean up of MSDB table history, etc.? Or does this happen during each run?

petey · January 4, 2011 9:06AM

mdgraves wrote:

Is there a seperate process that backup runs at some period to handle work for clean up of MSDB table history, etc.? Or does this happen during each run?

It happens during each run.

TLOG Backup hangs with "MSQL_XP" Wait Type

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk

TLOG Backup hangs with &quot;MSQL_XP&quot; Wait Type

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk

TLOG Backup hangs with "MSQL_XP" Wait Type