3

I have been using DBCC Traceon (3502, 3504, 3605, -1) because it was recommended in a blog for discovering performance issues related to I/O. I'm running MS SQL Server 2008 R2 SP1

Results in my SQL Log file look something like this (numbers fudged a little):

about to log checkpoint end

last target outstanding 2, avgWriteLatency 40ms

Average Throughput: 0.67 MB/sec, I/O Saturation: 79, Context Switches 201

FlushCache: cleaned up 125 Bufs with 69 writes, in 1447ms (avoided 0 new dirty bufs)

Ckpt dbid 9 phase 1 ended (8)

about to log checkpoint begin.

I don't really know how to read this, or break it down in a way that I get get anything truly meaningful out of it.

What does 'last target outstanding mean?"

Does the average write latency mean the overhead time it takes per write? or the time between writes? 40ms seems high, the physical drive is a 1TB, and it's RAID5 configured.

What is I/O saturation?

What does it have to do with the Context Switches. I'm assuming Context switches have something to do with multi-tasking. Changing between jobs/writes.

FlushCache. I realize this has to do with clearing out the cache. What are the Bufs? Are these pages of data that needed to be written? What are the dirty Bufs? Why would they be avoided?

A detailed breakdown would be appreciated.

Improve this question

2 Answers 2

Reset to default
6

The trace flags that you have turned on will tell you what a checkpoint is doing behind the scenes.

  • 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
  • 3605: allows trace prints to go to the error log

Refer to Paul Randall's blog post for more details on the above. Also, Fine Tuning for Optimal Performance has an excellent info - especially In Search of Spikes section.

Some really internals reading :

  1. How It Works: When is the FlushCache message added to SQL Server Error Log?
  2. How It Works: SQL Server Checkpoint (FlushCache) Outstanding I/O Target
  3. SQL Server checkpoint problems

Instead of concentrating directly on checkpoint behaviour, I would suggest you to look at DMVs and Perfmon (disk related) -

  1. sys.dm_io_virtual_file_stats
  2. Physical Disk Object: Avg. Disk Queue Length
  3. Avg. Disk Sec/Read
  4. Avg. Disk Sec/Write
  5. Physical Disk: %Disk Time
  6. Avg. Disk Reads/Sec
  7. Avg. Disk Writes/Sec

You can refer to Investigating I/O bottlenecks

Improve this answer
3
  • This is great information. I've read some of the articles linked as I was further investigating the issues. Very handy, thank you for the research.
    – meltdownmonk
    Commented Jun 21, 2013 at 17:28
  • I have been concentrating on Checkpoint behaviour but also on the perfmon physicaldisk and logical disk counters. % Disk time is high, but the avg disk reads and writes/sec aren't particularly alarming. The disk % write activity is very consistently going above 100% and averages around 70%.
    – meltdownmonk
    Commented Jun 21, 2013 at 18:05
  • You have to basically concentrate on Avg. Disk sec/Read Avg. Disk sec/Write and Avg. Disk sec/Transfer. what do you see those values ?
    – Kin Shah
    Commented Jun 21, 2013 at 18:28
0

My answer:

Bufs, are SQL Pages, they are 8KB Pages, 8 Pages per Extant (a group of pages) which is 64KB, and is the smallest block in an SQL Database File (but not the Log file, the log file can use the Physical discs smallest Block size, usually 512 Bytes)

So, in my own Example, the 125 Bufs, were 125 Pages, almost 1MB of Data spread over 69 writes. It took a total of 1447 to write that 125 pages (basically 1447 seconds to write 125x8KB) and if you multiple the time it took by the Throughput you'll get the size of data that was written, and it's very close to the 125.

The Dirty Bufs are just dirty pages, which are pages that are changed but haven't had those changes reflected anywhere else except the Cache.

I still don't understand I/O saturation.

The write latency average is the time it took to complete the checkpoint (1447) divided by the number of writes. In this case it should be 20.97 ms. So the numbers I used for the example are incorrect; They are not from the same log entry.

It does look like this Server is performing slowly based on the stats.

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.