What is WRITELOG waittype and how to troubleshoot and fix this wait in SQL Server

 

 

 

 

 

 

What is WRITELOG waittype and how to troubleshoot and fix this wait in SQL Server

Rate This
  • Comments 3

What does WRITELOG waittype mean?

WRITELOG waits represent the time waiting on a LOG I/O to complete. Common operations that cause log flushes are checkpoints and transaction commits.

Transaction commits can be whenever you run a COMMIT TRAN (incase of Explicit transaction) or whenever SQL Server commits the transaction on behalf of you (Auto commit)

Before we continue further, please read an Excellent article from SQL Customer Advisory Team at http://sqlcat.com/technicalnotes/archive/2008/12/09/diagnosing-transaction-log-performance-issues-and-limits-of-the-log-manager.aspx which talks about a throttle limit called "Outstanding I/O limit" and "Outstanding log I/O Limit".  So this is another condition where you will notice WRITELOG wait type when outstanding I/O limit is reached.

Given below are the conditions (but not limited to) when a log block will be flushed to disk:

1. COMMIT XSN (or ABORT XSN)

2. CHECKPOINT

3. LOG Block is full

More information about #3 LOG BLOCK:

You might be knowing that LOG entries are first written serially to in-memory structure called Log block and once the buffer is full or any of the transaction COMMITS, then the entire log block is flushed to disk. It is important to note that multiple active transactions can be interleaved in the log buffer, and if any one transaction commits, the buffer memory is written to the transaction log file by the log writer. No need to worry about what happens to data integrity when multiple transactions interleave at same time because SQL Server implements synchronization objects like spinlocks, mutex to control the access to log buffer.

The size of this log block can be between 512 bytes and 64 kilobytes. For more information about the size limit of different types of I/O performed by SQL Server, visit http://blogs.msdn.com/b/sqlcat/archive/2005/11/17/493944.aspx

To monitor your database log buffer flush and it's size, refer the the perfmon counters given below:

SQLServer: Database object counter
Displays
Log Bytes Per Flush Number of bytes in the log buffer when the buffer is flushed.
Log Flushes/sec Number of log flushes per second.
Log Flush Wait Time Total wait time (milliseconds) to flush the log.
Log Flush Waits/sec Number of commits per second that are waiting on log flush.

I want to share one interesting observation which might help you to choose IMPLICIT or EXPLICIT Transaction:

During a troubleshooting scenario where INSERT'ing 60000 records to a 2 column sample table took 8 minutes on a specific server while the same operation takes ,< 20 seconds in two other identical server. I was in a position to proove that it is a Disk problem and not a configuration issue within SQL Server. This insert was running in a WHILE loop without any EXPLICIT Transaction.

When I looked into his Wait Stats (sys.dm_os_wait_stats), WRITELOG was the top wait type in terms of total wait time.

I explained about the WRITELOG wait type and conditions when LOG Blocks will be flushed to disk to Cx. (These details are available in SQLCAT blog given above)

To show a demo about difference between Autocommit and EXPLICIT transaction which changes the behavior of Log Flush, changed his code:

Before:

WHILE @i < 60000

Begin

INSERT INTO table values (1,'Name')

End

After:

BEGIN TRAN

WHILE @i < 60000

Begin

INSERT INTO table values (1,'Name')

End

COMMIT TRAN

Second batch with EXPLICIT transaction completed in just 2 seconds (compared to 8 mins when IMPLICIT transaction) in the same problematic environment. The reason is because every IMPLICIT COMMIT is flushing the transaction log buffer to disk but in the case of EXPLICIT XSN, log buffers are flushed only when they are full (ofcourse in this test environment no other requests were running so they don't cause log buffer flush).

Also we knew that the comparison might be skewed if there is a autogrowth happening in the background so we ensured that Initial Size for both MDF and LDF was set before the testing started.

There is another difference in the case of EXPLICIT XSN which we noticed:

1. In IMPLICIT XSN, CHECKPOINT will run quite often and will complete soon because the amount of dirty buffers will be less when it runs so often

2. In EXPLICIT XSN, CHECKPOINT will run after a longer interval and it will run for longer duration because it has more work to do because of huge backlog of dirty buffers

Then it made sense to the customer that instead of 60,000 LOG I/O, we just be sending <10 LOG I/O to disk which makes transaction to complete fast.

DMV sys.dm_tran_database_transactions helped us to understand WRITELOG wait time for every transaction w.r.t  the transaction begin time. Also sys.dm_io_pending_io_requests helped us to understand the outstanding I/O and whether the I/O is still pending from Disk subsytem and how long it is pending.

So to summarize,

If you see WRITELOG wait type, before adding more disk, check how frequently you transactions commits and how good is your disk response time.

Feel free to post your comments if you have any questions or if you need more information.

Further Reads:

http://blogs.msdn.com/b/psssql/archive/2011/01/07/discussion-about-sql-server-i-o.aspx

http://msdn.microsoft.com/en-us/library/cc917726.aspx

http://blogs.msdn.com/cfs-filesystemfile.ashx/__key/CommunityServer-Components-PostAttachments/00-09-98-45-35/Microsoft-SQL-Server-IO-Internals.pptx

Sakthivel Chidambaram, SQL Server Support

Leave a Comment
  • Please add 5 and 5 and type the answer here:
  • Post
  • @SQLCAN: Great article, thanks; Ping back from sqlcan.wordpress.com/.../how-to-troubleshoot-writelog-wait-type.

  • "but in the case of EXPLICIT XSN, log buffers are flushed only when they are full (ofcourse in this test environment no other requests were running so they don't cause log buffer flush). "

    only when they are full ?Do you means even there was a checkpoint happened ,the log buffers are still not be flushed ? just like the following code .

    After:

    BEGIN TRAN

    WHILE @i < 60000

    Begin

    SET @i=@i+1;

    IF @i=10

    BEGIN

    CHECKPOINT

    END

    INSERT INTO table values (1,'Name')

    End

    COMMIT TRAN

  • Hi Jacky,

    You got it right, CHECKPOINT does check whether LSN for all the dirty pages which it is going to flush are pushed to LDF and if not, will initiate a flush of log buffers.

Page 1 of 1 (3 items)