August 9, 2017 at 4:55 am
Hi,
We sometimes (not always) have the issue that our backups seem to take a very long time to start.
The time that is given in the result of the query doesn't correspond with the time it actually took.
If I run the query:
BACKUP DATABASE [x] TO DISK = 'd:\test.bak'
I get this as output:
Processed 1544 pages for database 'X', file 'Y-X_Table' on file 1.
Processed 1024 pages for database 'X', file 'Y-X_Index' on file 1.
Processed 1040 pages for database 'X', file 'Y-X' on file 1.
Processed 24280 pages for database 'X', file 'FileGrp_Index_22AAA71' on file 1.
Processed 160992 pages for database 'X', file 'FileGrp_Table_48093562' on file 1.
Processed 350 pages for database 'X', file 'Y_Media' on file 1.
Processed 66 pages for database 'X', file 'Y-X_Log_log' on file 1.
BACKUP DATABASE successfully processed 189295 pages in 287.019 seconds (5.152 MB/sec).
However the actual query execution time as given in query analyser was 10m15s (so 615 seconds).
When I look at what's running after I start the query I see this:
SPID Threads Seconds %_Complete Cost Host Login Database Blocked_by Statement Schema Object Plan Cpu_Time Logical_Reads Reads Writes Wait_Time Wait_Type Program Status Granted_Memory_MB Missing_Memory_MB Estimated_Completion_Time
63 2 237 0 NULL x x\y x 0 BACKUP DATABASE [x] TO DISK = 'd:\test.bak' NULL NULL <ShowPlanXML xmlns="http://schemas.microsoft.com/sqlserver/2004/07/showplan" Version="1.2" Build="11.0.6598.0"><BatchSequence><Batch><Statements><StmtSimple StatementText="BACKUP DATABASE [x] TO DISK = 'd:\test.bak'" StatementId="1" StatementCompId="1" StatementType="BACKUP DATABASE" RetrievedFromCache="false" /></Statements></Batch></BatchSequence></ShowPlanXML> 15 50 0 6 220554 ASYNC_IO_COMPLETION .Net SqlClient Data Provider running NULL NULL 0
I don't manage to format it very well here but you can see that the %_complete remains at 0 after the first 237 seconds, as wait type it shows ASYNC_IO_COMPLETION.
The difference between the number of seconds in the successfully processed message and the actual time corresponds to this wait time.
My first idea was that it was caused by the Real-Time virus scanner, but even if it is disabled I sometimes see this happening.
Note that sometimes the delay is a couple of minutes, but I had occasions where it was over 2 hours. And sometimes there isn't any delay at all.
When I look at cpu and disk activity while the wait is happing it is very low. There are also no other queries running at the same time.
A similar database exists on multiple nearly identical computers. I see this issue occuring on all of them;
.Could somebody help us with any clues what could be the cause of this?
August 9, 2017 at 6:57 am
I would focus on the wait statistics. You can capture these using extended events. Here's an article from Paul Randal. There's something blocking the process. It's hard to say what from here. Capturing the wait stats will fill that in.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
August 9, 2017 at 4:33 pm
Thanks for the reply.
I did what was said in the article you referred to.
This is the result for a backup that took over 20 minutes but for which the query gave as result:
BACKUP DATABASE successfully processed 272109 pages in 226.951 seconds (9.366 MB/sec).
Wait Type Wait Count Total Wait Time (ms) Total Resource Wait Time (ms) Total Signal Wait Time (ms)
ASYNC_IO_COMPLETION 3 1031498 1031498 0
BACKUPTHREAD 21 147746 147746 0
BACKUPBUFFER 68007 122675 122520 155
BACKUPIO 16400 30362 30360 2
SLEEP_BPOOL_FLUSH 228 655 655 0
PAGEIOLATCH_EX 5 33 33 0
WRITELOG 13 32 32 0
PAGEIOLATCH_SH 1 18 18 0
PAGEIOLATCH_UP 4 8 8 0
SOS_SCHEDULER_YIELD 629 1 0 1
XE_BUFFERMGR_ALLPROCESSED_EVENT 1 0 0 0
I also did a backup of a similar database (same structure but different data) where there was no or very limited delay.
The wait stats I get there are:
ASYNC_IO_COMPLETION 3 88438 88438 0
BACKUPBUFFER 41943 57995 57824 171
BACKUPIO 4949 26931 26931 0
BACKUPTHREAD 21 21413 21413 0
WRITELOG 13 42 42 0
PAGEIOLATCH_SH 1 26 26 0
PAGEIOLATCH_UP 4 10 10 0
PAGEIOLATCH_EX 2 9 9 0
SLEEP_BPOOL_FLUSH 42 3 3 0
XE_BUFFERMGR_ALLPROCESSED_EVENT 1 0 0 0
SOS_SCHEDULER_YIELD 1355 0 0 0
When looking to the details of the ASYNC_IO_COMPLETION waittype I see this for the slow backup:
ASYNC_IO_COMPLETION 2017-08-09 20:00:37.467 ASYNC_IO_COMPLETION Begin 0 0
ASYNC_IO_COMPLETION 2017-08-09 20:00:38.340 ASYNC_IO_COMPLETION End 873 0
ASYNC_IO_COMPLETION 2017-08-09 20:00:38.343 ASYNC_IO_COMPLETION Begin 0 0
ASYNC_IO_COMPLETION 2017-08-09 20:16:29.830 ASYNC_IO_COMPLETION End 951486 0
ASYNC_IO_COMPLETION 2017-08-09 20:16:29.857 ASYNC_IO_COMPLETION Begin 0 0
ASYNC_IO_COMPLETION 2017-08-09 20:17:48.997 ASYNC_IO_COMPLETION End 79139 0
And this for the ok backup:
ASYNC_IO_COMPLETION 2017-08-09 21:57:04.280 ASYNC_IO_COMPLETION Begin 0 0
ASYNC_IO_COMPLETION 2017-08-09 21:57:04.360 ASYNC_IO_COMPLETION End 80 0
ASYNC_IO_COMPLETION 2017-08-09 21:57:04.363 ASYNC_IO_COMPLETION Begin 0 0
ASYNC_IO_COMPLETION 2017-08-09 21:57:17.067 ASYNC_IO_COMPLETION End 12702 0
ASYNC_IO_COMPLETION 2017-08-09 21:57:17.070 ASYNC_IO_COMPLETION Begin 0 0
ASYNC_IO_COMPLETION 2017-08-09 21:58:32.723 ASYNC_IO_COMPLETION End 75656 0
The difference is clearly in the second ASYNC_IO_COMPLETION wait.
But could somebody tell me what it is actually doing there?
It also seems that if I run the backup a second time just after the first this issue doesn't occur.
Could it have something to do with reading from disk into memory?
August 9, 2017 at 5:07 pm
It looks like the issue is somewhere around your disks. Is this networked storage or local? Is it virtual? It looks like you're hitting some kind of spin-up delay on the hardware. Frankly, this is outside my experience. However, it's not SQL Server directly. It's something external that's causing the issue.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
August 10, 2017 at 2:32 am
I'd guess that time is to create the backup file (can't recall if it has to be zeroed out). It shouldn't be that slow though.
What's the IO subsystem for the machines that show this? Where's the backup being written to?
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
August 10, 2017 at 4:56 am
GilaMonster - Thursday, August 10, 2017 2:32 AMI'd guess that time is to create the backup file (can't recall if it has to be zeroed out). It shouldn't be that slow though.What's the IO subsystem for the machines that show this? Where's the backup being written to?
It doesn't have to be zeroed out. I thought that might be it too so did some research on it.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
August 10, 2017 at 5:43 am
I must say there is a table containing 500.000 rows of which files are saved on disk (Filestream) The files itself are very small. (see screenshot in attachment)
Could it be the cause that reading all these files from disk is very slow?
August 10, 2017 at 6:03 am
Ah.
I'll bet that's it. It's notorious.
You can do partial backups where you only backup the database data and not the filestream data, or do that separately. Make you're following the best practices. Otherwise, you just have longer backups.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
August 11, 2017 at 3:47 am
Thanks for the help! Indeed if I backup the filegroups seperately it is quite obvious where the issue is:
Processed 248040 pages for database 'X', file 'FileGrp_Table_4D6D0AE4' onfile 1.
Processed 14 pages for database 'X', file 'X_log' onfile 1.
BACKUPDATABASE...FILE=<name> successfully processed 248054 pages in 62.621 seconds (30.946 MB/sec).
Query time: 62 sec
Processed 38744 pages for database 'X', file 'FileGrp_Index_4D704C41' onfile 1.
Processed 6 pages for database 'X, file 'X_Log_log' onfile 1.
BACKUPDATABASE...FILE=<name> successfully processed 38750 pages in 9.875 seconds (30.656 MB/sec).
Query time: 10 sec
Processed 937 pages for database 'X', file 'X_Media' on file 1.
Processed 101 pages for database 'X, file 'X_Log_log' onfile 1.
BACKUPDATABASE...FILE=<name> successfully processed 1037 pages in 110.361 seconds (0.073 MB/sec).
Query time 15m 42s
Viewing 9 posts - 1 through 9 (of 9 total)
You must be logged in to reply to this topic. Login to reply