0

We are having issues with one of our servers. When executing a stored proc 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.

5
  • 3
  • 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 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 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 – Newman Jun 8 at 14:53
  • Isn't this type implemented in clr, internally? Perhaps issues with the hosting of clr? Just one more thing on the list as potential things... I. e look for appdomain messages and such in the error log. – Tibor Karaszi Jun 8 at 19:57

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.