Don’t Miss a Beat: How Blocking Can Cause Unintended GETDATE() Behaviour

I was working on some SQL Server code recently which needed to check if an event that is logged to a table has completed and perform an action if it had. The way I looked to implement this was to run an agent job every 5 minutes to see if an event had occurred in the last 10 minutes and if so, action it.

The event usually happens once a day and I don’t want to miss when it happens. When writing this seemingly simple code, I realised there are some potential pitfalls with using GETDATE() for this.

The Problem

As stated above, we have a table which records events:

CREATE DATABASE [EventManagement];
GO

USE [EventManagement];
GO

CREATE TABLE dbo.[Event]
(
	Id	INT,
	EventDate DATETIME
);

INSERT INTO dbo.[Event]
VALUES
(1,'2024-09-02T22:06:00'),
(2,'2024-09-02T22:11:00');

We want to perform some action if a new event is created in the table.

The Solution

There are a number of ways to achieve this kind of event monitoring as will be discussed later in the post, however the approach that was chosen as stated above was to run an agent job every 5 minutes to see if an event had occurred in the last 10 minutes and if so, action it.

The query to check if the event has run in the last 10 minutes is below and the SELECT is our “action” (obviously in real life, it was something more useful!)

IF EXISTS 
(
	SELECT	1
	FROM	dbo.[Event]
	WHERE	EventDate >= DATEADD(MINUTE,-10,GETDATE())
)
SELECT 'It happened...';

The Conundrum

Upon writing the query, something that occurred to me was, what happens if the SELECT from the Event table takes a long time to run? Consider the timeline below, which shows our checks taking place every 5 minutes and shows where the events we added to the table happen.

Here, the check that runs at 15 minutes past the hour says “show me all the events that have happened in the last 10 minutes” but it takes 8 minutes to perform that check as it is a slow running query for whatever reason. Will the check that started at 15 minutes past say that the event that happened at 11 minutes past occurred? Remember – it’s checking for events that have happened in the last 10 minutes and so “did this happen in the last 10 minutes” is true for some of its execution time but not all.

The Test

To find out for sure what happens, the answer, as ever, is to test and here I will test two scenarios involving an extended query execution. Firstly, the classic – a blocking situation and secondly a long running query – think bad plan, large table, lack of indexes, resource contention and the plethora of other reasons why a query may run slowly from time to time.

Before we go on, note that as we are working with GETDATE() which returns the system time and I want to re-run these time based tests, I will be using the PowerShell cmdlet Set-Date to change the system time for the purpose of this testing.

Scenario 1

In Scenario 1, the check query will run at 15 minutes past the hour, be blocked for 8 minutes and then complete as per our timeline above. Will the query return the event that happens at 11 minutes past?

My initial assumption was that GETDATE() would be calculated when the plan is compiled at 15 minutes past and therefore it wouldn’t actually matter that the query was blocked – the WHERE clause would be checking for events that have happened since 10 minutes before 15 minutes past and therefore the event would be picked up.

It turns out my assumption was wrong…

To demonstrate what is happening, I’m going to change my check query slightly to return the actual records from the events table rather than doing a conditional check. I’m also outputting the time so we can see when the query executed and completed.

First, for the purpose of demonstration, I’ll change the system time to emulate it being 22:15 – the time the agent job runs. I run this on the SQL Server – not my client.

Stop-Service W32Time;
Set-Service W32Time -StartupType Disabled;
Set-Date "2024-09-02T22:15:00";

The query to return any events in the last 10 minutes is:

SELECT 'The code started at ' + CONVERT(NVARCHAR(20),GETDATE(),120);

SELECT	Id,
        EventDate
FROM	dbo.[Event]
WHERE	EventDate >= DATEADD(MINUTE,-10,GETDATE());

SELECT 'The code completed at ' + CONVERT(NVARCHAR(20),GETDATE(),120);

When I run the code above at 22:15 I get the output:

This is my expected output – we can see the start and end time are the same to the second and there were two events in the last 10 minutes.

However, let’s see what happens if this query gets blocked for 8 minutes. To set up the blocking situation, in another session, we can run this which leaves the transaction open and holds a lock on the table:

BEGIN TRAN
	SELECT 1 FROM dbo.[Event] WITH (TABLOCKX);

I’ll reset the time again so the test is like for like with the above:

Set-Date "2024-09-02T22:15:00";

And then run our check query again in our original session:

SELECT 'The code started at ' + CONVERT(NVARCHAR(20),GETDATE(),120);

SELECT	Id,
        EventDate
FROM	dbo.[Event]
WHERE	EventDate >= DATEADD(MINUTE,-10,GETDATE());

SELECT 'The code completed at ' + CONVERT(NVARCHAR(20),GETDATE(),120);

We can see that our event check query gets blocked as confirmed below in sp_whoisactive

After 8 minutes we can rollback or commit the transaction in the session that is holding the lock and the SELECT will complete:

We can see that the query started at 22:15:18 and ran until 22:23:21 but it didn’t return the event that was less than 10 minutes before the start time – why?

If I get the estimated plan for this query:

SELECT	Id,
        EventDate
FROM	dbo.[Event]
WHERE	EventDate >= DATEADD(MINUTE,-10,GETDATE());

We can see in black and white in the plan that SQL Server is using GETDATE() as a predicate:

The plan is compiled by the query optimizer when the query is executed (assuming it is not using a cached plan) and the storage engine retrieves data as per that plan at runtime. When the query is blocked, the runtime is deferred until the offending lock is released, at which point, the storage engine executes the plan which states GETDATE() is the predicate. If it worked the way I initially thought:

My initial assumption was that GETDATE() would be calculated when the plan is compiled at 15 minutes past and therefore it wouldn’t actually matter that the query was blocked

The literal date / time as at compile time would have shown as the predicate in the execution plan and if that were the case, the plan would be invalid for re-use as that time exists only once.

It seems obvious now but good to have clarified!

In my real world use case, this is not the behaviour I wanted – I am checking whether some event has happened on a routine basis and I want to do something when it has. Even though I am checking every 10 minutes, in my scenario it was more important to know the event has happened, even if there is a delay in catching that it happened.

Scenario 2

In Scenario 2, the query runs a long time for some reason other than blocking – lack of appropriate index, server CPU or memory pressure etc. For the purpose of easily simulating such a scenario, I have created a useless and terrible scalar UDF which goes and scans the entire StackOverflow Database Posts table numerous times (the StackOverflow database is provided under cc-by-sa 4.0 license from Stack Exchange Data Dump) (to be absolutely clear – THIS IS ABSOLUTELY TERRIBLE ON PURPOSE!) My testing machine is SQL Server 2022 on a VM with 8 cores and 35GB RAM, I spent a fair amount of time tweaking the below to ensure an 8 minute runtime!

CREATE OR ALTER FUNCTION dbo.udf_slow()
RETURNS NVARCHAR(MAX)
AS
BEGIN
	DECLARE @txt NVARCHAR(MAX);
	SELECT	TOP 300000000 @txt = p1.Body + p2.Body + p3.body + p4.body
	FROM	StackOverflow.dbo.Posts p1
			CROSS JOIN StackOverflow.dbo.Posts p2
			CROSS JOIN StackOverflow.dbo.Posts p3
			CROSS JOIN StackOverflow.dbo.Posts p4
	RETURN @txt;
END;

I’ll reset the clock again for the sake of the test:

Set-Date "2024-09-02T22:15:00";

and I’ll add the UDF to my check query so that it runs slowly:

SELECT 'The code started at ' + CONVERT(NVARCHAR(20),GETDATE(),120);

SELECT	Id,
        EventDate,
	    dbo.udf_slow()
FROM	dbo.[Event]
WHERE	EventDate >= DATEADD(MINUTE,-10,GETDATE());

SELECT 'The code completed at ' + CONVERT(NVARCHAR(20),GETDATE(),120);

Now let’s run the query (and go for tea / coffee / sleep / a shopping trip)

Here, we see different behaviour to Scenario 1 – the query ran for a similar amount of time but returned the Event records.

The reason for this is that in the same way as happened in Scenario 1, once the query started to execute, GETDATE() was evaluated at that time but the difference in this scenario is the query started executing straight away vs Scenario 1 where it took 8 minutes to actually start because of the block, the length of time it took is irrelevant really as the value of GETDATE() was evaluated once the query started executing.

This behaviour is fine for what I needed so I just needed a solution to the blocking issue.

The Options

So I was in the situation where a long execution still returned the results I wanted but if the query is blocked it may miss an event. How can we fix the query so I get my desired behaviour when the query is blocked?

Option 1

I could pick a longer time window as a lookback period in the query, using a period for which we are less likely to see a query blocked. There is always a possibility, however, that it could be blocked for that long.

Option 2

We could snapshot the current time when the query starts executing by using a variable:

SELECT 'The code started at ' + CONVERT(NVARCHAR(20),GETDATE(),120);

DECLARE @TheTime DATETIME = DATEADD(MINUTE,-10,GETDATE());

SELECT	Id,
        EventDate
FROM	dbo.[Event]
WHERE	EventDate >= @TheTime;

SELECT 'The code completed at ' + CONVERT(NVARCHAR(20),GETDATE(),120)

Now, when the query is blocked we can see that results are returned for the check despite the wait to execute:

Option 3

A more robust option would be to log the last event that was acted upon to a tracking table and check for events since that time, Query outputalternatively, we could add a column to the event table to show that the event has been actioned. Going back to our original check query, this would look something like:

Creation of the tracking table which we will use to store the last time we acted on an event:

CREATE TABLE dbo.LastEventAction
(
     EventActionDate DATETIME
);
INSERT INTO dbo.LastEventAction VALUES ('1900-01-01T00:00:00');

And our check query should now log that it has taken action:

IF EXISTS 
(
	SELECT	1
	FROM	dbo.[Event]
	WHERE	EventDate >= (SELECT EventActionDate FROM dbo.LastEventAction)
)
BEGIN
SELECT 'It happened...';
UPDATE LastEventAction SET EventActionDate = GETDATE();
END

or mark the events as actioned, which means adding a column to our Event table:

/* add the column */
ALTER TABLE dbo.Event ADD Actioned BIT;

/* we have actioned everything so far */
UPDATE dbo.Event SET Actioned = 1;

The check query would look like this:

IF EXISTS 
(
	SELECT	1
	FROM	[Event]
	WHERE	Actioned = 0
)
BEGIN
	SELECT 'It happened...';
	UPDATE [Event] SET Actioned = 1
	WHERE	Actioned = 0;
END

Option 4

We could implement an AFTER INSERT trigger on the Event table which performs the action for us:

CREATE OR ALTER TRIGGER trg_DoAction ON [Event]
AFTER INSERT
AS
BEGIN
	IF EXISTS
	(
		SELECT	1
		FROM	inserted
		WHERE	EventDate IS NOT NULL
	)
	SELECT 'It happened...';
END;

which will perform the action immediately after the event happens (i.e, when the event is committed into the table)

In my case, the code I was implementing was a short term sticking plaster fix for something so database changes seemed a little excessive and sometimes can cause extra process (source control / change control etc) so I settled for Option 2 – the variable, however, had it not been for these constraints, I would go with the trigger.

I hope you learned something here – I know I did!

Conclusion

In this post, we have looked at a scenario where SQL Server’s handling of GETDATE() behaved differently to what I initially expected. The key takeaway is that GETDATE() is evaluated at query execution time, not at plan compilation time. This distinction is irrelevant when a query runs normally, but becomes significant when a query is blocked — because blocking delays execution, meaning GETDATE() is evaluated later which could have an impact on query logic / intent. We looked at some solutions to resolve the issue of the code returning unexpected results when blocked.