Share via

Seeing I/O messages in errorlog. Does it indicate any pressure ?

Sam 1,476 Reputation points
2022-04-16T13:36:57.39+00:00

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

SQL Server
SQL Server
A family of Microsoft relational database management and analysis systems for e-commerce, line-of-business, and data warehousing solutions.
13,361 questions
Transact-SQL
Transact-SQL
A Microsoft extension to the ANSI SQL language that includes procedural programming, local variables, and various support functions.
4,601 questions

1 answer

Sort by: Most helpful
Most helpful Newest Oldest
  1. YufeiShao-msft 7,091 Reputation points
    2022-04-18T08:07:24.72+00:00

    Hi @Sam ,

    This is the error message that appears when scanning the SQL Server buffer pool might take a long time to finish on large-memory computers.
    Operations that trigger a buffer pool scan may run slowly on large-memory computers
    there is currently no way to eliminate this problem, if you want to finish quickly, you can:
    Run CHECKPOINT on each database
    After all the database on the server have been checkponits, reduce the size of the buffer pool
    Perform the operation that results in a buffer pool scan

    -------------

    If the answer is the right solution, please click "Accept Answer" and kindly upvote it. If you have extra questions about this answer, please click "Comment".

    Note: Please follow the steps in our documentation to enable e-mail notifications if you want to receive the related email notification for this thread.