CPU Ready Impact on SOS_SCHEDULER_YIELD

At the end of May 2017, Paul and I had a discussion about SOS_SCHEDULER_YIELD waits and whether or not they could become skewed in SQL Server as a result of hypervisor scheduling issues for a VM running SQL Server.  I did some initial testing of this in my VM lab using both Hyper-V and VMware and was able to create the exact scenario that Paul was asking about, which he explains in this blog post.  I’ve recently been working on reproducing another VM scheduling based issue that shows up in SQL Server, where again the behaviors being observed are misleading as a result of the hypervisor being oversubscribed, only this time it was not for the SQL Server VM, it was instead for the application servers, and while I was building a repro of that in my lab, I decided to take some time and rerun the SOS_SCHEDULER_YIELD tests and write a blog post to show the findings in detail.

The test environment that I used for this is a portable lab I’ve used for demos for VM content over the last eight years teaching our Immersion Events. The ESX host has 4 cores and 8GB RAM and hosts three virtual machines, a 4vCPU SQL Server with 4GB RAM, and two 2vCPU Windows Server VM’s with 2GB RAM that are used strictly to run Geekbench to produce load.  Within SQL Server, I a reproducible workload that drives parallelism and is repeatable consistently, that I have also used for years in teaching classes.

For the tests, I first ran a baseline where the SQL Server VM is the only machine executing any tasks/workload at all, but the other VMs are powered on and just sitting there on the hose.  This establishes a base metric in the host and had 1% RDY time average during the workload execution, after which I collected the wait stats for SOS_SCHEDULER_YIELD.

clip_image002

Then I reran the tests but ran four copies of GeekBench on one of the application VM’s to drive the CPU usage for that VM and keep it having to be scheduled by the hypervisor, and then reran the SQL Server workload.  This put the SQL Server VM at 5% RDY time in the hypervisor during the tests, which is my low watermark for where you would expect performance issues to start showing.  When the SQL workload completed, I recorded the waits again.

clip_image004

Then I repeated the test again, but with both of the application VM’s running four copies of Geekbench.  The SQL Server VM had an average of 28% RDY time, and when the workload completed the waits were recorded a final time.

clip_image006

As you can see below there is a direct increase in the wait occurrence with the increase in RDY%.

TestAVG RDY%wait_typewaiting_tasks_countwait_time_msmax_wait_time_mssignal_wait_time_msDuration
2 APP VM28.4SOS_SCHEDULER_YIELD1045522893124228033:59
1 APP VM5.1SOS_SCHEDULER_YIELD251436186236081:57
Baseline1.2SOS_SCHEDULER_YIELD1392974129631:32

High CPU Ready time is something that should be consistently monitored for with SQL Server VM’s where low latency response times are required.  It also should be monitored for application VMs where latency is important as well.  One thing to be aware of with any of the wait types on a virtualized SQL Server, not just the SOS_SCHEDULER_YIELD wait, is that the time spent waiting is going to also include time the VM has to wait to be scheduled by the hypervisor as well.  The SOS_SCHEDULER_YIELD wait type is unique in that the number of occurrences of the wait type increases because of the time shifts that happen causing quantum expiration internally for a thread inside of SQLOS forcing it to yield, even if it actually didn’t get to make progress due to the hypervisor not scheduling the VM.

Tracking Compiles with Extended Events

This post comes from a question by Tara Kizer on DBA StackExchange related to Compilations/Sec in PerfMon and using Extended Events to try and track the compilations that were happening in SQL Server for one of their clients.  There are a number of events in Extended Events that relate to plans in SQL Server, and Tara was using the sqlserver.query_pre_execution_showplan event as a way of tracking compiles with Extended Events.  When I read the post on StackExchange this stood out to me as not being the correct event for tracking an actual compilation, and I would have selected the query_post_compilation_showplan event instead.  These two events have similar descriptions, but they differ by one specific word:

query_pre_execution_showplan

Occurs after a SQL statement is compiled. This event returns an XML representation of the estimated query plan that is generated when the query is optimized. Using this event can have a significant performance overhead so it should only be used when troubleshooting or monitoring specific problems for brief periods of time.

query_post_compilation_showplan

Occurs after a SQL statement is compiled. This event returns an XML representation of the estimated query plan that is generated when the query is compiled. Using this event can have a significant performance overhead so it should only be used when troubleshooting or monitoring specific problems for brief periods of time.

NOTE: Both of these event descriptions state “Using this event can have a significant performance overhead so it should only be used when troubleshooting or monitoring specific problems for brief periods of time.” There are only a handful of events in Extended Events that include this warning in their description and each can introduce significant performance impacts to production workloads, so using them in live workloads is not something I’d recommend. (query_post_execution_showplan impact post)

The events aren’t exactly the same in description and occur at different times using the repro example from the StackExchange post. Using a much larger event session definition that includes additional events, it is easy to see where compilations actually are happening.  The event session definition used for proofing this is:

CREATE EVENT SESSION [Compiles] ON SERVER
ADD EVENT sqlserver.query_post_compilation_showplan(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.query_pre_execution_showplan(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sp_cache_hit(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sp_cache_insert(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sp_cache_miss(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sp_cache_remove(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sp_statement_completed(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sp_statement_starting(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sql_batch_completed(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sql_batch_starting(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sql_statement_completed(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sql_statement_recompile(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sql_statement_starting(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.uncached_sql_batch_statistics(
    ACTION(sqlserver.client_app_name,sqlserver.sql_text)
    WHERE ([sqlserver].[is_system]=(0)))
WITH (MAX_MEMORY=4096 KB,
      EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
      MAX_DISPATCH_LATENCY=30 SECONDS,
      MAX_EVENT_SIZE=0 KB,
      MEMORY_PARTITION_MODE=NONE,
      TRACK_CAUSALITY=ON,
      STARTUP_STATE=OFF)
GO

Using part of the repro example from the StackExchange post with slight changes to include clearing the plan cache and also to break the steps down into individual batches and then individual statements we can show how the plans were being used from cache and where compiles actually are occurring.

CREATE TABLE t1 (transaction_id int, Column2 varchar(100));
CREATE TABLE t2 (Column1 varchar(max), Column2 varchar(100));
GO

CREATE TRIGGER t2_ins
ON t2
AFTER INSERT
AS

INSERT INTO t1
SELECT (SELECT TOP 1 transaction_id FROM sys.dm_tran_active_transactions), Column2
FROM inserted;
GO

DBCC FREEPROCCACHE
GO

--Both of these show compilation events
INSERT INTO t2 VALUES ('row1', 'value1');
INSERT INTO t2 VALUES ('row2', 'value2');
GO

--Both of these show compilation events
INSERT INTO t2 VALUES ('row1', 'value1');
INSERT INTO t2 VALUES ('row2', 'value2');
GO

--Both of these show compilation events
INSERT INTO t2 VALUES ('row1', 'value1');
GO

INSERT INTO t2 VALUES ('row2', 'value2');
GO

Here you can see the first compilation happening for the INSERT statements as prepared plans being auto-parameterized in the green box. The trigger is compiled in the red box and the plan is inserted into the cache as shown by the sp_cache_insert event. Then in the orange box the trigger execution gets a cache hit and reuses the trigger plan for the second INSERT statement in the batch, so it’s not compiling every execution of the INSERT command and the plan does get reused as you can see with the sp_cache_hit event for the trigger.  The uncached_sql_batch_statistics event also fires for the initial batch since it doesn’t have a plan in cache and has to compile.

If we run the two INSERT statements individually again after the first execution the trigger doesn’t compile again as shown in the events below:

Here the first statement encounters a cache hit for the prepared auto-parameterized version of the statement in cache but a miss for the adhoc batch that was submitted. The trigger gets a cache hit and doesn’t compile again as shown in the red block of events. The green block of events repeats this behavior for the second INSERT statement run as a separate batch. However, in every case you still see the query_pre_execution_showplan event firing which I can only attribute to the difference in being optimized vs compiled in the event description, but the trigger isn’t compiling for every execution as shown by these series of events.  The query_post_compilation_showplan event only fires when the plan is actually being compiled for the statements and/or trigger.

Looking at Non-Updating Updates with Extended Events

For a few weeks now, there has been a long running thread on SQL Server Central about UPDATE operations that don't perform any changes because the statement sets a column to the same value as already exists in the row.  While I believe that one of the posters is incredibly snarky and outright rude to the people trying to answer the question and explain the behaviors being noticed, the topic is quite interesting and I finally got some time on my flight to Seattle to take a look at some of the internals of this with Extended Events in SQL Server 2012. 

Setting up the Tests

To setup the tests to be performed I am going to use the example table and row of data that are provided in that thread for the investigation with the exception that I am going to use a user database instead of tempdb for holding the test table so that I can create separate tests for a case-sensitive collation versus case-insensitive collations.

— Create the case-insensitive database
CREATE DATABASE TestUpdate COLLATE SQL_Latin1_General_CP1_CI_AI
GO
USE TestUpdate;
GO
CREATE TABLE Test
(
    ID         INT IDENTITY(1,1) NOT NULL,
    Name    VARCHAR(100) COLLATE SQL_Latin1_General_CP1_CI_AI NOT NULL
);
GO
INSERT dbo.Test
    (Name)
VALUES
    ('Tom');
GO
CHECKPOINT;
GO

— Create the case-sensitive database
CREATE DATABASE [TestUpdateCS] COLLATE SQL_Latin1_General_CP1_CS_AS
GO
USE TestUpdateCS;
GO
CREATE TABLE Test
(
    ID      INT IDENTITY(1,1) NOT NULL,
    Name    VARCHAR(100) COLLATE SQL_Latin1_General_CP1_CS_AS NOT NULL
);
GO
INSERT dbo.Test
    (Name)
VALUES
    ('Tom');
GO
CHECKPOINT;
GO

Then to setup the Extended Events session for collecting information about the operations being performed, we are going to collect a number of events in the engine along with the callstack for each even and the filter on the session_id where the tests are actually being run to prevent collecting data that is not related to the tests being executed.  I originally started with nearly double the events, but removed the events that were not firing for any of the tests from the final event session shown below.

IF EXISTS (SELECT 1 FROM sys.server_event_sessions
            WHERE name = 'SQLskills_InvestigatingUpdates')
BEGIN
    DROP EVENT SESSION [SQLskills_InvestigatingUpdates] ON SERVER;
END
GO
CREATE EVENT SESSION [SQLskills_InvestigatingUpdates]
ON SERVER
— Track sparse file writes for snapshots
ADD EVENT sqlserver.file_written_to_replica(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
— Track memory page allocations
ADD EVENT sqlos.page_allocated(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlos.page_freed(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
— Track latching
ADD EVENT sqlserver.latch_acquire_time(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.latch_suspend_begin(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.latch_suspend_end(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
— Track locking
ADD EVENT sqlserver.lock_acquired(
    SET collect_database_name = 1
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.lock_released(
    SET collect_database_name = 1
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
— Track transaction log activity
ADD EVENT sqlserver.log_flush_requested(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.log_single_record(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.transaction_log(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
— Track batch and statement activity
ADD EVENT sqlserver.sql_batch_completed(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.sql_batch_starting(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.sql_statement_completed(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.sql_statement_starting(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62)))
— Store event data in ring_buffer target
ADD TARGET package0.ring_buffer;
GO

Testing Methodolgy

From the original thread on SQL Server Central, there are a couple of sticking points that keep getting brought up so in the interests of attempting to be thorough I am going to provide the testing methodology being used, and then list all of the tests that are going to be run. 

  1. All tests will be conducted against both of the databases to identify behavior changes between CS and CI collations if they occur. 
  2. At the start of every test, the data in the tables will have 'Tom' for the Name column.  If a previous test has changed the value to something different it will be reset before the test is executed.
  3. The event session will be stopped and started between each test to isolate the data collect to each individual test.
  4. At least one minute of time will be waited for between tests to allow the background thread that performs row version cleanup to execute and remove row versions that may have been created by the tests. (http://msdn.microsoft.com/en-us/library/ms175492(v=sql.105).aspx)
  5. All of the tests will be run once initially to allow the execution plan to be generated and cached in the plan cache, and then the test will be reset and rerun so that the event session doesn't capture the page allocations and locking/latching associated with compiling/caching the plans.

Tests

The tests that will be performed are as follows:

  1. Determine the way that SQL Server handles UPDATE statements that set the column to the same value that previously existed without filtering.

    — Non-updating update
    UPDATE dbo.Test
    SET Name = Name;
    GO

    — Non-updating update
    UPDATE dbo.Test
    SET Name = 'Tom';
    GO

  2. Determine the way that SQL Server handles UPDATE statements that change the value that previously existed without filtering.

    — Updating update
    UPDATE dbo.Test
    SET Name = 'TOM';
    GO

  3. Determine the way that SQL Server handles UPDATE statements that set the column to the same value that previously existed with filtering.

    — Non-Updating with filter
    UPDATE dbo.Test
    SET Name = Name
    WHERE Name != 'Tom';
    GO

    — Non-Updating with filter
    UPDATE dbo.Test
    SET Name = 'Tom'
    WHERE Name != 'Tom';
    GO

  4. Determine the way that SQL Server handles UPDATE statements that change the value that previously existed with filtering.

    — Updating update
    UPDATE dbo.Test
    SET Name = 'TOM'
    WHERE Name != 'TOM';
    GO

All of these tests will be run against the CS and CI database.  Additionally after the first tests are performed against a table without a trigger, the tests will be repeated with the following FOR/AFTER UPDATE trigger on the tables.

CREATE TRIGGER trg_AuditChanges_Test
ON Test
FOR UPDATE
AS
BEGIN
DECLARE @ins INT;
DECLARE @del INT;

SELECT @ins = COUNT(*)
FROM inserted;

SELECT @del = COUNT(*)
FROM deleted;

END
GO

I am not going to include the 16 frame callstack in the results in this post except where it provides useful information for the investigation of the results being collected.  The callstack results in this post will be materialized through the use of Trace Flag 3656 and the public symbols as I explained in my blog post about the callstack action in the XEvent a Day series, An XEvent a Day (24 of 31) – What is the callstack?.

Results No Trigger

For both of the UPDATE statements in test number 1, the following events ( they are identical for both scenarios ) are generated by the event session.  Note that the locks acquired include a conversion of the U lock on the RID to an X lock as a part of the execution,  and even though the UPDATE doesn't actually make any changes, two log records are generated for the BEGIN_XACT and COMMIT_XACT, and these have to also be flushed to the transaction log file, as shown by the log_flush_requested event.

event_namelock_resource_typelock_modestatuslog_op_namecontextdatabase_idresource_0
sql_batch_startingNULLNULLNULLNULLNULLNULLNULL
sql_statement_startingNULLNULLNULLNULLNULLNULLNULL
lock_acquiredOBJECTIXNULLNULLNULL9245575913
latch_acquire_timeNULLNULLHASHED, ONLRUNULLNULLNULLNULL
lock_acquiredPAGEIUNULLNULLNULL9228
lock_acquiredRIDUNULLNULLNULL9228
lock_acquiredPAGEIXNULLNULLNULL9228
lock_acquiredRIDXNULLNULLNULL9228
log_single_recordNULLNULLNULLLOP_BEGIN_XACTNULL9NULL
transaction_logNULLNULLNULLLOP_BEGIN_XACTNULL9NULL
lock_releasedRIDNLNULLNULLNULL9228
lock_releasedPAGENLNULLNULLNULL9228
log_single_recordNULLNULLNULLLOP_COMMIT_XACTNULL9NULL
transaction_logNULLNULLNULLLOP_COMMIT_XACTNULL9NULL
log_flush_requestedNULLNULLNULLNULLNULL9NULL
lock_releasedRIDXNULLNULLNULL9228
lock_releasedPAGEIXNULLNULLNULL9228
lock_releasedOBJECTIXNULLNULLNULL9245575913
sql_statement_completedNULLNULLNULLNULLNULLNULLNULL
sql_batch_completedNULLNULLNULLNULLNULLNULLNULL

If we compare this to the UPDATE statement that actually performs a change to the data in the row from test number 2, we will see that additional log records are generated for the MODIFY_ROW operation, and then flushed to the log file.

event_namelock_resource_typelock_modestatuslog_op_namecontextdatabase_idresource_0
sql_batch_startingNULLNULLNULLNULLNULLNULLNULL
sql_statement_startingNULLNULLNULLNULLNULLNULLNULL
lock_acquiredOBJECTIXNULLNULLNULL9245575913
lock_acquiredPAGEIUNULLNULLNULL9228
lock_acquiredRIDUNULLNULLNULL9228
lock_acquiredPAGEIXNULLNULLNULL9228
lock_acquiredRIDXNULLNULLNULL9228
log_single_recordNULLNULLNULLLOP_BEGIN_XACTNULL9NULL
transaction_logNULLNULLNULLLOP_BEGIN_XACTNULL9NULL
log_single_recordNULLNULLNULLLOP_MODIFY_ROWNULL9NULL
transaction_logNULLNULLNULLLOP_MODIFY_ROWHEAP9NULL
lock_releasedRIDNLNULLNULLNULL9228
lock_releasedPAGENLNULLNULLNULL9228
log_single_recordNULLNULLNULLLOP_COMMIT_XACTNULL9NULL
transaction_logNULLNULLNULLLOP_COMMIT_XACTNULL9NULL
log_flush_requestedNULLNULLNULLNULLNULL9NULL
lock_releasedRIDXNULLNULLNULL9228
lock_releasedPAGEIXNULLNULLNULL9228
lock_releasedOBJECTIXNULLNULLNULL9245575913
sql_statement_completedNULLNULLNULLNULLNULLNULLNULL
sql_batch_completedNULLNULLNULLNULLNULLNULLNULL

For the UPDATE statement in test number 3 where a WHERE clause is applied to check the column value against the value being set to ensure that they are not the same values, the results are different as shown below:

event_namelock_resource_typelock_modestatuslog_op_namecontextdatabase_idresource_0
sql_batch_startingNULLNULLNULLNULLNULLNULLNULL
sql_statement_startingNULLNULLNULLNULLNULLNULLNULL
lock_acquiredOBJECTIXNULLNULLNULL9245575913
lock_acquiredPAGEIUNULLNULLNULL9228
lock_acquiredRIDUNULLNULLNULL9228
lock_releasedRIDUNULLNULLNULL9228
lock_releasedPAGEIUNULLNULLNULL9228
lock_releasedOBJECTIXNULLNULLNULL9245575913
sql_statement_completedNULLNULLNULLNULLNULLNULLNULL
sql_batch_completedNULLNULLNULLNULLNULLNULLNULL

Notice that here we don't have the lock conversion for the RID from U to X, and we don't have the log records being generated and flushed to the transaction log for the BEGIN_XACT and COMMIT_XACT. 

The results for the UPDATE in test number 4 has the same outcome as shown above for test number 3 when run against the case-insensitive collation database.  However, running test number 4 against the case-sensitive collation database results in the same events being fired for the non-filtered UPDATE and data changes in the table with the LOP_MODIFY_ROWS log records being generated. (Feel free to test and validate this using the provided code and CS collation database)

Results FOR/AFTER UPDATE Triggers

The results for the two UPDATE statements in test number 1 when a trigger exists on the table are different than when the table does not have the trigger on it.

event_namelock_resource_typelock_modestatuslog_op_namecontextdatabase_idresource_0
sql_batch_startingNULLNULLNULLNULLNULLNULLNULL
sql_statement_startingNULLNULLNULLNULLNULLNULLNULL
lock_acquiredOBJECTIXNULLNULLNULL10245575913
lock_acquiredPAGEIUNULLNULLNULL10357
lock_acquiredRIDUNULLNULLNULL10357
lock_acquiredPAGEIXNULLNULLNULL10357
lock_acquiredRIDXNULLNULLNULL10357
page_allocatedNULLNULLNULLNULLNULLNULLNULL
log_single_recordNULLNULLNULLLOP_BEGIN_XACTNULL10NULL
transaction_logNULLNULLNULLLOP_BEGIN_XACTNULL10NULL
lock_acquiredEXTENTXNULLNULLNULL21568
lock_releasedEXTENTXNULLNULLNULL21568
page_allocatedNULLNULLNULLNULLNULLNULLNULL
page_allocatedNULLNULLNULLNULLNULLNULLNULL
page_allocatedNULLNULLNULLNULLNULLNULLNULL
page_allocatedNULLNULLNULLNULLNULLNULLNULL
page_allocatedNULLNULLNULLNULLNULLNULLNULL
page_allocatedNULLNULLNULLNULLNULLNULLNULL
page_allocatedNULLNULLNULLNULLNULLNULLNULL
page_allocatedNULLNULLNULLNULLNULLNULLNULL
latch_acquire_timeNULLNULLCHKGEN, DIRTY, HASHED, ONNULLNULLNULLNULL
lock_acquiredEXTENTUNULLNULLNULL2312
lock_acquiredPAGEXNULLNULLNULL2318
lock_releasedEXTENTUNULLNULLNULL2312
lock_releasedPAGEXNULLNULLNULL2318
lock_releasedRIDNLNULLNULLNULL10357
lock_releasedPAGENLNULLNULLNULL10357
latch_acquire_timeNULLNULLCHKGEN, DIRTY, HASHED, ONNULLNULLNULLNULL
log_single_recordNULLNULLNULLLOP_COMMIT_XACTNULL10NULL
transaction_logNULLNULLNULLLOP_COMMIT_XACTNULL10NULL
log_flush_requestedNULLNULLNULLNULLNULL10NULL
lock_releasedRIDXNULLNULLNULL10357
lock_releasedPAGEIXNULLNULLNULL10357
lock_releasedOBJECTIXNULLNULLNULL10245575913
sql_statement_completedNULLNULLNULLNULLNULLNULLNULL
sql_batch_completedNULLNULLNULLNULLNULLNULLNULL

As you can see in the table above, we now have exclusive locks on an extent in tempdb, and memory page allocations occurring (shown by the page_allocated events) in the new result set.  If we take a look at the execution callstack for the page_allocated events, we'll see:

MemoryClerkInternal::AllocatePages+26f [ @ 0+0x0
BPool::Steal+35a [ @ 0+0x0
BPool::NewPage+7af [ @ 0+0x0
PageRef::FormatInternal+8e [ @ 0+0x0
AppendOnlyStorageUnit::SetupPageHeaderPreAllocation+af [ @ 0+0x0
AllocationReq::AllocateExtent+285 [ @ 0+0x0
AllocationReq::AllocateFirst+a9a [ @ 0+0x0
AllocationReq::Allocate+e9 [ @ 0+0x0
AppendOnlyStorageUnit::AllocateNewExtent+29a [ @ 0+0x0
AppendOnlyVerStoreMgr::AddRecord+e07 [ @ 0+0x0
VersionMgr::InsertNewImage+13e [ @ 0+0x0
HeapPageRef::Update+b4e [ @ 0+0x0
HeapFragment::Update+3b7 [ @ 0+0x0
HeapRowObject::Update+67d9 [ @ 0+0x0
HeapDataSetSession::SetDataInternal+8dcb [ @ 0+0x0
DatasetSession::SetData+16d [ @ 0+0x0
RowsetNewSS::SetData+6a [ @ 0+0x0
CValRow::SetDataX+63 [ @ 0+0x0
CEsExec::GeneralEval4+e7 [ @ 0+0x0
CQScanUpdateNew::GetRow+23a [ @ 0+0x0
CQueryScan::GetRow+81 [ @ 0+0x0
CXStmtQuery::ErsqExecuteQuery+36a [ @ 0+0x0
CXStmtDML::XretDMLExecute+2b9 [ @ 0+0x0
CXStmtDML::XretExecute+ad [ @ 0+0x0

By adding the trigger, we now have version store records being generated associated with the execution of the FOR/AFTER UPDATE trigger.  The version store records are also generated for test number 2 where the column data is actually changed by the UPDATE statement being executed.  On the case-insensitive collation, test number 3 and number 4 do not generate version store records.

However, for the case-sensitive collation, test number 4 does generate version store records, as shown below:

event_namelock_resource_typelock_modestatuslog_op_namecontextdatabase_idresource_0
sql_batch_startingNULLNULLNULLNULLNULLNULLNULL
sql_statement_startingNULLNULLNULLNULLNULLNULLNULL
lock_acquiredOBJECTIXNULLNULLNULL10325576198
latch_acquire_timeNULLNULLHASHED, ONLRUNULLNULLNULLNULL
latch_acquire_timeNULLNULLDIRTY, HASHED, ONLRUNULLNULLNULLNULL
lock_acquiredPAGEIUNULLNULLNULL1073
lock_acquiredRIDUNULLNULLNULL1073
lock_acquiredPAGEIXNULLNULLNULL1073
lock_acquiredRIDXNULLNULLNULL1073
log_single_recordNULLNULLNULLLOP_BEGIN_XACTNULL10NULL
transaction_logNULLNULLNULLLOP_BEGIN_XACTNULL10NULL
latch_acquire_timeNULLNULLHASHED, ONLRUNULLNULLNULLNULL
lock_acquiredEXTENTXNULLNULLNULL22944
lock_releasedEXTENTXNULLNULLNULL22944
lock_acquiredEXTENTUNULLNULLNULL2264
lock_acquiredPAGEXNULLNULLNULL2269
lock_releasedEXTENTUNULLNULLNULL2264
lock_releasedPAGEXNULLNULLNULL2269
log_single_recordNULLNULLNULLLOP_MODIFY_ROWNULL10NULL
transaction_logNULLNULLNULLLOP_MODIFY_ROWHEAP10NULL
lock_releasedRIDNLNULLNULLNULL1073
lock_releasedPAGENLNULLNULLNULL1073
log_single_recordNULLNULLNULLLOP_COMMIT_XACTNULL10NULL
transaction_logNULLNULLNULLLOP_COMMIT_XACTNULL10NULL
log_flush_requestedNULLNULLNULLNULLNULL10NULL
lock_releasedRIDXNULLNULLNULL1073
lock_releasedPAGEIXNULLNULLNULL1073
lock_releasedOBJECTIXNULLNULLNULL10325576198
sql_statement_completedNULLNULLNULLNULLNULLNULLNULL
sql_batch_completedNULLNULLNULLNULLNULLNULLNULL

The page_allocated events have the same callstack as the previously listed callstack in this post.

Conclusions

As can be seen by the results of these tests, UPDATE statements that do not actually change the value of a column in a row, can still have overhead associated with them, even when the database engine is recognizes that no change is actually occurring and doesn't actually affect the row on the page.  There is still overhead for the exclusive lock conversion and the implicit transaction that occurs as a part of the UPDATE occurring when no filter is provided to check the value currently on the row against the value being SET, and there is added overhead for row versioning if triggers exist on the table.

Looking at the callstack for the LOP_MODIFY_ROW log operation, we can also see that changes being made affect the specific row on the page.  The changes are NOT made on a separate page allocated by SQL Server to allow a binary comparison of the two pages, as suggested in the original forum thread that lead to this investigation. This is NOT how SQL Server behaves.

SQLServerLogMgr::FireAppendXevent+11b [ @ 0+0x0
SQLServerLogMgr::AppendLogRequest+6d8 [ @ 0+0x0
SQLServerLogMgr::ReserveAndAppend+74 [ @ 0+0x0
XdesRMReadWrite::GenerateLogRec+5ac [ @ 0+0x0

PageRef::ModifyRow+2b4a [ @ 0+0x0


PageRef::ModifyColumnsInternal+162 [ @ 0+0x0

HeapPageRef::Update+208d [ @ 0+0x0
HeapFragment::Update+3b7 [ @ 0+0x0
HeapRowObject::Update+67d9 [ @ 0+0x0
HeapDataSetSession::SetDataInternal+8dcb [ @ 0+0x0
DatasetSession::SetData+16d [ @ 0+0x0
RowsetNewSS::SetData+6a [ @ 0+0x0
CValRow::SetDataX+63 [ @ 0+0x0
CEsExec::GeneralEval4+e7 [ @ 0+0x0

CQScanUpdateNew::GetRow+23a [ @ 0+0x0
CQueryScan::GetRow+81 [ @ 0+0x0

CXStmtQuery::ErsqExecuteQuery+36a [ @ 0+0x0
CXStmtDML::XretDMLExecute+2b9 [ @ 0+0x0
CXStmtDML::XretExecute+ad [ @ 0+0x0
CMsqlExecContext::ExecuteStmts<0,0>+1a71 [ @ 0+0x0
CMsqlExecContext::FExecute+a4f [ @ 0+0x0
CSQLSource::Execute+866 [ @ 0+0x0
CStmtPrepQuery::XretPrepQueryExecute+3e2 [ @ 0+0x0
CMsqlExecContext::ExecuteStmts<1,0>+17c6 [ @ 0+0x0

This is further supported by the fact that no additional page_allocated events fire outside of the version store information being generated by the UPDATE.  Since these tests only focused on the internal operations of UPDATE statements against a single row table, no realistic determination can be made for the actual performance overhead of comparing the column value to the value being SET by the UPDATE statement, specifically for what additional overhead might be incurred by a less ideal execution plan based on the additional filter criteria being optimized.  This is something that I will definitely be looking at in more detail for a possible later post.  However, we can see that comparing the current value to the value being set, can affect row version generation, lock conversions, and the number of log records that are generated where the data would not actually be changed by the UPDATE statement being issued.

Addition:

For further reading on this subject, take a look at Paul Whites blog post from a few years ago.  The outcomes are the same, but he uses a different method of investigation