search

olahallengren / sql-server-maintenance-solution

SQL Server Maintenance Solution
https://ola.hallengren.com
MIT License
2.9k stars 754 forks source link

Database Backup Job Backs up the same database twice #631

Open sapkota-pratik opened 2 years ago

sapkota-pratik commented 2 years ago

we use the Ola Hallengren Maintenance plan for SQL Server database maintenance. All other maintenance jobs (DBCC and Index Optimization) jobs run fine without any issue but the Backup job is having an issue. it backs up a few user databases twice. it is not consistent. Sometimes it runs fine as expected but sometimes it backs up one or two databases twice.

SQL Server version and edition

Microsoft SQL Server 2016 (SP3) (KB5003279) - 13.0.6300.2 (X64) Aug 7 2021 01:20:37 Copyright (c) Microsoft Corporation Enterprise Edition: Core-based Licensing (64-bit) on Windows Server 2016 Datacenter 10.0 (Build 14393: ) (Hypervisor)

Version of the script --// Source: https://ola.hallengren.com //-- --// License: https://ola.hallengren.com/license.html //-- --// GitHub: https://github.com/olahallengren/sql-server-maintenance-solution //-- --// Version: 2020-12-31 18:58:56 //--

What command are you executing? EXECUTE [dbo].[DatabaseBackup] @Databases = 'USER_DATABASES', @Directory = 'E:\', @BackupType = 'FULL', @Verify = 'Y', @CleanupTime = 360, @CheckSum = 'Y', @LogToTable = 'Y', @compress = 'Y', @bufferCount = 50, @MAXTRANSFERSIZE = 4194304, @Numberoffiles = 4, @minbackupsizeformultiplefiles = 409600, @DatabaseOrder = 'DATABASE_SIZE_DESC'

What output are you getting? Job 'DBA DatabaseBackup - USER_DATABASES' : Step 1, 'DatabaseBackup - USER_DATABASES - FULL' : Began Executing 2022-03-14 13:40:00

Date and time: 2022-03-14 13:40:00 [SQLSTATE 01000] Server: ServerName [SQLSTATE 01000] Version: 13.0.6300.2 [SQLSTATE 01000] Edition: Enterprise Edition: Core-based Licensing (64-bit) [SQLSTATE 01000] Platform: Windows [SQLSTATE 01000]

Procedure: [dbo].[DatabaseBackup] [SQLSTATE 01000] Parameters: @Databases = 'USER_DATABASES', @Directory = 'E:\', @BackupType = 'FULL', @Verify = 'Y', @CleanupTime = 360, @CleanupMode = 'AFTER_BACKUP', @Compress = 'Y', @CopyOnly = 'N', @ChangeBackupType = 'N', @BackupSoftware = NULL, @CheckSum = 'Y', @BlockSize = NULL, @BufferCount = 50, @MaxTransferSize = 4194304, @NumberOfFiles = 4, @MinBackupSizeForMultipleFiles = 409600, @MaxFileSize = NULL, @CompressionLevel = NULL, @Description = NULL, @Threads = NULL, @Throttle = NULL, @Encrypt = 'N', @EncryptionAlgorithm = NULL, @ServerCertificate = NULL, @ServerAsymmetricKey = NULL, @EncryptionKey = NULL, @ReadWriteFileGroups = 'N', @OverrideBackupPreference = 'N', @NoRecovery = 'N', @URL = NULL, @Credential = NULL, @MirrorDirectory = NULL, @MirrorCleanupTime = NULL, @MirrorCleanupMode = 'AFTERBACKUP', @MirrorURL = NULL, @AvailabilityGroups = NULL, @Updateability = 'ALL', @AdaptiveCompression = NULL, @ModificationLevel = NULL, @LogSizeSinceLastLogBackup = NULL, @TimeSinceLastLogBackup = NULL, @DataDomainBoostHost = NULL, @DataDomainBoostUser = NULL, @DataDomainBoostDevicePath = NULL, @DataDomainBoostLockboxPath = NULL, @DirectoryStructure = '{ServerName}${InstanceName}{DirectorySeparator}{DatabaseName}{DirectorySeparator}{BackupType}{Partial}{CopyOnly}', @AvailabilityGroupDirectoryStructure = '{ClusterName}${AvailabilityGroupName}{DirectorySeparator}{DatabaseName}{DirectorySeparator}{BackupType}{Partial}{CopyOnly}', @FileName = '{ServerName}${InstanceName}{DatabaseName}{BackupType}{Partial}{CopyOnly}{Year}{Month}{Day}{Hour}{Minute}{Second}{FileNumber}.{FileExtension}', @AvailabilityGroupFileName = '{ClusterName}${AvailabilityGroupName}{DatabaseName}{BackupType}{Partial}{CopyOnly}{Year}{Month}{Day}{Hour}{Minute}{Second}_{FileNumber}.{FileExtension}', @FileExtensionFull = NULL, @FileExtensionDiff = NULL, @FileExtensionLog = NULL, @Init = 'N', @Format = 'N', @ObjectLevelRecoveryMap = 'N', @ExcludeLogShipp...

Version: 2020-12-31 18:58:56 [SQLSTATE 01000] Source: https://ola.hallengren.com [SQLSTATE 01000] [SQLSTATE 01000]

Date and time: 2022-03-14 13:40:00 [SQLSTATE 01000]

Database: [DatabaseName] [SQLSTATE 01000] State: ONLINE [SQLSTATE 01000] Standby: No [SQLSTATE 01000] Updateability: READ_WRITE [SQLSTATE 01000] User access: MULTI_USER [SQLSTATE 01000] Recovery model: SIMPLE [SQLSTATE 01000] Encrypted: No [SQLSTATE 01000] Is accessible: Yes [SQLSTATE 01000] Differential base LSN: 22770000000369600037 [SQLSTATE 01000] Last log backup LSN: N/A [SQLSTATE 01000] Allocated extent page count: 7280 (56.875000 MB) [SQLSTATE 01000] Modified extent page count: 40 (0.312500 MB) [SQLSTATE 01000] [SQLSTATE 01000] Date and time: 2022-03-14 13:40:00 [SQLSTATE 01000]

--Chck or create Directory Database context: [master] [SQLSTATE 01000] Command: DECLARE @ReturnCode int EXECUTE @ReturnCode = dbo.xp_create_subdir N'E:\ServerName\DatabaseName\FULL' IF @ReturnCode <> 0 RAISERROR('Error creating directory.', 16, 1) [SQLSTATE 01000] Outcome: Succeeded [SQLSTATE 01000] Duration: 00:00:00 [SQLSTATE 01000] Date and time: 2022-03-14 13:40:00 [SQLSTATE 01000] [SQLSTATE 01000] Date and time: 2022-03-14 13:40:00 [SQLSTATE 01000]

--Backup Command Database context: [master] [SQLSTATE 01000] Command: BACKUP DATABASE [DatabaseName] TO DISK = N'E:\ServerName\DatabaseName\FULL\ServerName_DatabaseName_FULL_20220314_134000.bak' WITH CHECKSUM, COMPRESSION, BUFFERCOUNT = 50, MAXTRANSFERSIZE = 4194304 [SQLSTATE 01000] Processed 7512 pages for database 'DatabaseName', file 'DatabaseName' on file 1. [SQLSTATE 01000] Processed 2 pages for database 'DatabaseName', file 'DatabaseName_log' on file 1. [SQLSTATE 01000] BACKUP DATABASE successfully processed 7514 pages in 0.756 seconds (77.649 MB/sec). [SQLSTATE 01000] Outcome: Succeeded [SQLSTATE 01000] Duration: 00:00:01 [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] [SQLSTATE 01000]

--Check Backup
Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] Database context: [master] [SQLSTATE 01000] Command: RESTORE VERIFYONLY FROM DISK = N'E:\ServerName\DatabaseName\FULL\ServerName_DatabaseName_FULL_20220314_134000.bak' WITH CHECKSUM [SQLSTATE 01000] The backup set on file 1 is valid. [SQLSTATE 01000] Outcome: Succeeded [SQLSTATE 01000] Duration: 00:00:00 [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] [SQLSTATE 01000]

--Delete Old Files Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] Database context: [master] [SQLSTATE 01000] Command: DECLARE @ReturnCode int EXECUTE @ReturnCode = dbo.xp_delete_file 0, N'E:\ServerName\DatabaseName\FULL', 'bak', '2022-02-27T13:40:01' IF @ReturnCode <> 0 RAISERROR('Error deleting files.', 16, 1) [SQLSTATE 01000] Outcome: Succeeded [SQLSTATE 01000] Duration: 00:00:00 [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] [SQLSTATE 01000]

Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] Database: [DatabaseName] [SQLSTATE 01000] State: ONLINE [SQLSTATE 01000] Standby: No [SQLSTATE 01000] Updateability: READ_WRITE [SQLSTATE 01000] User access: MULTI_USER [SQLSTATE 01000] Recovery model: SIMPLE [SQLSTATE 01000] Encrypted: No [SQLSTATE 01000] Is accessible: Yes [SQLSTATE 01000] Differential base LSN: 22770000000376800037 [SQLSTATE 01000] Last log backup LSN: N/A [SQLSTATE 01000] Allocated extent page count: 7280 (56.875000 MB) [SQLSTATE 01000] Modified extent page count: 40 (0.312500 MB) [SQLSTATE 01000] [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] Database context: [master] [SQLSTATE 01000] Command: DECLARE @ReturnCode int EXECUTE @ReturnCode = dbo.xp_create_subdir N'E:\ServerName\DatabaseName\FULL' IF @ReturnCode <> 0 RAISERROR('Error creating directory.', 16, 1) [SQLSTATE 01000] Outcome: Succeeded [SQLSTATE 01000] Duration: 00:00:00 [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] Database context: [master] [SQLSTATE 01000] Command: BACKUP DATABASE [DatabaseName] TO DISK = N'E:\ServerName\DatabaseName\FULL\ServerName_DatabaseName_FULL_20220314_134001.bak' WITH CHECKSUM, COMPRESSION, BUFFERCOUNT = 50, MAXTRANSFERSIZE = 4194304 [SQLSTATE 01000] Processed 7512 pages for database 'DatabaseName', file 'DatabaseName' on file 1. [SQLSTATE 01000] Processed 2 pages for database 'DatabaseName', file 'DatabaseName_log' on file 1. [SQLSTATE 01000] BACKUP DATABASE successfully processed 7514 pages in 0.206 seconds (284.966 MB/sec). [SQLSTATE 01000] Outcome: Succeeded [SQLSTATE 01000] Duration: 00:00:00 [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] Database context: [master] [SQLSTATE 01000] Command: RESTORE VERIFYONLY FROM DISK = N'E:\ServerName\DatabaseName\FULL\ServerName_DatabaseName_FULL_20220314_134001.bak' WITH CHECKSUM [SQLSTATE 01000] The backup set on file 1 is valid. [SQLSTATE 01000] Outcome: Succeeded [SQLSTATE 01000] Duration: 00:00:00 [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] Database context: [master] [SQLSTATE 01000] Command: DECLARE @ReturnCode int EXECUTE @ReturnCode = dbo.xp_delete_file 0, N'E:\ServerName\DatabaseName\FULL', 'bak', '2022-02-27T13:40:01' IF @ReturnCode <> 0 RAISERROR('Error deleting files.', 16, 1) [SQLSTATE 01000] Outcome: Succeeded [SQLSTATE 01000] Duration: 00:00:00 [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000] Database: [DBATOOLS] [SQLSTATE 01000] State: ONLINE [SQLSTATE 01000] Standby: No [SQLSTATE 01000] Updateability: READ_WRITE [SQLSTATE 01000] User access: MULTI_USER [SQLSTATE 01000] Recovery model: SIMPLE [SQLSTATE 01000] Encrypted: No [SQLSTATE 01000] Is accessible: Yes [SQLSTATE 01000] Differential base LSN: 951000011430400080 [SQLSTATE 01000] Last log backup LSN: N/A [SQLSTATE 01000] Allocated extent page count: 9160 (71.562500 MB) [SQLSTATE 01000] Modified extent page count: 104 (0.812500 MB) [SQLSTATE 01000] [SQLSTATE 01000] Date and time: 2022-03-14 13:40:01 [SQLSTATE 01000]

bwiggins10 commented 2 years ago

I use this across various environments with varying SQL Versions, and have not had this occur before and have used every single parameter you've used EXCEPT for @DatabaseOrder = 'DATABASE_SIZE_DESC' leading me to believe it's a bug with this parameter. I would try omitting this and see if it recurs.

powderdba commented 6 months ago

I'm having the same issue.

It is inconsistent. Sometimes it won't happen for weeks, then sometimes every night. And so far it's only been happening on one server, the rest are fine.

I am also using @DatabaseOrder = 'DATABASE_SIZE_DESC', as @bwiggins10 noted.

I tried adding a waitfor at the end of the loop to see if it's some race condition causing the issue but it's still happening.

After further investigation into the backup histories, it appears to be the same job picking up the same database twice in a row, for example if there's parallel jobs 1, 2, 3, and 4, then job 3 will pick up the same database twice. Which leans more towards the queuedatabase table not being updated when the backup finished, so the job picks it up again to be backed up.

It seems to only happen on the largest databases, so the ones that are backed up first (though the job that pick these up take longer than all the other jobs, so by the end it's just one job still running, backing up the first largest database. Then it picks up the same database to be backed up again).

I haven't tried any further code changes to be sure of what's causing it.

One thing to note is that the job appends the new database backup to the same file, so then there's two backups within one .bak file when the issue happens.