Sql-server – high writelog wait on OLTP system and fast SSD storage, log flush is slow

performanceslow-logsql serversql-server-2016transaction-log

we have recently upgraded from SQL server 2008 to new servers and upgraded to sql server 2016 (SP1 CU3)

new servers hardware hp proliant 580G8 , 4 socket intel xeon E7 processor, total 60 cores, 640GB ram, 8 intel SSD S3700 Raid 10, local

the environment is a busy OLTP system with around 3K batch request/second mostly insert and to a lesser degree updates. as an OLTP system there is mostly 1 insert/transaction so there are alot of transaction commits. there are some reporting queries for system purposes(queue readers, monitoring, etc)

the problem is log flush performance is slow and we get writelog waits.
i have tested I/O and it can manage over 100K iops/sec in 4k random write test, sequential writes up to 2500MB/sec

databases
compatibility level = 130(sql server 2016)

indirect checkpoint = on,

VLF count = 80-120

processor
cpu usage of 3%-8% , average of 5%, maxed under 10% when log backups runs(compressed backups)
total signal time/total wait time = 6% – 94% resource wait time

memory
PLE is about to tick every second, currently stands for 584000 secs
there is very little page swap observable (pages/sec)

this is the real problem i found

"log flushes/sec" = 1000-2000 /sec

"log flush waits time" = 1000-4000 ms/sec

"log flush write time" = 0-1 ms/sec with spikes of 10-15 ms/sec

"AVG disk sec/write" = 0

"current disk queue" = 0 (with spikes of 2 every few minutes)

"Disk idle time" = 90%-100%

so it seems there's something wrong as sql server is unable to use ultra low latency that SSD array provides…

i tried to disable log writer threads from cpu affinity mask , chris adkin wrote in his blog with no success, also used extended events to monitor log flushes, and saw multiple waits happens for a single log flush.

i don't know if this issue exists on previous servers because on that platform I/O was kinda problem and "log flush write time" was alot higher…

so did you ever see this issue in the field and what is the solution from now on
thanks

Best Answer

This is not an answer for 'what is the solution from now on' but more of how to identify the problem.

Transaction log is not like data pages in terms of how it is hardened to disk. Transaction log is first written to log buffer and then asynchronously written to disk. In 2016 there is a limit of 112 concurrent log-flush I/Os at any one time for each database’s transaction log.

There are 3 things that cause SQL Server to need to flush a log buffer to disk (to an adjoining log block in the transaction log).

  1. A transaction commits and that transaction has an active log record in a log buffer. This will cause all log records in those buffer (again, up to 60K worth of transaction log record for each log buffer) to be flushed to the log file.
  2. We hit the 60K size limit for the log buffer and must flush it to disk.
  3. We have data pages that we must write to disk and there are log records related to those pages. We must write those log records to the log file BEFORE we write the data pages to the data files (this supports our Write Ahead Logging (WAL) protocol).

The smallest log flush possible is a single 512-byte log block. If all transactions in a workload are very small (e.g. inserting a single, small table row) then there will be lots of minimally-sized log flushes occurring. Log flushes are performed asynchronously, to allow decent transaction log throughput, but there is a fixed limit of 112 concurrent log-flush I/Os at any one time.

As you described you have good io subsystem in conjunction with a large number of short transactions/sec your problem may be following.

On a high-performing I/O subsystem, the writes may complete extremely quickly, but the limit of 112 concurrent log-flush I/Os creates a bottleneck when trying to make the log records durable on disk. This situation can be identified by low write latencies and a near-constant number of outstanding transaction log writes near to 112 in the aggregated output of sys.dm_io_pending_io_requests.

Most of what I mentioned above are from following resources and there are few solutions described. Also Paul Randal has a short video with demo scripts to confirm if you are having the issue I mentioned above.

  1. Transaction Log Monitoring by Paul Randal
  2. Trimming the Transaction Log Fat part 1 by Paul
  3. Trimming More Transaction Log Fat part 2 by Paul Randal
  4. WHAT IS SQL SERVER’S IO BLOCK SIZE? by Argenis Fernandez
  5. Video by Paul Randal
  6. Demo code to use with the video by Paul Randal