Hi , In my company training one of my colleague asked me is it possible to see what a checkpoint operation is doing ?
There are some trace flags that allow you to watch a checkpoint operation is doing.
- 3502: writes to the error log when a checkpoint starts and finishes
- 3504: writes to the error log information about what is written to disk
You can enable these trace flags by using DBCC TRACE ON
DBCC TRACE ON (3502,3504,-1)
After Enabling trace flags run any DML Transaction with a checkpoint command and you can see in ERROR LOG. Below Iam posting some information after running a transaction by using checkpoint operation.
2010-10-02 01:32:00.03 spid11s Ckpt dbid 1 started (0)
2010-10-02 01:32:00.06 spid11s About to log Checkpoint begin.
2010-10-02 01:32:00.09 spid11s Ckpt dbid 1 phase 1 ended (0)
2010-10-02 01:32:00.10 spid11s FlushCache: cleaned up 6 bufs with 6 writes in 1 ms (avoided 0 new dirty bufs)
2010-10-02 01:32:00.10 spid11s average throughput: 46.88 MB/sec, I/O saturation: 5
2010-10-02 01:32:00.10 spid11s last target outstanding: 2
2010-10-02 01:32:00.10 spid11s About to log Checkpoint end.
2010-10-02 01:32:00.20 spid11s Ckpt dbid 1 complete
2010-10-02 01:32:01.62 spid11s Ckpt dbid 1 started (0)
2010-10-02 01:32:01.62 spid11s About to log Checkpoint begin.
2010-10-02 01:32:01.63 spid11s Ckpt dbid 1 phase 1 ended (0)
2010-10-02 01:32:01.63 spid11s FlushCache: cleaned up 4 bufs with 4 writes in 1 ms (avoided 0 new dirty bufs)
2010-10-02 01:32:01.63 spid11s average throughput: 31.25 MB/sec, I/O saturation: 2
2010-10-02 01:32:01.63 spid11s last target outstanding: 2
2010-10-02 01:32:01.63 spid11s About to log Checkpoint end.
2010-10-02 01:32:01.66 spid11s Ckpt dbid 1 complete
2010-10-02 01:32:01.94 spid11s Ckpt dbid 8 started (8)
2010-10-02 01:32:01.94 spid11s About to log Checkpoint begin.
2010-10-02 01:32:01.95 spid11s Ckpt dbid 8 phase 1 ended (8)
2010-10-02 01:32:02.23 spid11s FlushCache: cleaned up 1224 bufs with 64 writes in 281 ms (avoided 57 new dirty bufs)
2010-10-02 01:32:02.23 spid11s average throughput: 34.03 MB/sec, I/O saturation: 70
2010-10-02 01:32:02.23 spid11s last target outstanding: 2
2010-10-02 01:32:02.23 spid11s About to log Checkpoint end.
2010-10-02 01:32:02.23 spid11s Ckpt dbid 8 complete
2010-10-02 01:32:02.23 spid55 Ckpt dbid 8 started (8)
2010-10-02 01:32:02.23 spid55 About to log Checkpoint begin.
2010-10-02 01:32:02.23 spid55 Ckpt dbid 8 phase 1 ended (8)
2010-10-02 01:32:02.27 spid55 FlushCache: cleaned up 87 bufs with 8 writes in 31 ms (avoided 0 new dirty bufs)
2010-10-02 01:32:02.27 spid55 average throughput: 21.93 MB/sec, I/O saturation: 9
2010-10-02 01:32:02.27 spid55 last target outstanding: 2
2010-10-02 01:32:02.27 spid55 About to log Checkpoint end.
2010-10-02 01:32:02.27 spid55 Ckpt dbid 8 complete
2010-10-02 01:36:32.94 spid11s Ckpt dbid 8 started (0)
2010-10-02 01:36:32.94 spid11s About to log Checkpoint begin.
2010-10-02 01:36:32.94 spid11s Ckpt dbid 8 phase 1 ended (0)
2010-10-02 01:36:33.20 spid11s FlushCache: cleaned up 1288 bufs with 54 writes in 250 ms (avoided 33 new dirty bufs)
2010-10-02 01:36:33.20 spid11s average throughput: 40.25 MB/sec, I/O saturation: 61
2010-10-02 01:36:33.20 spid11s last target outstanding: 2
2010-10-02 01:36:33.20 spid11s About to log Checkpoint end.
2010-10-02 01:36:33.20 spid11s Ckpt dbid 8 complete
2010-10-02 01:48:00.17 spid11s Ckpt dbid 4 started (0)
2010-10-02 01:48:00.17 spid11s About to log Checkpoint begin.
2010-10-02 01:48:00.18 spid11s Ckpt dbid 4 phase 1 ended (0)
2010-10-02 01:48:00.18 spid11s FlushCache: cleaned up 20 bufs with 18 writes in 1 ms (avoided 0 new dirty bufs)
2010-10-02 01:48:00.18 spid11s average throughput: 156.25 MB/sec, I/O saturation: 15
2010-10-02 01:48:00.18 spid11s last target outstanding: 2
2010-10-02 01:48:00.18 spid11s About to log Checkpoint end.
2010-10-02 01:48:00.19 spid11s Ckpt dbid 4 complete
2010-10-02 02:00:23.77 spid54 DBCC TRACEON 3406, server process ID (SPID) 54. This is an informational message only; no user action is required.
2010-10-02 02:10:00.75 spid11s Ckpt dbid 4 started (0)
2010-10-02 02:10:00.75 spid11s About to log Checkpoint begin.
2010-10-02 02:10:00.75 spid11s Ckpt dbid 4 phase 1 ended (0)
2010-10-02 02:10:00.76 spid11s FlushCache: cleaned up 20 bufs with 19 writes in 15 ms (avoided 0 new dirty bufs)
2010-10-02 02:10:00.76 spid11s average throughput: 10.42 MB/sec, I/O saturation: 18
2010-10-02 02:10:00.76 spid11s last target outstanding: 2
2010-10-02 02:10:00.76 spid11s About to log Checkpoint end.
2010-10-02 02:10:00.76 spid11s Ckpt dbid 4 complete