10

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
1

2 Answers 2

2

Problems in performance regarding processing time can be related to your power option not being set to "HIGH PERFORMANCE", but in virtual machines, it is often related to misconfigurations in the cores per socket option.

SQL Server is numa aware and several optimizations and decisions are made on the Numa topology as presented by the bios; in high loads, misconfiguration on the alignment for the cores can lead to exacerbation of contention problems and take your server performance down.

A common misconfiguration that I have observed is 1 core per socket. Regardless of the number of sockets, this may cause latency issues when it comes to processing time and memory access.

Example:

exec sp_readerrorlog 0, 1, 'SQL Server detected'

 SQL Server detected 16 sockets with 1 cores per socket and 1 logical
 processors per socket, 16 total logical processors; using 16 logical
 processors based on SQL Server licensing. This is an informational
 message; no user action is required.

Check your cores per socket configuration and favor aligning it to underlying host. In other words: if your host has 16 cores per socket, make your VM 16 cores per socket.

For more information, see "Best Practices for Running SQL Server on vSphere":

https://www.vmware.com/content/dam/digitalmarketing/vmware/en/pdf/solutions/sql-server-on-vmware-best-practices-guide.pdf

3.5.4 Cores per Socket

As it’s still very common to use Cores per socket setting to ensure that SQL Server Standard Edition will be able to consume all allocated vCPUs and can use up to 24 cores23, care should be taken to get the right vNUMA topology exposed to a VM, especially on the vSphere 6.0 and below while satisfying the licensing needs. As a rule of thumb, try to reflect your hardware configuration while configuring cores per socket ratio and revise the NUMA section (3.6) of this document for further details

0
-4

SOS_SCHEDULER_YIELD indicates that you’ve got contention and that queries are spending a lot of time waiting to get access to a CPU.

  • Check MAXDOP : MAXDOP is the maximum number of cores that will be used when a query goes parallel. If you set 4 only 4 cores will be taken by that query. If you set 0 all cores will be taken therefore you will experience waits and blocking
  • Check Cost Threshold for Parallelism: Cost Threshold for Parallelism determine when the query should be parallelized. Unfortunately Microsoft set 5 by default which is an old default value that dates back the '90. If you keep that value so low most of the queries will go arallel very soon and if you have MAXDOP set to 0, well, all cores will be taken and you will experience waits and blocking. Set that value to 25 or 50 so will be like saying to your query:"hey, you, query... you don't look that heavy to me, stay down there and DON'T go parallel". This way only heavy queries will go parallel and at that point MAXDOP will enter in your equation... at the exact rate that you specified in the previous point

Another test: downgrade the compatibility level from 2016 to 2012 and see if it takes seconds to execute. It might be linked to the cardinality used in 2016.

1
  • SOS_SCHEDULER_YIELD accounts for only 0.18% of the query elapsed time. Dec 11, 2020 at 18:27

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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