Hi All,
We are seeing below messages in ERRORLOG. Does it indicate any pressure or just informational messages? Anything needs to be looked into?
2022-04-16 00:01:05.360 spid21s FlushCache: cleaned up 134823 bufs with 18733 writes in 62497 ms (avoided 3639 new dirty bufs) for db 27:0
2022-04-16 00:01:05.360 spid21s average writes per second: 299.74 writes/sec
average throughput: 16.85 MB/sec, I/O saturation: 2786, context switches 5773
2022-04-16 00:01:05.360 spid21s last target outstanding: 44640, avgWriteLatency 67
2022-04-16 00:10:54.210 spid21s FlushCache: cleaned up 9973 bufs with 6482 writes in 513882 ms (avoided 708941 new dirty bufs) for db 27:0
2022-04-16 00:10:54.210 spid21s average writes per second: 12.61 writes/sec
average throughput: 0.15 MB/sec, I/O saturation: 16059, context switches 30318
2022-04-16 00:10:54.210 spid21s last target outstanding: 44640, avgWriteLatency 302
2022-04-16 00:12:57.190 Server The Service Broker endpoint is in disabled or stopped state.
2022-04-16 00:20:45.590 spid33s FlushCache: cleaned up 3565 bufs with 3238 writes in 116840 ms (avoided 197 new dirty bufs) for db 7:0
2022-04-16 00:20:45.590 spid33s average writes per second: 27.71 writes/sec
average throughput: 0.23 MB/sec, I/O saturation: 4966, context switches 12981
2022-04-16 00:20:45.590 spid33s last target outstanding: 54, avgWriteLatency 89
2022-04-16 00:21:28.560 spid21s Buffer Pool scan took 570 seconds: database ID 27, command 'CHECKPOINT', operation 'FlushCache', scanned buffers 21741623, total iterated buffers 25734589, wait time 509060 ms. See 'https://go.microsoft.com/fwlink/?linkid=2132602' for more information.
2022-04-16 00:21:29.280 spid21s FlushCache: cleaned up 571882 bufs with 246260 writes in 571594 ms (avoided 750856 new dirty bufs) for db 27:0
2022-04-16 00:21:29.280 spid21s average writes per second: 430.83 writes/sec
average throughput: 7.81 MB/sec, I/O saturation: 15886, context switches 51903
2022-04-16 00:21:29.280 spid21s last target outstanding: 44640, avgWriteLatency 326
2022-04-16 00:27:58.740 Server The Service Broker endpoint is in disabled or stopped state.
2022-04-16 00:32:57.920 spid21s Buffer Pool scan took 627 seconds: database ID 27, command 'CHECKPOINT', operation 'FlushCache', scanned buffers 21379858, total iterated buffers 25734589, wait time 577842 ms. See 'https://go.microsoft.com/fwlink/?linkid=2132602' for more information.
2022-04-16 00:32:58.470 spid21s FlushCache: cleaned up 510777 bufs with 212124 writes in 627595 ms (avoided 547632 new dirty bufs) for db 27:0
2022-04-16 00:32:58.470 spid21s average writes per second: 338.00 writes/sec
average throughput: 6.36 MB/sec, I/O saturation: 16406, context switches 47004
2022-04-16 00:32:58.470 spid21s last target outstanding: 44640, avgWriteLatency 239
2022-04-16 00:33:12.540 spid224 BackupToUrl process initiated with PID: 22920, for database name []
2022-04-16 00:34:06.480 spid262 BackupToUrl process initiated with PID: 10636, for database name []
2022-04-16 00:34:07.980 Backup Log was backed up. Database: db1, creation date(time): 2021/02/21(20:42:55), first LSN: 31768:242096:1, last LSN: 31768:251078:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows.net/sq
2022-04-16 00:34:09.150 spid262 BackupToUrl process initiated with PID: 20620, for database name []
2022-04-16 00:34:12.280 spid262 BackupToUrl process initiated with PID: 5960, for database name []
2022-04-16 00:34:13.500 Backup Log was backed up. Database: db2, creation date(time): 2021/02/21(21:11:12), first LSN: 197:116497:1, last LSN: 197:116544:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows.net/
2022-04-16 00:34:13.680 spid262 BackupToUrl process initiated with PID: 7044, for database name []
2022-04-16 00:36:54.110 spid262 BackupToUrl process initiated with PID: 20856, for database name []
2022-04-16 00:36:55.300 Backup Log was backed up. Database: db3, creation date(time): 2021/02/21(20:42:55), first LSN: 32374:163256:1, last LSN: 32374:163957:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows
2022-04-16 00:36:55.880 spid262 BackupToUrl process initiated with PID: 22992, for database name []
2022-04-16 00:37:20.940 spid262 BackupToUrl process initiated with PID: 22116, for database name [DNB_MDM_PROXY]
2022-04-16 00:37:22.190 Backup Log was backed up. Database: db4, creation date(time): 2021/02/21(20:42:55), first LSN: 22253:3006:1, last LSN: 22253:3015:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows.n
2022-04-16 00:37:22.470 spid262 BackupToUrl process initiated with PID: 21492, for database name []
2022-04-16 00:39:03.140 Backup Log was backed up. Database: db5, creation date(time): 2021/02/21(20:42:55), first LSN: 5609206:1074682:1, last LSN: 5609236:889737:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.window
2022-04-16 00:39:03.670 spid224 BackupToUrl process initiated with PID: 10308, for database name []
2022-04-16 00:41:23.090 spid262 FlushCache: cleaned up 4607 bufs with 3805 writes in 115046 ms (avoided 0 new dirty bufs) for db 24:0
2022-04-16 00:41:23.090 spid262 average writes per second: 33.07 writes/sec
average throughput: 0.30 MB/sec, I/O saturation: 5817, context switches 9142
2022-04-16 00:41:23.090 spid262 last target outstanding: 14, avgWriteLatency 63
2022-04-16 00:41:23.150 spid262 BackupToUrl process initiated with PID: 21648, for database name []
2022-04-16 00:41:24.740 Backup Log was backed up. Database: db6, creation date(time): 2021/02/21(20:42:55), first LSN: 381088:141684:1, last LSN: 381088:159078:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows.n
2022-04-16 00:41:24.830 spid262 BackupToUrl process initiated with PID: 21752, for database name []
2022-04-16 00:41:27.100 spid262 BackupToUrl process initiated with PID: 24612, for database name []
2022-04-16 00:41:27.930 Backup Log was backed up. Database: db7, creation date(time): 2021/02/21(20:42:55), first LSN: 43:203306:1, last LSN: 43:203312:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows.ne
2022-04-16 00:41:28.020 spid262 BackupToUrl process initiated with PID: 25024, for database name []
2022-04-16 00:41:32.890 spid262 BackupToUrl process initiated with PID: 19176, for database name []
2022-04-16 00:41:33.690 Backup Log was backed up. Database: db8, creation date(time): 2021/02/21(20:42:55), first LSN: 1440:85:1, last LSN: 1440:94:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows.net/s
2022-04-16 00:41:33.990 spid262 BackupToUrl process initiated with PID: 22304, for database name []
2022-04-16 00:41:41.700 spid262 BackupToUrl process initiated with PID: 23420, for database name []
2022-04-16 00:41:42.800 Backup Log was backed up. Database: db9, creation date(time): 2021/02/21(20:42:55), first LSN: 73:236326:1, last LSN: 73:236609:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows.
2022-04-16 00:41:43.370 spid262 BackupToUrl process initiated with PID: 25376, for database name []
2022-04-16 00:41:53.010 spid262 BackupToUrl process initiated with PID: 18796, for database name []
2022-04-16 00:41:54.080 Backup Log was backed up. Database: db10, creation date(time): 2021/02/21(20:42:55), first LSN: 63:228334:1, last LSN: 63:228622:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows
2022-04-16 00:41:54.190 spid262 BackupToUrl process initiated with PID: 23800, for database name []
2022-04-16 00:42:04.360 spid262 BackupToUrl process initiated with PID: 18828, for database name []
2022-04-16 00:42:05.330 Backup Log was backed up. Database: db11, creation date(time): 2021/02/21(20:42:55), first LSN: 7802:285402:1, last LSN: 7802:296524:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windo
2022-04-16 00:42:05.540 spid262 BackupToUrl process initiated with PID: 25108, for database name []
2022-04-16 00:42:08.240 spid262 BackupToUrl process initiated with PID: 17296, for database name []
2022-04-16 00:42:09.440 Backup Log was backed up. Database: db12, creation date(time): 2021/02/21(20:42:55), first LSN: 496:73042:1, last LSN: 496:73048:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://prodbackups.blob.core.windows.
2022-04-16 00:42:09.700 spid262 BackupToUrl process initiated with PID: 17500, for database name []
2022-04-16 00:43:00.400 Server The Service Broker endpoint is in disabled or stopped state.
2022-04-16 00:43:41.830 spid21s Buffer Pool scan took 577 seconds: database ID 27, command 'CHECKPOINT', operation 'FlushCache', scanned buffers 21934758, total iterated buffers 25734589, wait time 524850 ms. See 'https://go.microsoft.com/fwlink/?linkid=2132602' for more information.
2022-04-16 00:43:42.650 spid21s FlushCache: cleaned up 337128 bufs with 228013 writes in 577850 ms (avoided 823823 new dirty bufs) for db 27:0
2022-04-16 00:43:42.650 spid21s average writes per second: 394.59 writes/sec
average throughput: 4.56 MB/sec, I/O saturation: 16066, context switches 33990
2022-04-16 00:43:42.650 spid21s last target outstanding: 44640, avgWriteLatency 0
2022-04-16 00:45:19.000 spid21s FlushCache: cleaned up 20854 bufs with 916 writes in 95992 ms (avoided 35165 new dirty bufs) for db 24:0
2022-04-16 00:45:19.000 spid21s average writes per second: 9.54 writes/sec
average throughput: 1.69 MB/sec, I/O saturation: 3270, context switches 6262
2022-04-16 00:45:19.000 spid21s last target outstanding: 2, avgWriteLatency 77
2022-04-16 00:49:06.430 spid344s FlushCache: cleaned up 3738 bufs with 3387 writes in 85782 ms (avoided 506 new dirty bufs) for db 7:0
2022-04-16 00:49:06.430 spid344s average writes per second: 39.48 writes/sec
average throughput: 0.34 MB/sec, I/O saturation: 4070, context switches 5794
2022-04-16 00:49:06.430 spid344s last target outstanding: 2572, avgWriteLatency 63
2022-04-16 00:50:30.950 spid21s FlushCache: cleaned up 62100 bufs with 2699 writes in 251831 ms (avoided 81320 new dirty bufs) for db 24:0
2022-04-16 00:50:30.950 spid21s average writes per second: 10.72 writes/sec
average throughput: 1.93 MB/sec, I/O saturation: 8797, context switches 25493
2022-04-16 00:50:30.950 spid21s last target outstanding: 2, avgWriteLatency 108
2022-04-16 00:51:25.760 spid262 BackupToUrl process initiated with PID: 3344, for database name []
2022-04-16 00:51:27.040 Backup Log was backed up. Database: db13, creation date(time): 2021/02/21(20:42:55), first LSN: 7272:9390329:1
Regards,
Sam
Unless you have a process that requires that successful backups be logged in the SQL Server Error Log, I'd turn those off. Here's just one article on how to do that that shows a both a way to test it and a way to make it permanent as a startup parameter for the server. And, yes... I have this trace flag enabled on all my servers because I don't depend on my error log to tell me if my backups are running correctly. This trace flag will NOT prevent backup messages where the backups have an issue. It's the best of both worlds and I don't understand why they don't have the trace flag enabled by default, but whatever.
There is a way to do it by modifying the registry through T-SQL but that can be quite dangerous if you don't do it precisely right and so I'm not going to publish a link for that because I don't want to be responsible for any mishaps. 😉
Also, if you setup the startup parameter (and you should if that's what you want to happen), you do NOT need to restart the server for it to take immediate effect server wide. You can just turn it on globally using the DBCC TRACEON method shown in the article at the link above. If the trace flag has been included as a startup parameter, then the next time it reboots, no such manual action will be required.
As for the rest of the messages, here's an old (first published in June 2012) but "recently" (January 2019) updated article by Bob Dorr (Principal SQL Server Escalation Engineer at Microsoft) that explains a good portion of your other messages.
As a bit of a sidebar, and easier way to convert the "buf" counts to MB is to simply divide them by 128 because there are precisely 128 - 8KB pages per megabyte.
Such flushes (the name is a bit scary) but they're "normal" as CHECKPOINTs occur. I say "normal" but if they take a long time or are frequent you "could" have a problem. I can only say "It Depends" on what the code is actually doing (the "WorkLoad"). Sometimes, it can be an indication of some pretty crappy code doing a lot of unnecessary things but it can also be just an advisory that you have some big stuff running.
Again, read the article for a better understanding.
--Jeff Moden
Change is inevitable... Change for the better is not.
Viewing 2 posts - 1 through 1 (of 1 total)
You must be logged in to reply to this topic. Login to reply