1

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.

Profiler Trace

22
  • 6
    Getting Help With A Slow Query Jun 7, 2021 at 19:22
  • I see nothing in the event logs that indicate an issue. We have not seen blocking either. What is weird in profiler is the 4 seconds between the start of the batch and the start of the SP execution. The code is fast. I don't see anything about compiles in profiler.
    – SteveB
    Jun 7, 2021 at 20:30
  • @SteveB To reinforce the first point of Erik's linked article, you should compare the actual execution plans between a fast and slow execution of the procedure and look for any differences. Furthermore, you should add those execution plans to your post, so we can help point you in the right direction. I actually have a feeling you have something else odd going on here, but execution plans are pretty much essential in most performance troubleshooting questions, and can at the minimum help us rule out the usual if you have a bigger issue going on.
    – J.D.
    Jun 8, 2021 at 3:09
  • Maybe, It can be good idea to consider the Automatic Updates to Statistics option of the database sqlperformance.com/2014/05/sql-performance/auto-stats-effects
    – Esat Erkec
    Jun 8, 2021 at 14:53
  • 1
    Hierarchyid will need to load a library - Microsoft.SqlServer.Types so just possibly the antivirus is interfering? Oct 6, 2021 at 20:10

1 Answer 1

0

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/

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.