SQL Server 2016 Multi Threaded Log Writer

This is probably one of the most unheralded new features of SQL Server 2016 which gets but a single bullet point in the CSS engineers “It Just Runs Faster” blog post series.

Querying sysprocesses and joining a few other objects to it reveals that the log writer is multi threaded in SQL Server 2016:

sql 2016 log writer

As always I am never satisfied with with reading about new features and accepting what they do on face value, you should know where this is going by now ! . . . So I decided to give this new feature a test drive with my singleton insert test. Here is the table I will insert into:

CREATE TABLE [dbo].[MyBigTable] (
      [c1] [bigint]    NOT NULL
     ,[c2] [datetime]  NULL
     ,[c3] [char](111) NULL
     ,[c4] [int]       NULL
     ,[c5] [int]       NULL
     ,[c6] [bigint]    NULL
     CONSTRAINT [PK_BigTable] PRIMARY KEY CLUSTERED (
         [c1] ASC
     ) WITH ( PAD_INDEX              = OFF
             ,STATISTICS_NORECOMPUTE = OFF
             ,IGNORE_DUP_KEY         = OFF
             ,ALLOW_ROW_LOCKS        = ON
             ,ALLOW_PAGE_LOCKS       = ON) ON [FG_01]
)

And this is the stored procedure that will be used to perform concurrent inserts into it via osstress (which comes with rml utilities):

CREATE PROCEDURE [dbo].[usp_InsertSpid]
    @RowsToInsert int = 500000
AS
BEGIN
    SET XACT_ABORT ON;
    SET NOCOUNT ON;

    DECLARE  @i      INTEGER = 0
            ,@base   BIGINT  = @@SPID * 10000000000
            ,@PartId INTEGER;

    WHILE @i <= @RowsToInsert
    BEGIN
        BEGIN TRANSACTION
            INSERT INTO dbo.MyBigTable (c1)
            VALUES (@base + @i);
        COMMIT;

        SET @i += 1;
    END;
END;

This is my test hardware:

reasonably priced server

I should also mention that all the work in this post involves the legacy row store engine and not the in-memory OLTP engine.

I have two types of storage; a Raid 0 stripe composed of 3 SanDisk 480Gb Extreme Pro drives, which according to DiskSpd gives the following performance for a workload which is 100% write intensive and composed of 60K writes:

SanDisk Pro Stripe

and a single Samsung 512GB PCIe NVMe drive which gives us:

Samsung 950 Nvme

I have chosen the 60K write intensive workload because I want to illustrate what the NVMe drive can do in comparison with a high end consumer SSD for the best case scenario when writing to a transaction log.

Test Time !

The first test is to compare SQL Server 2014 SP1 ( CU 4 ) against SQL Server 2016 RC1 with full durability:

fully durable

And now for the exact same test but with delayed durability:

delayed durable

To understand why we get this performance degradation with SQL Server 2016 RC1 three key parts of a transactions life cycle need to be understood along with the serialisation mechanisms that protect them:

  1. Transaction Creation and Removal

This call stack excerpt is taken from SQL Server 2014 SP1 CU4, the call immediately after sqlmin!XdesMgr::GetXdesId is for the XDESMGR spinlock (what you will see in sys.dm_os_spinlock_stats) for this function. In a nutshell sqlmin!XdesMgr::GetXdesId deals out transaction ids. The in-memory OTLP engine has a completely different mechanism for dealing out transaction ids, which I believe is based on the use of an atomic increment instruction and does not involve any spinlocks.

xdesmgr

Remove Transaction

2. Copying Log Records Into The LOG Buffer

To recap on something I have used a lot in my blog posts, this is the logging infrastructure ( which I need to get around to adding the log pool to at some stage ):

logging infrastructure

The big takeaway point from this diagram is that there is a hell of a lot of things which happen from the point of log record generation to the point at which log records are hardened to the transaction log.

Here is the call stack excerpt for the LOGCACHE_ACCESS spinlock which serialises access to the log buffer, again this is taken from SQL Server 2014 SP1 CU4. Despite the claims of Microsoft’s marketing department that the in-memory OLTP engine is spinlock free, the LOGCACHE_ACCESS spinlock is still used, but only for the copying of undo information to the log buffer.

logcache_access

3. Harding Log Records To Disk

When the log writer flushes log records to disk the LOGFLUSHQ spinlock ( again the name you will see in in sys.dm_os_spinlock_stats ) serialises access to the log flush queue:

logflushq

And The Point Of All Of This Is . . . ?

If we understand the spinlocks associated with transaction id generation and logging we have a means of identifying pressure on these particular points of the engine. For the tests with delayed durability the spin activity on the key three spinlocks is:

xdesmgr spins

xdesmgr back offs

logcache_access spins

logcache_access back off

logflushq spins

logflushq back offs

My theory is that a combination of:

  • The number of osstress insert threads
  • The performance of the NVMe flash drive
  • An optimal log write size of 60K
  • The fact there is now more than one log writer thread, meaning we would get LOGFLUSHQ spins naturally without the perfect storm that has been created for putting this under pressure.

is creating the “Perfect storm” whereby the multiple log writers in SQL Server 2016 are contending on draining the log flush queue such that spins on the LOGFLUSHQ become a factor to such an extent that a “Back pressure” effect is created against the log buffer. Hence why the number of LOGCACHE_ACCESS spins is so much higher for SQL Server 2016 than it is for 2014. And in summary it is this spin activity that is sending performance backwards compared to SQL Server 2014.

Why Have Microsoft Done This ?

At this point in time I do not have an honest answer to this, however something that has caught my eye, is the function call highlighted below, this is present for SQL Server 2016 but not for 2014:

GroupCommit

My hunch, and this is only a hunch, is that the multi threaded log writer may have been introduced as part of some wider piece of work to do with availability group optimisation. I know for a fact that a lot of engine tuning has gone into SQL Server 2016 as per this graph provided by Jimmy May from SanDisk:

Ag Wire Protocol

And Remember !!!

If you like my work, places are still available for my SQL Bits precon.

 

 

 

24 thoughts on “SQL Server 2016 Multi Threaded Log Writer

  1. “Group commit” usually refers to writing the log records of multiple transactions in one IO. I don’t see a relationship to AGs based on that word.

    • When you say “Usually refers”, which version of SQL Server are you referring to ?, can you provide me with any official Microsoft documentation or stack traces to support this claim, this function call did not appear in the stack trace for SQL Server 2014. There are white papers on the in-memory OLTP engine which refer to the grouping of records together for larger writes, but they make no mention of writes themselves being grouped together. I invite you to try and find the IsGroupCommitEnabled function in any version of SQL Server prior to 2016. Taken on face value this function name hints on something that needs to be enabled, by a trace flag ?, I don’t know, also its name seems similar to the Is . . . Enabled columns in sys.databases. Finally, as per the use of the word hunch twice, I tried to make the point that this was a tenuous link. However, it is entirely within the realms of possibility that Microsoft have implemented this to support the enhancement to the availability group wire protocol. Consider this, if you can commit on a replica at 1GB/s according to the work SanDisk have done with SQL Server 2016, it does not take a great mental leap to come to the conclusion that Microsoft may have done work in other areas, i.e. the log writer (which in their eyes at least) supports this, but again, to use the word for a third time, this is only a ‘Hunch’ and could be something or nothing, which to come full circle is the point I was trying to make.

    • You can take CPU core out of the affinity mask, this is where the log writer ** usually ** runs on versions of SQL Server prior to 2016, on 2016 it appears that the log writer ** usually ** uses cores 0 and 1 of CPU socket zero. If you have hyper-threading enabled this, it will appear that SQL Server 2016 is uses four logical CPUs. I suspect the problem is down to the fact that when you have more than one log writer running with delayed durability ( implicit transactions will achieve the same effect ) you have LOGFLUSHQ spinlock contention between the two log writer threads. As per my graphs in the blog post, the affect of this is not noticeable when using normal full durability, change to full durability, and the log writers are clearing the log flush queue down that fast that they begin to stress the LOGFLUSHQ spinlock, most people will not see this on SQL Server 2016, to reproduce this you need:

      1. Low latency storage for the transaction log.
      2. A scenario specifically constructed in order to achieve a high throughput of singleton inserts.
      3. A reasonable number of CPU cores.
      4. . . . and obviously SQL Server 2016

      I suspect that Microsoft have not hammered SQL Server 2016 in the way I have . . .

      You will notice that with my test on SQL Server 2014 the number of XDESMGR spins is higher than that for 2016, which makes me conclude that this is not the bottleneck inhibiting insert throughput.

      I hope this explains the scenario better.

    • I’ve looked at your response again, my thoughts and this is 100% pure conjecture on my part, are that if you have more than one user database per instance, despite the fact that log records always have to be hardened in log sequence order, there should be no logical reason why the log flush queue cannot have more than one log writer when it is flushing data to the transaction logs of multiple databases. Again, this is 100% pure conjecture, I suspect that ( as per my wrap-up comments ) the multi threaded log writer might be part of a wider piece of work associated with the tuning of the availability group wire protocol in SQL 2016.

    • I’ve tested this with RC3 with low latency storage, delayed durability and a test that is designed to stress the logging infrastructure its slower than 2014.

      • Besides your Connect item I would imagine that CSS knows all about your findings. Wonder how this performs if you could find a way of going back to 1 log writer?

      • I would hope it would perform as well as SQL Server 2014, having said that they have added more code around the log writer, therefore the code path might be longer. However, without getting windows performance toolkit out I can’t offer an opinion (as yet) as to what this extra code does.

  2. Hi,
    Yesterday, i installed 2k16 RC3 on my laptop where I have 4 cores (Hyper threading enabled) but I cannot see multi thread for log writing. May you please confirm the SQL Server version (RC0, RC1 or RC2 ?) which you used?

    Thanks!

    • According to the CSS engineers blog post on this, you get one log writer thread per NUMA node, implying you need a machine with at least two CPU sockets to see this feature, this is why you cannot see the multiple log writer threads on your laptop. All laptops to the best of my knowledge only support a single CPU socket.

  3. Eagerly awaiting your RTM tests. I’m discussing your results with the dev team, as this seems like a backward step in perf under some circumstances that should be configurable to turn off. Good stuff as always!

    • Hi Paul,
      My findings with the rtm version are no different to what I found with CTP versions of SQL 2016. As you have access to people at Microsoft that I do not I would be interested to know what specific problem Microsoft were trying to solve with it.

      Chris

  4. Hello Datatake,
    first of all greetings for your excellent posts, I was not aware of your blog and it will become a must for me!

    Maybe the multi threaded log writer has been developed togheter with the multi threaded redo log job? As far as I know one of the new feature of sql2016 is the improved performance of the redo job in an AlwaysOn scenario.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s