FULL COPY ONLY BACKUP ON Secondary replica blocking background command DB STARTUP

Question

Dear Folks,

While Full copy only backup is running on secondary replica it is blocking background process DB STARTUP command for that database,
utlimately giving birth to latency on secondary replica and log_reuse_wait_desc output as AVAILABILITY_REPLICA
The database is VLDB, having size of 8TB. I am clueless, need suggestions to resolve the issue.

We have third party tool configured which is continuously giving alert of this blocking.
ETA for completion is 9 hours approx, If I wait for 9 hours then there will be too much latency due to blocking

Need your advice and suggestions

Answer 1

This is the REDO thread also called as DB_startup is doing its redo and blocking things. When it is going on it may block other processes and there is not much you can do. Below article has details about this

Troubleshooting REDO queue build-up (data latency issues) on AlwaysOn Readable Secondary Replicas using the WAIT_IN...

My suggestion do not start backup until this has completed. This is by design

Answer 2

Hi Shashank,

I tried it on weekend again, same thing happened SPID from full_copy_only backup was blocking DB_Startup SPID, due to which t-log backup started failing and hence latency occurs.
Since it was the weekend hence very less activity on db and able to complete the job with blocking and t-log backup failure scenario.

It is still a mystery for me why only for this DB which is VLDB redo threads are getting blocked by full_copy_only job everytime.

Once job completed taken full backups and secondary replica catched up primary replica.

Answer 3

2021-01-17 02:26:57.68 spid48s FlushCache: cleaned up 5627 bufs with 4046 writes in 69078 ms (avoided 198 new dirty bufs) for db 9:0
2021-01-17 02:26:57.68 spid48s average writes per second: 58.57 writes/sec
average throughput: 0.62 MB/sec, I/O saturation: 2820, context switches 4532
2021-01-17 02:26:57.68 spid48s last target outstanding: 44480, avgWriteLatency 1
2021-01-17 02:39:43.74 spid48s FlushCache: cleaned up 6251 bufs with 4667 writes in 285062 ms (avoided 128 new dirty bufs) for db 9:0
2021-01-17 02:39:43.74 spid48s average writes per second: 16.37 writes/sec
average throughput: 0.17 MB/sec, I/O saturation: 12306, context switches 21470
2021-01-17 02:39:43.74 spid48s last target outstanding: 4, avgWriteLatency 97
2021-01-17 02:40:12.72 spid440s FlushCache: cleaned up 67748 bufs with 5686 writes in 388739 ms (avoided 311 new dirty bufs) for db 8:0
2021-01-17 02:40:12.72 spid440s average writes per second: 14.63 writes/sec
average throughput: 1.36 MB/sec, I/O saturation: 15066, context switches 27513
2021-01-17 02:40:12.72 spid440s last target outstanding: 2, avgWriteLatency 79
2021-01-17 02:41:43.08 spid48s FlushCache: cleaned up 5172 bufs with 4048 writes in 105214 ms (avoided 168 new dirty bufs) for db 9:0
2021-01-17 02:41:43.08 spid48s average writes per second: 38.47 writes/sec
average throughput: 0.38 MB/sec, I/O saturation: 5297, context switches 8170
2021-01-17 02:41:43.08 spid48s last target outstanding: 44480, avgWriteLatency 75
2021-01-17 02:42:42.17 spid440s FlushCache: cleaned up 43918 bufs with 4691 writes in 133757 ms (avoided 7767 new dirty bufs) for db 8:0
2021-01-17 02:42:42.17 spid440s average writes per second: 35.07 writes/sec
average throughput: 2.56 MB/sec, I/O saturation: 6311, context switches 11169
2021-01-17 02:42:42.17 spid440s last target outstanding: 44480, avgWriteLatency 112
2021-01-17 02:46:05.29 spid48s FlushCache: cleaned up 4993 bufs with 3974 writes in 203390 ms (avoided 530 new dirty bufs) for db 9:0
2021-01-17 02:46:05.29 spid48s average writes per second: 19.54 writes/sec
average throughput: 0.19 MB/sec, I/O saturation: 9259, context switches 14237
2021-01-17 02:46:05.29 spid48s last target outstanding: 2, avgWriteLatency 99
2021-01-17 02:47:47.51 spid440s FlushCache: cleaned up 46176 bufs with 4550 writes in 301443 ms (avoided 321 new dirty bufs) for db 8:0
2021-01-17 02:47:47.51 spid440s average writes per second: 15.09 writes/sec
average throughput: 1.19 MB/sec, I/O saturation: 12324, context switches 21862
2021-01-17 02:47:47.51 spid440s last target outstanding: 8, avgWriteLatency 105
2021-01-17 02:47:56.66 spid48s FlushCache: cleaned up 5601 bufs with 4099 writes in 111382 ms (avoided 164 new dirty bufs) for db 9:0
2021-01-17 02:47:56.66 spid48s average writes per second: 36.80 writes/sec
average throughput: 0.39 MB/sec, I/O saturation: 6209, context switches 9823
2021-01-17 02:47:56.66 spid48s last target outstanding: 40, avgWriteLatency 90
2021-01-17 02:50:32.60 spid440s FlushCache: cleaned up 29628 bufs with 3340 writes in 156473 ms (avoided 7820 new dirty bufs) for db 8:0
2021-01-17 02:50:32.60 spid440s average writes per second: 21.35 writes/sec
average throughput: 1.48 MB/sec, I/O saturation: 6555, context switches 11617
2021-01-17 02:50:32.60 spid440s last target outstanding: 2, avgWriteLatency 94
2021-01-17 02:51:02.74 spid48s FlushCache: cleaned up 5281 bufs with 4260 writes in 130432 ms (avoided 177 new dirty bufs) for db 9:0
2021-01-17 02:51:02.74 spid48s average writes per second: 32.66 writes/sec
average throughput: 0.31 MB/sec, I/O saturation: 6458, context switches 10763
2021-01-17 02:51:02.74 spid48s last target outstanding: 952, avgWriteLatency 85
2021-01-17 02:52:41.63 spid48s FlushCache: cleaned up 4020 bufs with 2739 writes in 98528 ms (avoided 151 new dirty bufs) for db 9:0
2021-01-17 02:52:41.63 spid48s average writes per second: 27.80 writes/sec
average throughput: 0.31 MB/sec, I/O saturation: 4888, context switches 8185
2021-01-17 02:52:41.63 spid48s last target outstanding: 34, avgWriteLatency 0
2021-01-17 02:52:44.05 spid440s FlushCache: cleaned up 28053 bufs with 2881 writes in 126987 ms (avoided 45 new dirty bufs) for db 8:0
2021-01-17 02:52:44.05 spid440s average writes per second: 22.69 writes/sec
average throughput: 1.72 MB/sec, I/O saturation: 5404, context switches 9333
2021-01-17 02:52:44.05 spid440s last target outstanding: 44480, avgWriteLatency 1
2021-01-17 02:53:50.61 spid440s FlushCache: cleaned up 22724 bufs with 3066 writes in 63385 ms (avoided 409 new dirty bufs) for db 8:0
2021-01-17 02:53:50.61 spid440s average writes per second: 48.37 writes/sec
average throughput: 2.79 MB/sec, I/O saturation: 3326, context switches 6029
2021-01-17 02:53:50.61 spid440s last target outstanding: 44480, avgWriteLatency 108
2021-01-17 02:56:00.13 spid440s FlushCache: cleaned up 59311 bufs with 5189 writes in 115606 ms (avoided 2055 new dirty bufs) for db 8:0
2021-01-17 02:56:00.13 spid440s average writes per second: 44.89 writes/sec
average throughput: 4.00 MB/sec, I/O saturation: 6812, context switches 11204
2021-01-17 02:56:00.13 spid440s last target outstanding: 172, avgWriteLatency 67
2021-01-17 02:57:07.03 spid48s FlushCache: cleaned up 7163 bufs with 5192 writes in 168797 ms (avoided 174 new dirty bufs) for db 9:0
2021-01-17 02:57:07.03 spid48s average writes per second: 30.76 writes/sec
average throughput: 0.33 MB/sec, I/O saturation: 8412, context switches 12717
2021-01-17 02:57:07.03 spid48s last target outstanding: 2, avgWriteLatency 21
2021-01-17 02:57:29.16 spid440s FlushCache: cleaned up 27621 bufs with 3948 writes in 75944 ms (avoided 88 new dirty bufs) for db 8:0
2021-01-17 02:57:29.16 spid440s average writes per second: 51.99 writes/sec
average throughput: 2.83 MB/sec, I/O saturation: 4471, context switches 7582
2021-01-17 02:57:29.16 spid440s last target outstanding: 614, avgWriteLatency 65
2021-01-17 02:58:35.25 spid48s FlushCache: cleaned up 6293 bufs with 4776 writes in 88270 ms (avoided 140 new dirty bufs) for db 9:0
2021-01-17 02:58:35.25 spid48s average writes per second: 54.11 writes/sec
average throughput: 0.56 MB/sec, I/O saturation: 4721, context switches 7006
2021-01-17 02:58:35.25 spid48s last target outstanding: 3680, avgWriteLatency 75
2021-01-17 02:59:17.13 spid440s FlushCache: cleaned up 5989 bufs with 1973 writes in 107283 ms (avoided 315 new dirty bufs) for db 8:0
2021-01-17 02:59:17.13 spid440s average writes per second: 18.39 writes/sec
average throughput: 0.43 MB/sec, I/O saturation: 4699, context switches 7963
2021-01-17 02:59:17.13 spid440s last target outstanding: 2, avgWriteLatency 88
2021-01-17 03:00:12.21 spid48s FlushCache: cleaned up 6201 bufs with 4311 writes in 95768 ms (avoided 208 new dirty bufs) for db 9:0
2021-01-17 03:00:12.21 spid48s average writes per second: 45.02 writes/sec
average throughput: 0.50 MB/sec, I/O saturation: 4683, context switches 7159
2021-01-17 03:00:12.21 spid48s last target outstanding: 4420, avgWriteLatency 25
2021-01-17 03:02:24.05 spid48s FlushCache: cleaned up 5905 bufs with 3772 writes in 129015 ms (avoided 51 new dirty bufs) for db 9:0
2021-01-17 03:02:24.05 spid48s average writes per second: 29.24 writes/sec
average throughput: 0.36 MB/sec, I/O saturation: 5520, context switches 9431
2021-01-17 03:02:24.05 spid48s last target outstanding: 44480, avgWriteLatency 191
2021-01-17 03:02:46.02 spid440s FlushCache: cleaned up 91719 bufs with 7477 writes in 175448 ms (avoided 9256 new dirty bufs) for db 8:0
2021-01-17 03:02:46.02 spid440s average writes per second: 42.62 writes/sec
average throughput: 4.08 MB/sec, I/O saturation: 9579, context switches 16240
2021-01-17 03:02:46.02 spid440s last target outstanding: 552, avgWriteLatency 195
2021-01-17 03:05:30.56 spid48s FlushCache: cleaned up 6808 bufs with 4912 writes in 105355 ms (avoided 253 new dirty bufs) for db 9:0
2021-01-17 03:05:30.56 spid48s average writes per second: 46.62 writes/sec
average throughput: 0.50 MB/sec, I/O saturation: 5049, context switches 8152
2021-01-17 03:05:30.56 spid48s last target outstanding: 44480, avgWriteLatency 75
2021-01-17 03:06:56.85 spid48s FlushCache: cleaned up 6833 bufs with 4980 writes in 86138 ms (avoided 56 new dirty bufs) for db 9:0
2021-01-17 03:06:56.85 spid48s average writes per second: 57.81 writes/sec
average throughput: 0.62 MB/sec, I/O saturation: 4968, context switches 7918
2021-01-17 03:06:56.85 spid48s last target outstanding: 50, avgWriteLatency 248
2021-01-17 03:11:27.94 spid48s FlushCache: cleaned up 7581 bufs with 5632 writes in 271103 ms (avoided 288 new dirty bufs) for db 9:0
2021-01-17 03:11:27.94 spid48s average writes per second: 20.77 writes/sec
average throughput: 0.22 MB/sec, I/O saturation: 11506, context switches 17992
2021-01-17 03:11:27.94 spid48s last target outstanding: 16642, avgWriteLatency 123
2021-01-17 03:12:28.24 spid440s FlushCache: cleaned up 373923 bufs with 21603 writes in 498131 ms (avoided 88460 new dirty bufs) for db 8:0
2021-01-17 03:12:28.24 spid440s average writes per second: 43.37 writes/sec
average throughput: 5.86 MB/sec, I/O saturation: 25935, context switches 46219
2021-01-17 03:12:28.24 spid440s last target outstanding: 44480, avgWriteLatency 1773
2021-01-17 03:16:06.05 spid48s FlushCache: cleaned up 5776 bufs with 4052 writes in 277998 ms (avoided 93 new dirty bufs) for db 9:0
2021-01-17 03:16:06.05 spid48s average writes per second: 14.58 writes/sec
average throughput: 0.16 MB/sec, I/O saturation: 10683, context switches 16319
2021-01-17 03:16:06.05 spid48s last target outstanding: 44480, avgWriteLatency 1
2021-01-17 03:22:25.76 spid440s FlushCache: cleaned up 230830 bufs with 15956 writes in 519561 ms (avoided 929 new dirty bufs) for db 8:0
2021-01-17 03:22:25.76 spid440s average writes per second: 30.71 writes/sec
average throughput: 3.47 MB/sec, I/O saturation: 21148, context switches 41656
2021-01-17 03:22:25.76 spid440s last target outstanding: 44480, avgWriteLatency 1808
2021-01-17 03:23:38.91 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 03:23:38.91 Backup BACKUP failed to complete the command BACKUP LOG DB_DEF. Check the backup application log for detailed messages.
2021-01-17 03:23:40.50 spid48s FlushCache: cleaned up 6770 bufs with 4697 writes in 455119 ms (avoided 214 new dirty bufs) for db 9:0
2021-01-17 03:23:40.50 spid48s average writes per second: 10.32 writes/sec
average throughput: 0.11 MB/sec, I/O saturation: 16289, context switches 26896
2021-01-17 03:23:40.50 spid48s last target outstanding: 20036, avgWriteLatency 280
2021-01-17 03:26:07.03 spid48s FlushCache: cleaned up 5932 bufs with 4638 writes in 145934 ms (avoided 229 new dirty bufs) for db 9:0
2021-01-17 03:26:07.03 spid48s average writes per second: 31.78 writes/sec
average throughput: 0.32 MB/sec, I/O saturation: 5310, context switches 10833
2021-01-17 03:26:07.03 spid48s last target outstanding: 5730, avgWriteLatency 324
2021-01-17 03:30:25.88 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 03:30:25.88 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 03:34:28.98 spid48s FlushCache: cleaned up 5903 bufs with 4477 writes in 502175 ms (avoided 231 new dirty bufs) for db 9:0
2021-01-17 03:34:28.98 spid48s average writes per second: 8.92 writes/sec
average throughput: 0.09 MB/sec, I/O saturation: 17785, context switches 30187
2021-01-17 03:34:28.98 spid48s last target outstanding: 44480, avgWriteLatency 448
2021-01-17 03:37:18.70 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 03:37:18.70 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 03:40:29.93 spid48s FlushCache: cleaned up 5404 bufs with 4036 writes in 361283 ms (avoided 175 new dirty bufs) for db 9:0
2021-01-17 03:40:29.93 spid48s average writes per second: 11.17 writes/sec
average throughput: 0.12 MB/sec, I/O saturation: 13004, context switches 21925
2021-01-17 03:40:29.93 spid48s last target outstanding: 15220, avgWriteLatency 418
2021-01-17 03:44:27.83 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 03:44:27.83 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 03:48:53.24 spid48s FlushCache: cleaned up 7492 bufs with 5390 writes in 497341 ms (avoided 188 new dirty bufs) for db 9:0
2021-01-17 03:48:53.24 spid48s average writes per second: 10.84 writes/sec
average throughput: 0.12 MB/sec, I/O saturation: 17649, context switches 35278
2021-01-17 03:48:53.24 spid48s last target outstanding: 44480, avgWriteLatency 439
2021-01-17 03:51:20.32 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 03:51:20.32 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 03:51:23.03 spid48s FlushCache: cleaned up 8208 bufs with 4903 writes in 148739 ms (avoided 140 new dirty bufs) for db 9:0
2021-01-17 03:51:23.03 spid48s average writes per second: 32.96 writes/sec
average throughput: 0.43 MB/sec, I/O saturation: 5389, context switches 11514
2021-01-17 03:51:23.03 spid48s last target outstanding: 44480, avgWriteLatency 194
2021-01-17 03:56:28.42 spid48s FlushCache: cleaned up 4817 bufs with 3839 writes in 303198 ms (avoided 265 new dirty bufs) for db 9:0
2021-01-17 03:56:28.42 spid48s average writes per second: 12.66 writes/sec
average throughput: 0.12 MB/sec, I/O saturation: 12131, context switches 21196
2021-01-17 03:56:28.42 spid48s last target outstanding: 2, avgWriteLatency 416
2021-01-17 03:58:19.67 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 03:58:19.67 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:04:53.53 spid48s FlushCache: cleaned up 7436 bufs with 5497 writes in 501856 ms (avoided 149 new dirty bufs) for db 9:0
2021-01-17 04:04:53.53 spid48s average writes per second: 10.95 writes/sec
average throughput: 0.12 MB/sec, I/O saturation: 17786, context switches 35432
2021-01-17 04:04:53.53 spid48s last target outstanding: 44480, avgWriteLatency 0
2021-01-17 04:05:24.09 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 04:05:24.09 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:05:37.17 spid358s FlushCache: cleaned up 43226 bufs with 661 writes in 244893 ms (avoided 0 new dirty bufs) for db 20:0
2021-01-17 04:05:37.17 spid358s average writes per second: 2.70 writes/sec
average throughput: 1.38 MB/sec, I/O saturation: 8150, context switches 13854
2021-01-17 04:05:37.17 spid358s last target outstanding: 2, avgWriteLatency 417
2021-01-17 04:09:51.89 spid48s FlushCache: cleaned up 8935 bufs with 6199 writes in 297704 ms (avoided 258 new dirty bufs) for db 9:0
2021-01-17 04:09:51.89 spid48s average writes per second: 20.82 writes/sec
average throughput: 0.23 MB/sec, I/O saturation: 10695, context switches 20199
2021-01-17 04:09:51.89 spid48s last target outstanding: 44480, avgWriteLatency 0
2021-01-17 04:12:21.56 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 04:12:21.56 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:13:49.68 spid48s FlushCache: cleaned up 5889 bufs with 3805 writes in 238202 ms (avoided 213 new dirty bufs) for db 9:0
2021-01-17 04:13:49.68 spid48s average writes per second: 15.97 writes/sec
average throughput: 0.19 MB/sec, I/O saturation: 9717, context switches 17006
2021-01-17 04:13:49.68 spid48s last target outstanding: 2, avgWriteLatency 347
2021-01-17 04:18:55.98 spid48s FlushCache: cleaned up 7186 bufs with 5041 writes in 279009 ms (avoided 35 new dirty bufs) for db 9:0
2021-01-17 04:18:55.98 spid48s average writes per second: 18.07 writes/sec
average throughput: 0.20 MB/sec, I/O saturation: 11238, context switches 20148
2021-01-17 04:18:55.98 spid48s last target outstanding: 44480, avgWriteLatency 6
2021-01-17 04:19:20.68 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 04:19:20.68 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:24:54.30 spid48s FlushCache: cleaned up 5298 bufs with 3896 writes in 156569 ms (avoided 357 new dirty bufs) for db 9:0
2021-01-17 04:24:54.30 spid48s average writes per second: 24.88 writes/sec
average throughput: 0.26 MB/sec, I/O saturation: 7158, context switches 11030
2021-01-17 04:24:54.30 spid48s last target outstanding: 44480, avgWriteLatency 118
2021-01-17 04:26:20.75 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 04:26:20.75 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:28:37.99 spid48s FlushCache: cleaned up 5359 bufs with 3974 writes in 223990 ms (avoided 187 new dirty bufs) for db 9:0
2021-01-17 04:28:37.99 spid48s average writes per second: 17.74 writes/sec
average throughput: 0.18 MB/sec, I/O saturation: 9897, context switches 16714
2021-01-17 04:28:37.99 spid48s last target outstanding: 10, avgWriteLatency 67
2021-01-17 04:30:22.85 spid48s FlushCache: cleaned up 5224 bufs with 3835 writes in 104831 ms (avoided 54 new dirty bufs) for db 9:0
2021-01-17 04:30:22.85 spid48s average writes per second: 36.58 writes/sec
average throughput: 0.38 MB/sec, I/O saturation: 4720, context switches 7457
2021-01-17 04:30:22.85 spid48s last target outstanding: 44480, avgWriteLatency 78
2021-01-17 04:32:50.97 spid48s FlushCache: cleaned up 5752 bufs with 3934 writes in 88146 ms (avoided 61 new dirty bufs) for db 9:0
2021-01-17 04:32:50.97 spid48s average writes per second: 44.63 writes/sec
average throughput: 0.50 MB/sec, I/O saturation: 4223, context switches 6608
2021-01-17 04:32:50.97 spid48s last target outstanding: 17886, avgWriteLatency 61
2021-01-17 04:33:19.78 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 04:33:19.78 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:34:29.46 spid48s FlushCache: cleaned up 6369 bufs with 4426 writes in 98441 ms (avoided 217 new dirty bufs) for db 9:0
2021-01-17 04:34:29.46 spid48s average writes per second: 44.96 writes/sec
average throughput: 0.50 MB/sec, I/O saturation: 5044, context switches 7852
2021-01-17 04:34:29.46 spid48s last target outstanding: 5300, avgWriteLatency 73
2021-01-17 04:36:39.45 spid48s FlushCache: cleaned up 7175 bufs with 4859 writes in 130012 ms (avoided 86 new dirty bufs) for db 9:0
2021-01-17 04:36:39.45 spid48s average writes per second: 37.37 writes/sec
average throughput: 0.43 MB/sec, I/O saturation: 6749, context switches 11130
2021-01-17 04:36:39.45 spid48s last target outstanding: 304, avgWriteLatency 83
2021-01-17 04:38:54.43 spid48s FlushCache: cleaned up 8536 bufs with 5584 writes in 86444 ms (avoided 132 new dirty bufs) for db 9:0
2021-01-17 04:38:54.43 spid48s average writes per second: 64.60 writes/sec
average throughput: 0.76 MB/sec, I/O saturation: 4447, context switches 7556
2021-01-17 04:38:54.43 spid48s last target outstanding: 12288, avgWriteLatency 68
2021-01-17 04:40:20.28 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 04:40:20.28 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:41:24.19 spid48s FlushCache: cleaned up 5461 bufs with 4342 writes in 144437 ms (avoided 188 new dirty bufs) for db 9:0
2021-01-17 04:41:24.19 spid48s average writes per second: 30.06 writes/sec
average throughput: 0.29 MB/sec, I/O saturation: 6615, context switches 10058
2021-01-17 04:41:24.19 spid48s last target outstanding: 44480, avgWriteLatency 6
2021-01-17 04:42:36.74 spid48s FlushCache: cleaned up 5640 bufs with 3791 writes in 71543 ms (avoided 442 new dirty bufs) for db 9:0
2021-01-17 04:42:36.74 spid48s average writes per second: 52.99 writes/sec
average throughput: 0.62 MB/sec, I/O saturation: 3889, context switches 6078
2021-01-17 04:42:36.74 spid48s last target outstanding: 11826, avgWriteLatency 70
2021-01-17 04:43:53.50 spid48s FlushCache: cleaned up 7786 bufs with 5199 writes in 61697 ms (avoided 175 new dirty bufs) for db 9:0
2021-01-17 04:43:53.50 spid48s average writes per second: 84.27 writes/sec
average throughput: 0.97 MB/sec, I/O saturation: 4106, context switches 6870
2021-01-17 04:43:53.50 spid48s last target outstanding: 1298, avgWriteLatency 59
2021-01-17 04:44:54.00 spid48s FlushCache: cleaned up 5645 bufs with 3977 writes in 60354 ms (avoided 209 new dirty bufs) for db 9:0
2021-01-17 04:44:54.01 spid48s average writes per second: 65.89 writes/sec
average throughput: 0.73 MB/sec, I/O saturation: 2774, context switches 4549
2021-01-17 04:44:54.01 spid48s last target outstanding: 44480, avgWriteLatency 0
2021-01-17 04:46:44.69 spid48s FlushCache: cleaned up 5853 bufs with 3957 writes in 70480 ms (avoided 82 new dirty bufs) for db 9:0
2021-01-17 04:46:44.69 spid48s average writes per second: 56.14 writes/sec
average throughput: 0.64 MB/sec, I/O saturation: 4079, context switches 6683
2021-01-17 04:46:44.69 spid48s last target outstanding: 44480, avgWriteLatency 18
2021-01-17 04:47:21.27 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 04:47:21.27 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:49:12.25 spid48s FlushCache: cleaned up 5470 bufs with 4266 writes in 139260 ms (avoided 228 new dirty bufs) for db 9:0
2021-01-17 04:49:12.25 spid48s average writes per second: 30.63 writes/sec
average throughput: 0.30 MB/sec, I/O saturation: 6519, context switches 9971
2021-01-17 04:49:12.25 spid48s last target outstanding: 1244, avgWriteLatency 68
2021-01-17 04:50:16.91 spid48s FlushCache: cleaned up 5384 bufs with 3972 writes in 64612 ms (avoided 103 new dirty bufs) for db 9:0
2021-01-17 04:50:16.91 spid48s average writes per second: 61.47 writes/sec
average throughput: 0.65 MB/sec, I/O saturation: 3564, context switches 6210
2021-01-17 04:50:16.91 spid48s last target outstanding: 44480, avgWriteLatency 66
2021-01-17 04:51:51.47 spid48s FlushCache: cleaned up 4738 bufs with 3496 writes in 94507 ms (avoided 198 new dirty bufs) for db 9:0
2021-01-17 04:51:51.47 spid48s average writes per second: 36.99 writes/sec
average throughput: 0.39 MB/sec, I/O saturation: 4390, context switches 6698
2021-01-17 04:51:51.47 spid48s last target outstanding: 23590, avgWriteLatency 52
2021-01-17 04:53:35.85 spid48s FlushCache: cleaned up 7009 bufs with 5136 writes in 104297 ms (avoided 115 new dirty bufs) for db 9:0
2021-01-17 04:53:35.85 spid48s average writes per second: 49.24 writes/sec
average throughput: 0.52 MB/sec, I/O saturation: 6156, context switches 9120
2021-01-17 04:53:35.85 spid48s last target outstanding: 2, avgWriteLatency 117
2021-01-17 04:54:19.55 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 04:54:19.55 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 04:56:51.27 spid48s FlushCache: cleaned up 5265 bufs with 3653 writes in 195671 ms (avoided 158 new dirty bufs) for db 9:0
2021-01-17 04:56:51.27 spid48s average writes per second: 18.67 writes/sec
average throughput: 0.21 MB/sec, I/O saturation: 8239, context switches 12468
2021-01-17 04:56:51.27 spid48s last target outstanding: 2, avgWriteLatency 120
2021-01-17 04:58:08.80 spid48s FlushCache: cleaned up 5640 bufs with 4255 writes in 77501 ms (avoided 360 new dirty bufs) for db 9:0
2021-01-17 04:58:08.80 spid48s average writes per second: 54.90 writes/sec
average throughput: 0.57 MB/sec, I/O saturation: 3512, context switches 5952
2021-01-17 04:58:08.80 spid48s last target outstanding: 44480, avgWriteLatency 77
2021-01-17 05:01:21.99 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:01:21.99 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 05:06:36.60 spid48s FlushCache: cleaned up 7370 bufs with 5268 writes in 297086 ms (avoided 75 new dirty bufs) for db 9:0
2021-01-17 05:06:36.60 spid48s average writes per second: 17.73 writes/sec
average throughput: 0.19 MB/sec, I/O saturation: 12176, context switches 21305
2021-01-17 05:06:36.60 spid48s last target outstanding: 2, avgWriteLatency 299
2021-01-17 05:08:22.61 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:08:22.61 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 05:14:39.22 spid48s FlushCache: cleaned up 4953 bufs with 3472 writes in 482946 ms (avoided 202 new dirty bufs) for db 9:0
2021-01-17 05:14:39.22 spid48s average writes per second: 7.19 writes/sec
average throughput: 0.08 MB/sec, I/O saturation: 17146, context switches 33228
2021-01-17 05:14:39.22 spid48s last target outstanding: 44480, avgWriteLatency 407
2021-01-17 05:15:20.38 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:15:20.38 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 05:22:22.01 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:22:22.01 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 05:22:40.41 spid48s FlushCache: cleaned up 4138 bufs with 2952 writes in 481487 ms (avoided 70 new dirty bufs) for db 9:0
2021-01-17 05:22:40.41 spid48s average writes per second: 6.13 writes/sec
average throughput: 0.07 MB/sec, I/O saturation: 17047, context switches 30634
2021-01-17 05:22:40.41 spid48s last target outstanding: 44480, avgWriteLatency 17
2021-01-17 05:25:32.87 spid48s FlushCache: cleaned up 4613 bufs with 2934 writes in 172717 ms (avoided 595 new dirty bufs) for db 9:0
2021-01-17 05:25:32.87 spid48s average writes per second: 16.99 writes/sec
average throughput: 0.21 MB/sec, I/O saturation: 6231, context switches 10644
2021-01-17 05:25:32.87 spid48s last target outstanding: 44480, avgWriteLatency 82
2021-01-17 05:29:20.24 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:29:20.24 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 05:36:23.54 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:36:23.54 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 05:43:20.00 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:43:20.00 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 05:46:55.56 spid48s FlushCache: cleaned up 3805 bufs with 2670 writes in 136554 ms (avoided 71 new dirty bufs) for db 9:0
2021-01-17 05:46:55.56 spid48s average writes per second: 19.55 writes/sec
average throughput: 0.21 MB/sec, I/O saturation: 4898, context switches 8435
2021-01-17 05:46:55.56 spid48s last target outstanding: 44480, avgWriteLatency 262
2021-01-17 05:50:21.78 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:50:21.78 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 05:57:21.86 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 05:57:21.86 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:04:20.57 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 06:04:20.57 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:05:57.37 spid48s FlushCache: cleaned up 5925 bufs with 4850 writes in 109817 ms (avoided 87 new dirty bufs) for db 9:0
2021-01-17 06:05:57.37 spid48s average writes per second: 44.16 writes/sec
average throughput: 0.42 MB/sec, I/O saturation: 4164, context switches 8631
2021-01-17 06:05:57.37 spid48s last target outstanding: 29136, avgWriteLatency 115
2021-01-17 06:11:20.33 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 06:11:20.33 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:18:18.48 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 06:18:18.48 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:25:19.17 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 06:25:19.17 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:27:52.39 spid48s FlushCache: cleaned up 5440 bufs with 4349 writes in 68262 ms (avoided 73 new dirty bufs) for db 9:0
2021-01-17 06:27:52.39 spid48s average writes per second: 63.71 writes/sec
average throughput: 0.62 MB/sec, I/O saturation: 4082, context switches 7166
2021-01-17 06:27:52.39 spid48s last target outstanding: 764, avgWriteLatency 92
2021-01-17 06:32:20.51 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 06:32:20.51 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:35:19.74 spid48s FlushCache: cleaned up 4498 bufs with 3285 writes in 81373 ms (avoided 346 new dirty bufs) for db 9:0
2021-01-17 06:35:19.74 spid48s average writes per second: 40.37 writes/sec
average throughput: 0.43 MB/sec, I/O saturation: 3876, context switches 7449
2021-01-17 06:35:19.74 spid48s last target outstanding: 5354, avgWriteLatency 122
2021-01-17 06:39:19.23 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 06:39:19.23 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:46:20.89 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 06:46:20.89 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:52:40.76 spid48s FlushCache: cleaned up 4077 bufs with 3141 writes in 180367 ms (avoided 336 new dirty bufs) for db 9:0
2021-01-17 06:52:40.76 spid48s average writes per second: 17.41 writes/sec
average throughput: 0.17 MB/sec, I/O saturation: 7375, context switches 11757
2021-01-17 06:52:40.76 spid48s last target outstanding: 2, avgWriteLatency 381
2021-01-17 06:53:18.88 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 06:53:18.88 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 06:56:21.46 spid48s FlushCache: cleaned up 3885 bufs with 2856 writes in 218183 ms (avoided 541 new dirty bufs) for db 9:0
2021-01-17 06:56:21.46 spid48s average writes per second: 13.09 writes/sec
average throughput: 0.14 MB/sec, I/O saturation: 7835, context switches 14953
2021-01-17 06:56:21.46 spid48s last target outstanding: 44480, avgWriteLatency 49
2021-01-17 07:00:21.89 Backup Error: 3041, Severity: 16, State: 1.
2021-01-17 07:00:21.89 Backup BACKUP failed to complete the command BACKUP LOG DB_XYZ. Check the backup application log for detailed messages.
2021-01-17 07:04:51.00 spid48s FlushCache: cleaned up 4268 bufs with 2767 writes in 96321 ms (avoided 46 new dirty bufs) for db 9:0
2021-01-17 07:04:51.00 spid48s average writes per second: 28.73 writes/sec
average throughput: 0.34 MB/sec, I/O saturation: 3477, context switches 8532
2021-01-17 07:04:51.00 spid48s last target outstanding: 15694, avgWriteLatency 405
2021-01-

Answer 4

spid440s average writes per second: 21.11 writes/sec

average throughput: 0.58 MB/sec, I/O saturation: 5227, context switches 8620

The whole errorlog is filled with above message.

5627 bufs with 4046 writes in 69078 ms
6251 bufs with 4667 writes in 285062

If you note above to flush 5627 Buffer which is 5267*8= 42 MB of data SQL Server tool 69 seconds and in 2nd case for almost same MB of data it tool 284 sec. If you ask me this is not a good number. This means lot of checkpoint operations generated and your storage is not able to keep up with the lot of I/O requests generated. You need to seriously look into the disk of this secondary replica. Not only disk but the whole storage susbsystem. A similar thread here. Normally to avoid such scenario it is suggested to enable indirect checkpoint.

This slow subsystem is affecting the REDO RATE of the secondary replica and it seems like it always is busy redoing lot of transactions. This is why it is lagging and when you are starting a backup, which fires checkpoint, it is getting blocked. But still I am not sure what your redo is doing actually to get blocked by a backup.

Log backup for database "DB_XYZ" on a secondary replica failed because the last backup LSN (0x001e792b:0005a228:0001) from the primary database is greater than the current local redo LSN (0x001e792b:0005a227:0001).

Again regarding this message your redo queue is too large.

What is output of below, does this always return a value for db startup.

SELECT db_name(database_id) as DBName, session_id FROM sys.dm_exec_requests WHERE command = 'DB STARTUP'

Also check the redo queue in SSMS GUI AG dashboard. The whole issue is because of secondary replica is not able to redo records at the rate at which primary is producing. The reason for which seems like storage and underlying component.

Answer 5

Hi Shashank,

Thanks for this information,

I fetched output of query

SELECT db_name(database_id) as DBName, session_id FROM sys.dm_exec_requests WHERE command = 'DB STARTUP'

It is always showing output, i have changed the DB name for privacy purpose