[SQL Server]性能排错之系统等待：WRITELOG

水深无声 2022-09-27 00:29 162阅读 0赞

# WRITELOG #

## Definition ##

When a SQL Server session waits on the WRITELOG wait type, it is waiting to write the contents of the log cache to disk where the transaction log is stored.

To explain the process in more detail, assume a session starts a transaction that will perform several INSERT statements. While the data is being inserted, two actions occur:

1.  The data page in the buffer cache is updated with the new data.
2.  Data is written to the log cache which is a segment of memory used to record data that will be used for rolling back the transaction or be written to the log file.

This process continues until the transaction has completed (committed) at which time the data in the log cache is immediately written to the physical log file. When SQL Server is in the act of flushing the log cache to disk, the session will wait on the WRITELOG wait type.

## Getting More Information ##

If sessions are consistently waiting on the WRITELOG wait type, review the following Perfmon data for signs of disk bottlenecks where the transaction log is stored:

1.  PhysicalDisk Object
    
     *  Avg. Disk Queue Length – the average number of IO requests that were queued. If this is consistently greater than one, this could indicate a disk bottleneck.
     *  Avg. Disk sec/Read and Avg. Disk sec/Write – if either of these are higher than 15-20 ms, this could indicate the transaction log is stored on a slow device
2.  SQLServer: Buffer Manager
    
     *  Checkpoint pages/sec – number of pages flushed by checkpoint operations that require all dirty buffers to be written to disk

Using Ignite for SQL Server or other tools, also determine the top SQL statements waiting on the WRITELOG event. If many statements are found waiting, this could indicate that one of the above items is the problem. If only a few SQL statements are found waiting on WRITELOG, it could indicate an inefficient use of transactions (discussed with examples below).

## Fixing the Problem ##

Disk Subsystem Performance - In much of the documentation about the WRITELOG wait type, it seems the problem is often mischaracterized as solely a disk subsystem issue. In the cases where disks are the problem, counters from the PhysicalDisk Object in Perfmon will be high and fixes often include:

1.  Adding additional IO bandwidth to the disk subsystem where the transaction log is stored.
2.  Moving non-transaction log IO from the disk.
3.  Moving the transaction log to a less busy disk.
4.  Reducing the size of the transaction log has also helped in some cases.

**Committing Data Too Often -** In many cases that we see during performance consultations, excessive waits on the WRITELOG wait type can be caused by an over zealous usage of transactions, i.e. committing data too often. To illustrate this problem, consider the following code examples:

**Example 1:** The following code took 418 seconds to execute and waited 410 seconds on the WRITELOG wait type. Note how the COMMIT statement is located inside the loop and executed 100,000 times.

<table style="margin-top: 8px; width: 525px; margin-bottom: 8px;"> 
 <tbody> 
  <tr> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
  </tr> 
  <tr> 
   <td>&nbsp;</td> 
   <td> <p>DECLARE @i INT<br>SET @i = 1<br>WHILE @i &lt; 100000<br>&nbsp;&nbsp;&nbsp;&nbsp; BEGIN<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; BEGIN TRANSACTION<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;INSERT INTO [splendidCRM].[dbo].[product]<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; ([productid],<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [category],<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [name],<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [descn])<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;VALUES (@i,<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; floor(@i / 1000),<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 'PROD' + REPLACE(str(@i),' ',''),<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 'PROD' + REPLACE(str(@i),' ',''))<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;SET @i = @i + 1<br>&nbsp;&nbsp;&nbsp;&nbsp;COMMIT<br>END </p> </td> 
   <td>&nbsp;</td> 
  </tr> 
  <tr> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
  </tr> 
 </tbody> 
</table>

**Example 2:** The following code, which also inserts 100,000 rows as above, took 3 seconds and waited less than a second on the WRITELOG wait type. Note how the COMMIT statement is located outside the loop and only executed once.

<table style="margin-top: 8px; width: 525px; margin-bottom: 8px;"> 
 <tbody> 
  <tr> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
  </tr> 
  <tr> 
   <td>&nbsp;</td> 
   <td> <p>DECLARE @i INT<br>SET @i = 1<br>BEGIN TRANSACTION<br>WHILE @i &lt; 100000<br>&nbsp;&nbsp;&nbsp;&nbsp;BEGIN<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; INSERT INTO [splendidCRM].[dbo].[product]<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; ([productid],<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [category],<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [name],<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [descn])<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;VALUES (@i,<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; floor(@i / 1000),<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 'PROD' + REPLACE(str(@i),' ',''),<br>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 'PROD' + REPLACE(str(@i),' ',''))<br>&nbsp;&nbsp;&nbsp;&nbsp; SET @i = @i + 1<br>&nbsp;&nbsp;&nbsp;&nbsp; END<br>COMMIT</p> </td> 
   <td>&nbsp;</td> 
  </tr> 
  <tr> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
  </tr> 
 </tbody> 
</table>

## Conclusion ##

When sessions are found waiting on the WRITELOG wait type, it is imperative to perform a full analysis of the situation. This analysis should include review of disk performance data but also a review of all SQL statements found waiting on WRITELOG. Only then can you be assured you are solving the correct problem and not just adding expensive hardware that will not fix the root cause.