Delayed execution of code - possible cache issue

Question

We are having issues with one of our servers. When executing multiple stored procs it can take seconds to return data. Sometimes it is milliseconds. I don't think it is a parameter sniffing issue as it happens with multiple stored procs.

1. When I ran whoisactive during one of these calls I get no wait stats for it.
2. When I look in QueryStore for the proc the stats that it is millisecond fast.
3. When I run sp_BlitzFirst it does show that we have excessive compilations but they seem to be around table variables and temp tables.
4. When running the proc in SSMS with STATISTIC_IO, TIME ON it reports that it only worked for a few milliseconds but the elapsed time was 1463 milliseconds.

SQL Server parse and compile time: CPU time = 0 ms, elapsed time = 1 ms.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 0 ms. Table '#TempTable______________________________________________________________________________________________000000C6E4C1'. Scan count 0, logical reads 7, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0. Table 'Worktable'. Scan count 2, logical reads 44, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 1 ms.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 0 ms. SQL Server parse and compile time: CPU time = 0 ms, elapsed time = 0 ms. Table 'RealTable'. Scan count 7, logical reads 63, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0. Table '#TempTable______________________________________________________________________________________________000000C6E4C1'. Scan count 1, logical reads 1, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 1 ms.

SQL Server Execution Times: CPU time = 0 ms, elapsed time = 1463 ms.

I ran profiler to see what was happening between SQL Server and my machine. I called the SP at 12:51:43.080 and I see "Select @@SPID" happening in 0 milliseconds. Then I see the SP being call with a SQL:BatchStarting and SQL:StmtStarting both at 12:51:43.087. I then get a SP:Starting for the SP at 12:51:47.357. That's 4 seconds to actually start. What is going on in between? The statements in the SP only take 3 milliseconds to run.

I'm kinda at a loss here. Any ideas on where to look next?

Edit: Here's the server info.

Priority 250: Server Info:

• Data Size - 4 databases, 1492.38 GB total file size

• Default Trace Contents - The default trace holds 15 hours of data between Jun 7 2021 12:18AM and Jun 7 2021 3:10PM. The default trace files are located in: C:\Program Files\Microsoft SQL Server\MSSQL15.MSSQLSERVER\MSSQL\Log

• Drive C Space - 16.40 GB free on C drive out of 49.40 GB total (66.79%)

• Drive D Space - 284.29 GB free on D drive (Data) out of 1,638.38 GB total (82.65%)

• Drive L Space - 95.44 GB free on L drive (Logs) out of 249.98 GB total (61.82%)

• Drive T Space - 0.78 GB free on T drive (TempDB) out of 199.98 GB total (99.61%)

• Hardware - Logical processors: 24. Physical memory: 320GB.

• Hardware - NUMA Config

• Node: 0 State: ONLINE Online schedulers: 6 Offline schedulers: 0 Processor Group: 0 Memory node: 0 Memory VAS Reserved GB: 1172

• Node: 1 State: ONLINE Online schedulers: 6 Offline schedulers: 0 Processor Group: 0 Memory node: 0 Memory VAS Reserved GB: 1172

• Node: 2 State: ONLINE Online schedulers: 6 Offline schedulers: 0 Processor Group: 0 Memory node: 1 Memory VAS Reserved GB: 0

• Node: 3 State: ONLINE Online schedulers: 6 Offline schedulers: 0 Processor Group: 0 Memory node: 1 Memory VAS Reserved GB: 0

• Locked Pages In Memory Enabled - You currently have 294 GB of pages locked in memory.

• Memory Model Unconventional - Memory Model: LOCK_PAGES

• Operating System Version - You're running Windows Server 2019 Datacenter, version 10.0

• Power Plan - Your server has 3.49GHz CPUs, and is in high performance power mode

• Server Last Restart - May 10 2021 2:36PM

• SQL Server Last Restart - May 10 2021 2:36PM

• SQL Server Service - Version: 15.0.4083.2. Patch Level: RTM. Cumulative Update: CU8. Edition: Enterprise Edition: Core-based Licensing (64-bit). Availability Groups Enabled: 1. Availability Groups Manager Status: 1

• Virtual Server - Type: (HYPERVISOR)

UPDATE: We narrowed down what seems to be causing the delayed stored procedure execution in the SP we are testing with. One of the parameters is a HierarchyID. Most of the time when calling this SP and passing in the HierarchyID we see a delay of anywhere between 1 and 7 seconds BEFORE the stored proc STARTS executing. I know people want the execution plan but the plan is the same when it runs quickly or when it is delayed. It doesn't seem to be the plan. It literally looks like it is having a hard time looking in the plan cache for the plan or like it wanted to compile, taking a long time, each time it runs. We changed the parameter to be a varchar instead and the SP executes immediately. Of course this means we have to deal with an implicit conversion from varchar to HierarchyID.

• When trying to view the plan SQL Sentry it says a query plan can't be collected some of the time. However, when the SP runs quickly, it can collect a plan. This is what led us to investigate the parameter issue.
• This server is in an AG (sorry I didn't mention that earlier) and the issue did not exist on the read only replica.
• We did try freeing the proc cache to see if that was the issue with accessing the plan but it did nothing. Like I said, we were reaching for straws.

We have seen an issue somewhat like this before (slightly different symptoms) and as much as I hate to admit it we rebooted the server and the issue seemed resolved. We chalked it up to a one time thing. Unfortunately we have some highly visible work happening this morning so we didn't have time to research further or contact MS for help. Because of that, I rebooted the server and the issue seems resolved again. If the issue happens again we will get MS involved.

EDIT: I know everyone wants the query plans but we have examined the plans and these queries are simple. The problem revolves around the HieracrhyID data type. We have opened a case with MS but I thought I'd update the question for even more help. Here's a better way that shows the problem.

We have a user defined table type which is used to pass lists to stored procedures.

CREATE TYPE [DV].[NodeList] AS TABLE(
    [NodePath] [hierarchyid] NOT NULL
)

We then insert values into a variable of this type to pass to the SP.

declare @p1 DV.NodeList
insert into @p1 values(N'/5/65/12/3/1/')
insert into @p1 values(N'/5/65/14/1/1/')

This code should run in a few milliseconds. It took 26 seconds. It gets worse with more inserts. I did capture a profiler trace while running it. Look at the start and end times. Crazy.

Answer 1

Well. It's been fun working on this. I worked with MS for 4 months and we believe we have the answer. And yes, it's my fault. Thank you all for your suggestions.

Stephen Morris - Mo64 - You were on the right track. HierarchyID does load a library and that's where the problem was. I had over allocated memory for SQL. I gave SQL Server 302 of 320GB of the memory. We lowered the memory for SQL and the issue immediately resolved. We will monitor to ensure this is the solution but it seems right. Here's the wrap up from Collin at MS.

• In the WPR traces collected when the issue was reproduced we can see in the code path leading to use of hierarchyid. In the WPR traces when the issue wasn’t reproduced, we don’t see that code path.
• In the PerfMon data we can see that there is ~6.75GB available memory. The machine has a total of 320GB. That is approximately 2% available. I don’t know the exact logic that determines when Windows will start paging or trigger memory pressure notifications, but I suspect that threshold has been crossed.
• The PerfMon data does clearly show that there was paging going on,
• In that capture, SQL Server was utilizing ~302GB of memory, of which only ~2GB (0.66%) was in the working set and therefore eligible to be paged.
• I see in the SQL Server code path that the buffer created to hold the assembly needed to leverage hierarchyid is allocated without first reserving AWE allocation (see VirtualAlloc function (memoryapi.h) - Win32 apps | Microsoft Docs). It’s therefore part of that 0.66% eligible for paging.

I am looking to use the values indicated by Jonathan Keyayias in this article going forward. https://www.sqlskills.com/blogs/jonathan/how-much-memory-does-my-sql-server-actually-need/