Category Archives: SQL Server

SQL WHILE Loop is Slow and Takes a While (WRITELOG Wait Type)

SQL WHILE Loops can be a convenient way to add various amounts of mock data to a table for testing.  But the WHILE Loop itself can also be a good way to test different functionality within SQL Server itself.  When using a WHILE Loop to insert hundreds of thousands of rows, you might find it taking a lot longer than you expect; even minutes just to insert half a million narrow rows.  Now of course this could be caused by any number of issues, but in this post I am going to focus on a particular cause of the WRITELOG wait type that I recently ran in to.

Setup

Lets start with a simple example. First create a simple example table.


CREATE TABLE [dbo].[MyTable](
[Id] [int] IDENTITY(1,1) NOT NULL,
[SomeText] [varchar](10) NULL,
[MoreText] [varchar](50) NULL
) ON [PRIMARY]

Then execute a WHILE Loop that will insert 500k records.

TRUNCATE TABLE dbo.MyTable
DECLARE @Iterations int = 500000
DECLARE @Counter int = @Iteration
WHILE @Counter > 0
BEGIN
INSERT INTO [dbo].[MyTable]
([SomeText]
,[MoreText])
VALUES
('Num:' + CONVERT(varchar,@Counter)
,CONVERT(varchar,@Counter) + ' bottles of beer on the wall')
SET @Counter = @Counter - 1
END
SELECT *
FROM dbo.MyTable

Your results will vary, but for me that took ~ 1 minute on an otherwise idle Core i7 laptop with 16GB of RAM and an SSD – a lot longer than you might expect.

Why So Slow?

Well, lets first take a look at Activity Monitor while we run the above script again. It will TRUNCATE and reload the table. You’ll see that after a few seconds the INSERT query gets suspended with a Wait Type of WRITELOG.

What is WRITELOG?

The WRITELOG wait type occurs while, wait for it…, “waiting for a log flush to complete. Common operations that cause log flushes are checkpoints and transaction commits.”  Ok, so what is a log flush?  Without going too far off topic here, we need to very quickly discuss a bit about the SQL Server Transaction Log (much more detail here).

When data in SQL Server is modified, the first thing that happens is SQL checks if the needed data page is in memory, and if not, it reads it from disk into memory.  Once the required data page is stored in memory, the changes are applied, and the changes are written to the Log Buffer, also in memory, which stores log records until they are written to disk.  Before being able to write the “dirty” pages to the data files on disk, first the Log Buffer records must be “flushed” and written to disk in the log file itself.  It is at this point where the WRITELOG wait type is encountered as more log flushes for more data changes occur.

Per Paul Randal, log flushes basically occur when either a transaction is committed, or when the maximum of 60KB of log records have been generated since the last log flush.  In order to maximize performance, we generally would want the most efficient flushes of log files to disk – which often means we actually want fewer, larger, log flushes versus tons of very tiny ones causing repeated calls back to disk.

Which brings us back to our WHILE Loop.

How Can We Tell What The WHILE Loop is Doing?

So with that background out of the way, lets take a closer look at exactly what is happening when our above script is running.  Microsoft was kind enough to provide us with a number of Performance Monitor (in Windows 10, just start typing “Perf” at the Start Menu to find it) counters that we can use to see the details of the log flush activity within SQL Server.

Click on the + to add new performance counters, scroll down to the SQLServer:Databases category, and then select the below three log flush related items.

Select Log Flush Wait Time, Log Flush Write Time, and Log Flushes/sec (Log Flush Waits/sec tends to overlap on the graph with Log Flushes/sec, so we will leave it out).

Now click OK and lets re-run the WHILE Loop script from above to INSERT another 500k records.

Your mileage will vary, but you should get graphs similar to the above.  You can see that right around 10:57:45 the query starts, log flushes/sec jumps and so do the wait and write times.  It’s a little confusing because the scales are different for each counter, but if you highlight one of the counters in the pane at the bottom, you can see the Last/Average/Min/Max values.  You can see above (if its not too small to read) that the max value for Log Flushes/sec (blue line, just above 10 on the vertical axis) was ~12,500.  You can’t tell exactly from the graph, but the query ran for 44 seconds.  Of course we need to take into account the roughness of the calculation, but 44sec x 12,500 log flushes/sec = 550,000 log flushes.  Which is right around our 500k row mark!  So from this we can infer that there was essentially one log flush, and one write to disk, for every. Single. Row.  Which makes sense because, with the WHILE Loop, each iteration of the loop – unless otherwise specified – is treated as a single transaction to be committed.

*Honestly I was kind of surprised when I did the math and it worked out…

Wrapping it Up

Now lets tweak the query by wrapping it in a BEGIN TRAN and COMMIT.

DECLARE @Iterations int = 500000
DECLARE @Counter int = @Iterations
BEGIN TRAN
WHILE @Counter > 0
BEGIN
INSERT INTO [dbo].[MyTable]
([SomeText]
,[MoreText])
VALUES
('Num:' + CONVERT(varchar,@Counter)
,CONVERT(varchar,@Counter) + ' bottles of beer on the wall')
SET @Counter = @Counter - 1
END
COMMIT TRAN

Now lets clear the performance counters, select the same ones, and run the new query.

This time the query took 17 seconds, and as you can see (*the scale is different by a factor of 100 this time), there were substantially less log flushes this time.  In fact, the max this time was only 500 log flushes/sec.  What this tells us is that by wrapping the WHILE Loop of INSERTS inside one transaction, SQL waits until the log buffer is full with ~60KB of log records before flushing it to disk.  This leads to many fewer I/O calls, and thus a big improvement in performance by doing fewer, but larger, writes to the log file.

I’m not exactly sure why there is the small ramp up, then the jump to 500 flushes/sec, but I was able to reproduce a similar pattern during multiple attempts.  If anyone has an explanation, please leave it in the comments!

Summary

In this example we saw that depending on how you work with transactions, and by extension log flushes, a WHILE Loop can behave very differently.  Depending on how transactions are structured, you may run in to different bottlenecks, such as the WRITELOG wait type, which cause your query to run slower than expected.  Using Performance Monitor, we were able to find the cause of the WRITELOG wait type, log flushes, and measure how small changes to the query can affect this underlying performance issue.

 

What happens to an Identity column value when an INSERT is rolled back in SQL?

What happens to an Identity column in a table when an INSERT statement fails and is rolled back before it is committed in SQL Server?  I came across this question while playing around with some unit tests in SQL and looking at how the unit testing framework rolled back transactions during teardown.  In a unit test, I was using an explicit Id value in a WHERE clause – say WHERE Id = 2 – and was not getting a result.

To see exactly what happens with the identity column, we can walk through a few simple transactions.

--Create table with an Identity column seeded to 1
CREATE TABLE IdentityRollbackTest (
Id int IDENTITY(1,1)
,SomeText varchar(10)
,MoreText varchar(50)
)
--Insert first record
INSERT INTO IdentityRollbackTest (SomeText,MoreText)
VALUES ('First','Identity rollback test row')
--Check that row was inserted
SELECT *
FROM IdentityRollbackTest

First we create the table, IdentityRollbackTest, INSERT one row, and check the results.  As expected there is one row, Id = 1, in the table.

And DBCC CHECKIDENT (IdentityRollbackTest) returns the below.  Remember that DBCC CHECKIDENT  returns the current, eg: last used, identity value – in this case, 1.

Now lets try to INSERT a second row, but rollback this transaction.


--Try to insert a second row, but rollback the transaction
BEGIN TRAN
INSERT INTO IdentityRollbackTest (SomeText,MoreText)
VALUES ('Second','Identity rollback test row')
ROLLBACK TRAN
--Check that second row was correctly rolled back
SELECT *
FROM IdentityRollbackTest

As expected, we still only get 1 row returned from the SELECT *.

BUT, this time when we run DBCC CHECKIDENT(IdentityRollbackTest)

We get a current identity value = 2!

Now to confirm what happened, we run a third INSERT statement, which we commit.


--Try to insert a third row, allow this one to commit
INSERT INTO IdentityRollbackTest (SomeText,MoreText)
VALUES ('Third','Identity rollback test row')
--Check that the third insert attempt did succeed, and that the Id column value is 3. This confirms that the identity value was
--incremented even though the second row insert was rolled back
SELECT *
FROM IdentityRollbackTest

When we SELECT * FROM IdentityRollbackTest this time, we see the Id has in fact incremented to 3, but we only have the two rows from the two statements we allowed to commit.

Why does this happen?

At first this behavior had me confused – why did the ROLLBACK not also rollback the incrementing of the Identity column?  Until I did a bit of googling and found the explanation – https://stackoverflow.com/questions/282451/sql-identity-autonumber-is-incremented-even-with-a-transaction-rollback .  Since the identity column’s only requirement is to be unique, not sequential, if transaction A starts, then transaction B starts, B can’t wait to see if A commits before “claiming” its own identity value.  Once an INSERT command has been issued, an identity value is “claimed” by a transaction, even if the transaction is never committed.  If the transaction never commits, that identity value is “lost” for good.

It’s a feature, not a bug.

Writing SQL Server Unit Tests Using Visual Studio, NUnit, and SqlTest

Unit testing SQL development is generally more difficult than other, more “traditional”, application development, such as with .Net.  The nature of databases and transactions don’t always lend themselves to easily run a large number of small individual tests of things such as complicated queries or stored procedures.  Some of this is due to our ingrained design patterns as SQL developers, and some is due to a lack of tools.  Thankfully, on the subject of tools, there has been a lot of progress over the last several years.

A colleague of mine, Mark Wojciechowicz, recently took it upon himself to create a library that can be used in Visual Studio with the NUnit framework and the NUnit3TestAdaptor (both can be downloaded via Nuget) to conduct unit tests of SQL Server objects – aptly named SqlTest.  You can read his introductory post about SqlTest, and some of the deficiencies of existing tools, at his website –   https://www.thisintelligentlife.net/introducing-sqltest and check out the code on github.

In this post I am going to walk through my own experience setting up some simple unit tests with NUnit and SqlTest.  I only recently became familiar with unit testing for SQL Server myself,  so hopefully this post can help beginners to get started.   I hope to expand on this with a series of posts on more CICD in the near future including using SqlTest to test SSIS packages and integrating SqlTest based unit tests with TFS.

Setup

First we are going to need to set up a Database Project in Visual Studio and add a few NuGet packages to our solution.  In this example I used SQL Server 2016 and VS 2015, and I have a Solution called SandboxDB which contains a SandboxDB SQL Server DB project, and a SandboxDBTests C# class library project.  The SandboxDB database project is a simple local database with just a few basic tables and a stored procedure, InsertCustomer which just takes 3 parameters and INSERTs a record in to dbo.Customer.  The CREATE scripts for this sample db can be found here.  Any db project will work as long as it builds and the Tests are modified accordingly.

Before you are able to select the NuGet package manager option in VS, you first need to add a new C# class library project to your solution.  Once you have added a class library project, you can go to the below menu.

NuGetPackageManagerOption

The three packages we need to install are:

–     NUnit
–     NUnit3TestAdaptor
–     SqlTest
 UnitTestPackages

After installing these 3 packages, your references should look like the below.  The SqlTest package should add a Samples folder within your class library project containing sample unit tests for SQL and SSIS.  The SandboxDBTests project contains the references to NUnit and SqlTest, as well as the Samples folder installed by SqlTest.  For now, we will exclude the SsisSample.cs file from the project and focus on the SQL db unit tests.

 

References

Writing a Test

Once installed, the next step is to edit the samples to fit our own db project, including setting the App.config file.  Below we set the connection string name to Sandbox, the Data Source to my named instance of SQL Server (localhost\MSSQLSERVER2016), and the Initial Catalog to Sandbox for our demo.  Later, this is also where we would configure the settings for our SSIS Server.

<configuration>
<connectionStrings>
<add name=”Sandbox” connectionString=”Data Source=localhost\MSSQLSERVER2016;Initial Catalog=Sandbox;Provider=sqloledb;Integrated Security=SSPI;” />
</connectionStrings>
<appSettings>
<add key=”ssisServer” value=”localhost” />
</appSettings>
</configuration>

Next, in the file generated as an example when we installed SqlTest, SqlSample.cs, we modify the SqlTestTarget and connection strings to match our project.  Such as:


public class SQLUnitUnderTest
{
TransactionScope scope;
SqlTest.SqlTestTarget SandboxDb;

[SetUp]
public void Setup()
{
scope = new TransactionScope();
SandboxDb = new SqlTest.SqlTestTarget("Sandbox");
}


Thanks to NUnit, we have a robust framework to Setup, TearDown, Arrange, Act, and Assert our tests. Setup prepares a new transaction and performs any common Db preperations, TearDown returns the database to its original state by rolling back any transactions used in the test. Arrange, Act, and Assert correspond to a Test’s specific preparation, execution of the unit of code that is being tested, and validating that the results are as expected, respectively.

Each [Test] block designates a separate unit test. It is helpful to name each method/Test with a naming standard such as UnitUnderTest_Action_ExpectedOutcome; such as InsertCustomer_Insert_OneRow – Stored procedure “InsertCustomer”, Action “INSERT”, expected outcome “one row”. After the Assert, the teardown method is called to rollback the transaction.

In the below example test, first we TRUNCATE the Customer table to set it up for the test, next we call the dbo.InsertCustomer stored procedure and pass in the required parameters, and lastly we do a SELECT COUNT(1) to make sure we return the expected value, one row.


[Test]
public void InsertCustomer_Insert_OneRow()
{
//Arrange
SandboxDb.ExecuteAdhoc($"TRUNCATE TABLE Customer;");
//Act
SandboxDb.ExecuteAdhoc($"Exec dbo.InsertCustomer 'Steve', 'Rogers','7/4/1920';");
//Assert
var actual = SandboxDb.GetActual("SELECT COUNT(1) AS TotalRows FROM dbo.Customer");
Assert.That(actual, Is.EqualTo(1));
//The teardown method runs after every test and will rollback all actions in one transaction
}

The NUnit framework is what provides the Assert.That method, and the various arguments, such as Is.EqualTo, which we can use to check our results.  In the above example, we are checking that the variable “actual” is equal to the integer 1.  There are a ton of possibilities built into NUnit assertions that you can use for your tests.

Running a Test

Once the code is set up and built, we are ready to run our test. Having installed the NuGet NUNIT3TestAdapter above, our NUnit SqlTests can be run directly from within Visual Studio. If the Test Explorer window is not open, go to Test > Windows > Test Explorer to open the pane. The Test Explorer should display something like the below. If it says there are no tests, make sure to build the project containing the tests. The blue “!” indicates that the test has yet to be run for this build.

TestExplorer

Right click on the InserCustomer_Insert_OneRow test and click Run Test.  If all goes well, the test will pass.

PassedTest

Congrats! That’s all there is to it to run a simple Unit Test of a stored procedure using NUnit and SQLTest.  From here you can copy/paste the [Test] code block (this is how NUnit recognizes that a method is a test) and modify it accordingly to run various tests on various objects.  For each [Test] code block you add, you will get another test listed in the test explorer.  You can even sort the tests based on what class they are in to organize them for each object you want to test.

TestExplorerGrouping

Had we messed up any of the SQL statements, or if a result is different than what is expected in the Assert, the test would fail, and throw an error with the SQL error message.  In this screenshot you can see I left out the FROM in the Assert SQL statement.

FailedTest

Summary

In this post we got started writing unit test for SQL Server DB projects using VS, NUnit, and SqlTest.  After writing one test, you’ll want to write another.  After you get started with these frameworks, you can begin to copy/paste much of the code in order to write more unit tests.  Adding another test for SqlTest is as simple as copying the [Test] code block and changing the tables and queries.  The small amount of upfront cost will return huge dividends later with improved code reliability and confidence.

In future posts I will review how to use SqlTest to write unit tests for SSIS packages, and hopefully how to integrate these SQL Server unit tests into a full TFS CICD solution.

Lastly, another shout out to Mark for taking the time to create the SqlTest library to help make unit testing SQL Server easier!

Problem Connecting to Remote SQL Server – “doesn’t support requested protocol”

Problem:

After installing a new named instance of SQL Server 2016 onto a development machine, I was unable to connect via a remote machine, but could connect locally.  The named instance, MSSQLSERVER2016, was the 2nd instance to be installed on the server – the original was the default instance of SQL 2012 Standard.

I got the error message:

“A network-related or instance-specific error occurred while establishing a connection to SQL Server.  The server was not found or was not accessible.  Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: SQL Network Interfaces, error: 28 – Server doesn’t support requested protocol) (Microsoft SQL Server)”

I was still able to connect successfully to the original 2012 default instance.

 

Solution:

The first thing I checked, as suggested in the error message, was that remote connections were enabled in the server properties of the named instance.

The named instance was correctly set to allow remote connections.  So started to search for information regarding SQL Server network protocols and came across this MS document on SQL Server Network Protocol Configuration – https://docs.microsoft.com/en-us/sql/database-engine/configure-windows/default-sql-server-network-protocol-configuration .

Apparently, different editions of SQL Server set network protocols differently for security purposes, as you can see from the table below taken from the documentation.

In this case, I was in fact using Developer Edition for the MSSQLSERVER2016 named instance, so TCP/IP connections – which would be used for remote connections – was disabled, while Shared Memory – which would be used locally – was enabled.  This differs from the installation defaults of Enterprise and Standard editions.

So, to fix the connection problem, I opened up SQL Server Configuration Manager on the server, went to SQL Server Network Configuration, and sure enough, for the MSSQLSERVER2016 named instance TCP/IP was set to disabled.

After changing the TCP/IP Protocol Status to Enabled, all I had to do was restart the SQL Server Service for the named instance, and then I could connect successfully from a remote machine.