Sql-server – Instance performance variations around SOS_SCHEDULER_YIELD behavior during single-row INSERT statements

I have a shared SQL Server 2016 dev instance in a VM which has poor INSERT performance compared to a shared SQL Server 2012 dev instance on an (supposed to be) identical VM. It also compares poorly to my local SQL Server 2016 dev instance, so I am currently proceeding on the assumption that there is some quirky issue on that instance, because most other operations on that server seem fairly steady.

They are 1000 individual insert statements of the form:

INSERT INTO tblname (columnlist) VALUES (literals);

There is no explicit transaction.

I wrapped these INSERTs in extended events so I could see a little of what the difference is between environments. I also made a version which runs a loop instead of literals. The performance of the loop is noticeably different on the affected system, I am not including the loop version code below – it performs consistently, but I do drop and recreate the DB before executing that script and the results are included.

I have the system set up to be reproducible and easily pushed to any system for comparison. I am running everything from command scripts and sqlcmd. First a setup script runs to create the database, the table, the XE session. Then a second script runs which starts the trace, executes 1000 INSERT VALUES statements, stops the trace and displays the results using https://www.sqlskills.com/blogs/paul/capturing-wait-stats-for-a-single-operation/

I already noticed that this particular SQL Server 2016 has very different character around SOS_SCHEDULER_YIELD, and I wonder if this already points to what the underlying problem might be. In addition, I seem to have isolated the problem to the use of GETDATE and GETUTCDATE in defaults on this server.

perftest.cmd:

DEL *.xel
echo Running setup.sql
sqlcmd -o "setup.sql.output-1.txt" -I -b -l 120 -t 300 -S %SQLINSTANCE% -U sa -P %PASSWORD% -d master -i .\setup.sql
echo Running perftest.sql
sqlcmd -o "perftest.sql.output-1.txt" -I -b -l 120 -t 300 -S %SQLINSTANCE% -U sa -P %PASSWORD% -d InsertPerfTest -i .\perftest.sql
echo Running setup.sql
sqlcmd -o "setup.sql.output-2.txt" -I -b -l 120 -t 300 -S %SQLINSTANCE% -U sa -P %PASSWORD% -d master -i .\setup.sql
echo Running perftestloop.sql
sqlcmd -o "perftestloop.sql.output-1.txt" -I -b -l 120 -t 300 -S %SQLINSTANCE% -U sa -P %PASSWORD% -d InsertPerfTest -i .\perftestloop.sql
COPY setup.sql.output-1.txt /A + perftest.sql.output-1.txt /A + setup.sql.output-2.txt /A + perftestloop.sql.output-1.txt /A combined-output.txt /A

setup.sql:

SET NOCOUNT ON;
GO

PRINT '-------------------- SCRIPT START--------------------------------';
SELECT TEST = 'setup.sql', SERVERNAME = CAST(@@SERVERNAME AS nvarchar(32)), [VERSION] = @@VERSION, DATABASENAME = CAST(DB_NAME() AS nvarchar(32));
GO

IF EXISTS (SELECT * FROM sys.databases WHERE [name] = 'InsertPerfTest')
BEGIN
    EXEC msdb.dbo.sp_delete_database_backuphistory @database_name = N'InsertPerfTest';
    ALTER DATABASE [InsertPerfTest] SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
    DROP DATABASE [InsertPerfTest];
END
GO

CREATE DATABASE [InsertPerfTest]
ON (
    NAME = 'PerfTest_Data'
    , FILENAME = 'C:\perftest\PerfTest_Data.mdf'
    , SIZE = 32MB
    , MAXSIZE = 32MB
)
LOG ON (
    NAME = 'PerfTest_Log'
    , FILENAME = 'C:\perftest\PerfTest_Log.ldf'
    , SIZE = 32MB
    , MAXSIZE = 32MB
)
;
GO

ALTER DATABASE [InsertPerfTest] SET RECOVERY SIMPLE;
GO

USE [InsertPerfTest];
GO

ALTER DATABASE SCOPED CONFIGURATION SET MAXDOP = 1;
GO

CREATE TABLE [TrivialTest](
    [MapRowID] [int] IDENTITY(1,1) NOT NULL,
    [ItemNumber] [int] NOT NULL,

    [ItemText] [nvarchar](max) NULL,

    [UpdateDateTime] [datetimeoffset](7) NOT NULL CONSTRAINT [DF_Trivial_UpdateDateTime] DEFAULT (GETUTCDATE())
);
GO

CREATE TABLE [TrivialTest2](
    [MapRowID] [int] IDENTITY(1,1) NOT NULL,
    [ItemNumber] [int] NOT NULL,

    [ItemText] [nvarchar](max) NULL,
    
    [UpdateDateTime] [datetimeoffset](7) NOT NULL CONSTRAINT [DF_Trivial2_UpdateDateTime] DEFAULT ('01/01/1970')
);
GO

CREATE TABLE [TrivialTest3](
    [MapRowID] [int] IDENTITY(1,1) NOT NULL,
    [ItemNumber] [int] NOT NULL,

    [ItemText] [nvarchar](max) NULL,
    
    [UpdateDateTime] [datetimeoffset](7) NOT NULL CONSTRAINT [DF_Trivial3_UpdateDateTime] DEFAULT (GETDATE())
);
GO

IF EXISTS (SELECT * FROM sys.server_event_sessions WHERE name = 'MonitorWaits')
    DROP EVENT SESSION MonitorWaits ON SERVER;
GO

CREATE EVENT SESSION MonitorWaits ON SERVER
ADD EVENT sqlos.wait_info
    (WHERE sqlserver.database_name = 'InsertPerfTest')
ADD TARGET package0.asynchronous_file_target
    (SET FILENAME = N'C:\perftest\EE_WaitStats.xel',
    METADATAFILE = N'C:\perftest\EE_WaitStats.xem')
WITH (max_dispatch_latency = 1 seconds);
GO

perftest.sql:

SET NOCOUNT ON;
GO

PRINT '-------------------- SCRIPT START--------------------------------';
SELECT TEST = 'perftest.sql', SERVERNAME = CAST(@@SERVERNAME AS nvarchar(32)), [VERSION] = @@VERSION, DATABASENAME = CAST(DB_NAME() AS nvarchar(32));
TRUNCATE TABLE [TrivialTest];
TRUNCATE TABLE [TrivialTest2];
TRUNCATE TABLE [TrivialTest3];
SELECT RowsExistingTest = (SELECT COUNT(*) FROM [TrivialTest])
    , RowsExistingTest2 = (SELECT COUNT(*) FROM [TrivialTest2])
    , RowsExistingTest3 = (SELECT COUNT(*) FROM [TrivialTest3]);
GO

ALTER EVENT SESSION MonitorWaits ON SERVER STATE = START;
GO

DECLARE @ResultsMS AS TABLE(SetName nvarchar(50) NOT NULL, TimeMS int NOT NULL);
DECLARE @Start AS DATETIME;
DECLARE @End AS DATETIME;

SET @Start = GETDATE();

INSERT INTO TrivialTest (ItemNumber, [ItemText]) VALUES ('1', 'Put a huge lump of text here, not sure it really matters, but we want to get the rows size up to a size that''s similar to what we are seeing in the real world rule set.');
-- ... Another 998 rows here
INSERT INTO TrivialTest (ItemNumber, [ItemText]) VALUES ('1000', 'Put a huge lump of text here, not sure it really matters, but we want to get the rows size up to a size that''s similar to what we are seeing in the real world rule set.');

SET @End = GETDATE();
INSERT INTO @ResultsMS (SetName, TimeMS)
SELECT 'Set 1: GETUTCDATE', DATEDIFF(MILLISECOND, @Start, @End);

SET @Start = GETDATE();

INSERT INTO TrivialTest2 (ItemNumber, [ItemText]) VALUES ('1', 'Put a huge lump of text here, not sure it really matters, but we want to get the rows size up to a size that''s similar to what we are seeing in the real world rule set.');
-- ... Another 998 rows here
INSERT INTO TrivialTest2 (ItemNumber, [ItemText]) VALUES ('1000', 'Put a huge lump of text here, not sure it really matters, but we want to get the rows size up to a size that''s similar to what we are seeing in the real world rule set.');

SET @End = GETDATE();
INSERT INTO @ResultsMS (SetName, TimeMS)
SELECT 'Set 2: Literal', DATEDIFF(MILLISECOND, @Start, @End);

SET @Start = GETDATE();

INSERT INTO TrivialTest3 (ItemNumber, [ItemText]) VALUES ('1', 'Put a huge lump of text here, not sure it really matters, but we want to get the rows size up to a size that''s similar to what we are seeing in the real world rule set.');
-- ... Another 998 rows here
INSERT INTO TrivialTest3 (ItemNumber, [ItemText]) VALUES ('1000', 'Put a huge lump of text here, not sure it really matters, but we want to get the rows size up to a size that''s similar to what we are seeing in the real world rule set.');

SET @End = GETDATE();
INSERT INTO @ResultsMS (SetName, TimeMS)
SELECT 'Set 3: GETDATE', DATEDIFF(MILLISECOND, @Start, @End);

SELECT *
FROM @ResultsMS
ORDER BY SetName;

GO

ALTER EVENT SESSION MonitorWaits ON SERVER STATE = STOP;
GO

SELECT RowsExistingTest = (SELECT COUNT(*) FROM [TrivialTest])
    , RowsExistingTest2 = (SELECT COUNT(*) FROM [TrivialTest2])
    , RowsExistingTest3 = (SELECT COUNT(*) FROM [TrivialTest3]);
GO

-- https://www.sqlskills.com/blogs/paul/capturing-wait-stats-for-a-single-operation/
--Create intermediate temp table for raw event data
CREATE TABLE #RawEventData (
    Rowid  INT IDENTITY PRIMARY KEY,
    event_data XML);
 
GO

-- Read the file data into intermediate temp table
INSERT INTO #RawEventData (event_data)
SELECT
    CAST (event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file (
    'C:\perftest\EE_WaitStats*.xel',
    'C:\perftest\EE_WaitStats*.xem', null, null);
GO

SELECT
    waits.[Wait Type],
    COUNT (*) AS [Wait Count],
    SUM (waits.[Duration]) AS [Total Wait Time (ms)],
    SUM (waits.[Duration]) - SUM (waits.[Signal Duration]) AS [Total Resource Wait Time (ms)],
    SUM (waits.[Signal Duration]) AS [Total Signal Wait Time (ms)]
FROM
    (SELECT
        event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [Time],
        event_data.value ('(/event/data[@name=''wait_type'']/text)[1]', 'VARCHAR(25)') AS [Wait Type],
        event_data.value ('(/event/data[@name=''opcode'']/text)[1]', 'VARCHAR(100)') AS [Op],
        event_data.value ('(/event/data[@name=''duration'']/value)[1]', 'BIGINT') AS [Duration],
        event_data.value ('(/event/data[@name=''signal_duration'']/value)[1]', 'BIGINT') AS [Signal Duration]
     FROM #RawEventData
    ) AS waits
WHERE waits.[op] = 'End'
GROUP BY waits.[Wait Type]
ORDER BY [Total Wait Time (ms)] DESC;
GO

-- Cleanup
DROP TABLE #RawEventData;
GO

combined-output.txt:

-------------------- SCRIPT START--------------------------------
TEST      SERVERNAME                       VERSION                                                                                                                                                                                                                                                                                                      DATABASENAME                    
--------- -------------------------------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ --------------------------------
setup.sql SQL2016DEV                       Microsoft SQL Server 2016 (SP2-GDR) (KB4532097) - 13.0.5102.14 (X64) 
    Dec 31 2019 22:39:35 
    Copyright (c) Microsoft Corporation
    Standard Edition (64-bit) on Windows Server 2012 R2 Standard 6.3 <X64> (Build 9600: ) (Hypervisor)
                                                                       master                          
Changed database context to 'InsertPerfTest'.
-------------------- SCRIPT START--------------------------------
TEST         SERVERNAME                       VERSION                                                                                                                                                                                                                                                                                                      DATABASENAME                    
------------ -------------------------------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ --------------------------------
perftest.sql SQL2016DEV                       Microsoft SQL Server 2016 (SP2-GDR) (KB4532097) - 13.0.5102.14 (X64) 
    Dec 31 2019 22:39:35 
    Copyright (c) Microsoft Corporation
    Standard Edition (64-bit) on Windows Server 2012 R2 Standard 6.3 <X64> (Build 9600: ) (Hypervisor)
                                                                       InsertPerfTest                  
RowsExistingTest RowsExistingTest2 RowsExistingTest3
---------------- ----------------- -----------------
               0                 0                 0
SetName                                            TimeMS     
-------------------------------------------------- -----------
Set 1: GETUTCDATE                                        31920
Set 2: Literal                                             877
Set 3: GETDATE                                           31890
RowsExistingTest RowsExistingTest2 RowsExistingTest3
---------------- ----------------- -----------------
            1000              1000              1000
Wait Type                 Wait Count  Total Wait Time (ms) Total Resource Wait Time (ms) Total Signal Wait Time (ms)
------------------------- ----------- -------------------- ----------------------------- ---------------------------
WRITELOG                         3001                 1276                          1274                           2
SOS_SCHEDULER_YIELD              2066                   61                             2                          59
PAGEIOLATCH_SH                      1                    2                             2                           0
PAGELATCH_SH                        2                    0                             0                           0
NETWORK_IO                         38                    0                             0                           0
XE_BUFFERMGR_ALLPROCESSED           1                    0                             0                           0
PAGELATCH_EX                        2                    0                             0                           0
-------------------- SCRIPT START--------------------------------
TEST      SERVERNAME                       VERSION                                                                                                                                                                                                                                                                                                      DATABASENAME                    
--------- -------------------------------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ --------------------------------
setup.sql SQL2016DEV                       Microsoft SQL Server 2016 (SP2-GDR) (KB4532097) - 13.0.5102.14 (X64) 
    Dec 31 2019 22:39:35 
    Copyright (c) Microsoft Corporation
    Standard Edition (64-bit) on Windows Server 2012 R2 Standard 6.3 <X64> (Build 9600: ) (Hypervisor)
                                                                       master                          
Changed database context to 'InsertPerfTest'.
-------------------- SCRIPT START--------------------------------
TEST             SERVERNAME                       VERSION                                                                                                                                                                                                                                                                                                      DATABASENAME                    
---------------- -------------------------------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ --------------------------------
perftestloop.sql SQL2016DEV                       Microsoft SQL Server 2016 (SP2-GDR) (KB4532097) - 13.0.5102.14 (X64) 
    Dec 31 2019 22:39:35 
    Copyright (c) Microsoft Corporation
    Standard Edition (64-bit) on Windows Server 2012 R2 Standard 6.3 <X64> (Build 9600: ) (Hypervisor)
                                                                       InsertPerfTest                  
RowsExistingTest RowsExistingTest2 RowsExistingTest3
---------------- ----------------- -----------------
               0                 0                 0
SetName                                            TimeMS     
-------------------------------------------------- -----------
Set 1: GETUTCDATE                                          940
Set 2: Literal                                             796
Set 3: GETDATE                                            1030
RowsExistingTest RowsExistingTest2 RowsExistingTest3
---------------- ----------------- -----------------
            1000              1000              1000
Wait Type                 Wait Count  Total Wait Time (ms) Total Resource Wait Time (ms) Total Signal Wait Time (ms)
------------------------- ----------- -------------------- ----------------------------- ---------------------------
WRITELOG                         6002                 1798                          1792                           6
SOS_SCHEDULER_YIELD              2069                   61                             2                          59
PAGEIOLATCH_SH                      2                    2                             2                           0
XE_BUFFERMGR_ALLPROCESSED           2                    1                             1                           0
PAGELATCH_EX                        4                    0                             0                           0
PAGELATCH_SH                        4                    0                             0                           0
NETWORK_IO                         38                    0                             0                           0