3

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

  • Are data and log on the same array? What IO rates and times does PMON report versus sys.dm_io_virtual_file_stats? – Dan Guzman Aug 27 '17 at 15:49
  • With 0-2ms logflush time it does not look slow to me. This is essentially singlethreaded and most likely the striping does not help with distributing that as well. You could consider having multiple databases to get more parallelity. You can try to rerun your IOPS test with one writer test, it should show the same 2k IOP/s. – eckes Aug 27 '17 at 16:15
  • @eckes yes it dosn't seems slow to me too, but this is average... what we have here is 90% of inserts written in micro second times but those 8% written longer and few 2% written very long... up to 100ms at times, so its not as smooth as it seems. you can see my comment about test system on my comment for david's answer – majid malek Aug 27 '17 at 18:24
  • Well, not sure how to find the reasons, but here are some ideas which might help: Are your SSDs working close to the capacity maximum (I.e. need time for GC)? Could you maybe reduce the raid0 stripe size? Is this one NTFS for data and log? BTW do you have pre-upgrade numbers to compare? – eckes Aug 27 '17 at 18:30
  • @dan yes everything on same volume, generally i get very fast times in sys.dm_io_virtual_file_stats. my most active log file stall time(latency) per write is 71 microsecond , but with sys.dm_os_wait_stats writelog is my number 1 wait and on average it takes 800 microsecond/log flush. perfmon disk counters as stated in my original post seems very fast times, "log flush write time" for example took less than a milisecond to write 1 second of I/O generated but "log flush wait time" on average gets 2000 ms – majid malek Aug 27 '17 at 18:40
1

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
0

(Not an answer, but comments don't allow code.)

You don't have an AlwaysOn AG or a mirror, correct?

In a user database test your max log flush rate like this:

create table t(id int)
go
set nocount on
declare @i int = 0
while @i < 100000
begin
  insert into t(id) values (@i);
  set @i = @i + 1;
end
  • on a similar server with 2 raid 1 SSD , using 60 threads(about same sa production system) using connection pooling (.net clients) and production like stored procedures (into 5 tables) i can reach 7K inserts(log flushes) /sec with very little waits(log flush wait time 0-50ms). so that is more realistic test than above query – majid malek Aug 27 '17 at 17:54
  • yes there are 3 servers in asynchronous commit mode, but when i suspend data movement nothing gets better, same waits all over again. we wanted to switch to synchronous commit but cant due to growing response times. and with running similar workload in test systems i tracked transaction delay in synchronous commit roots in high wait time for log flushes. – majid malek Aug 27 '17 at 18:16
  • @majidmalek log flushes don't wait on sync commit - fyi. They happen in parallel, however there is an extra step in copying to the log pool. Asynch commit mode can stil hit the log/log pool in ways that affect log throughput, since you paused and saw no change I doubt it has anything to do with the AGs. – Sean Gallardy Aug 27 '17 at 19:29

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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