March 26, 2015 at 9:57 am
For the past four days, we have seen the following error in the SQL Server Agent log when trying to backup a large (450GB) database:
25272 152c 03/23 21:08:18 7108757 CSQLBackup::doDbSubclientBackup() - starting backup of db = [db]
25272 152c 03/23 21:08:18 7108757 CSQLBackup::doDbBackup() - ***Collectfile offset of db[db] = 18
25272 152c 03/23 21:08:19 7108757 CSQLBackup::doVDIBackup() - Number of streams used in Phase [Differential] = 1
25272 152c 03/23 21:08:19 7108757 CCvSQLVDIBase() - Initialzed COM library.
25272 152c 03/23 21:08:19 7108757 CCvSQLVDI::InitializeVDI() - Dump path =
25272 152c 03/23 21:08:19 7108757 CCvSQLVDIBase::InitializeVDI() - VDI Intialized.
25272 152c 03/23 21:08:19 7108757 CCvSQLVDIBase::setSQLQueryTimeoutKey() - SQLQuery timeout key is not set. Default option is to set timeout to zero.
25272 152c 03/23 21:08:19 7108757 CCvSQLVDIBase::StartDBBackup() - !!!!QUERY: [BACKUP DATABASE [db] TO VIRTUAL_DEVICE = '7f7bd442-d8d9-467c-802a-bd01b6fef22e' WITH MAXTRANSFERSIZE=2097152, BLOCKSIZE=65536, BUFFERCOUNT=20, DIFFERENTIAL, NOINIT, name='CommVault Galaxy Backup'].
25272 152c 03/23 21:08:19 7108757 CCvSQLVDIBase::RunQueryInThread() - OpenThreadToken failed 1008
25272 152c 03/23 21:08:21 7108757 CCvSQLVDI::StartVDIOperation()() - VDI Timeout Used = 300
25272 152c 03/23 21:08:21 7108757 SqlDataTransferHandler::startTransfer() - Created Data Transfer thread for stream [1]. HANDLE [0xAD8]
25272 36c8 03/23 21:08:21 7108757 SdtSignature::ProcessBuffer - [Buffer type - 16(10)][Message type - 273 (111)]
25272 1748 03/23 21:08:21 ####### [PIPELAYER ] Tail response = Archive File Offset: 5014586633 Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 273 EventError = 0
25272 1748 03/23 21:08:21 7108757 ID=GetBkupData SPEED, Bytes Read = 0, Total time = 0.000012, Average = 0.000012, Samples = 1
25272 1748 03/23 21:08:21 7108757 ID=Allocate Buffer SPEED, Bytes Read = 2097152, Total time = 0.000003, Average = 584415.500000, Samples = 1
25272 1748 03/23 21:13:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 1
25272 1748 03/23 21:18:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 2
25272 1748 03/23 21:23:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 3
25272 1748 03/23 21:28:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 4
25272 1748 03/23 21:33:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 5
25272 1748 03/23 21:38:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 6
25272 1748 03/23 21:43:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 7
25272 1748 03/23 21:48:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 8
25272 1748 03/23 21:53:21 7108757 CCvSQLVDI::GetBkpData() - Vdi Timeout retry count = 9
25272 1748 03/23 21:58:21 7108757 CCvSQLVDI::GetBkpData() - GetCommand Failed, returned VD_E_TIMEOUT.
25272 1748 03/23 21:58:21 7108757 SqlDataWriter::writeData() - Stream [1]: Failed to get backup data.
25272 152c 03/23 21:58:21 7108757 SqlDataTransferHandler::startTransfer() - Total Bytes Transferred = 0
25272 152c 03/23 21:58:21 7108757 CCvSQLVDI::Finalize() - Calling Finalize. Max Retry count set to [100]
25272 152c 03/23 21:58:21 7108757 CCvSQLVDI::Finalize() - VDI timeout ocuured ,so we are closing the handle to the thread runSQLQuery
25272 152c 03/23 21:58:21 7108757 CSQLBackup::doVDIBackup() - Error encountered during backup. Error:
25272 152c 03/23 21:58:21 7108757 CSQLCommon::logDatabaseBackupStatus() - Successfully logged the database [db] into backup.out
25272 152c 03/23 21:58:21 7108757 CSQLBackup::doDbSubclientBackup() - Failed to backup the database [db]
The following message is written to the main SQL Server log:
Timeout occurred while waiting for latch: class 'ALLOC_IAM_PAGE_RANGE_CACHE', id 00000002F4941A50, type 2, Task 0x0000000005AEF708 : 19, waittime 296400, flags 0x100000001a, owning task 0x0000000008AD5948. Continuing to wait.
Timeout occurred while waiting for latch: class 'ACCESS_METHODS_HOBT_COUNT', id 000000015A2B5F30, type 2, Task 0x0000000000A65B88 : 1, waittime 297000, flags 0x2018, owning task 0x0000000000000000. Continuing to wait.
Time out occurred while waiting for buffer latch -- type 2, bp 0000000AF0FD51C0, page 1:42875387, stat 0xc0000b, database id: 7, allocation unit id: 72057594377076736, task 0x0000000008AD5948 : 13, waittime 297300, flags 0x3a, owning task 0x0000000000A65B88. Continuing to wait.
LatchClassWait_SWaitCountPercentageAvgWait_S
ALLOC_IAM_PAGE_RANGE_CACHE4670732.48152246.623068.8124
ACCESS_METHODS_DATASET_PARENT4389850.41108797585643.820.0040
ACCESS_METHODS_HOBT_COUNT585023.45159255.8436.7362
DBCC_PFS_STATUS256154.041228670622.560.0021
DBCC_MULTIOBJECT_SCANNER58058.78204756310.580.0028
ACCESS_METHODS_HOBT_VIRTUAL_ROOT13017.7131021340.130.0042
DBCC_OBJECT_METADATA11969.1443196140.120.0028
DBCC_CHECK_TABLE_INIT11454.07225900.110.5070
NESTING_TRANSACTION_READONLY10559.66374075920.110.0003
NESTING_TRANSACTION_FULL6223.10118807330.060.0005
DBCC_CHECK_AGGREGATE3492.5711673070.030.0030
LOG_MANAGER1140.2015030.010.7586
FGCB_ADD_REMOVE838.8450380.010.1665
ACCESS_METHODS_BULK_ALLOC76.624680.000.1637
ACCESS_METHODS_ACCESSOR_CACHE50.35449920.000.0011
BUFFER_POOL_GROW1.544440.000.0035
ALLOC_EXTENT_CACHE0.2810350.000.0003
ACCESS_METHODS_STRING_COMPARE0.242580.000.0009
UTILITY_DYNAMIC_MANAGER_VIEW0.083390.000.0002
QUERY_OPTIMIZER_ID_MANAGER0.053170.000.0001
ACCESS_METHODS_HOBT_FACTORY0.02310.000.0005
SERVICE_BROKER_TRANSMISSION_WORK0.02560.000.0003
Viewing 0 posts
You must be logged in to reply to this topic. Login to reply