3

We've inherited some SQL server 2014 databases, they are running on Azure IaaS. We're getting complaints about performance and trying to get a grip on it. We're starting to look at CPU performance, and run the following test (all tests are running on database machine itself, ie not via network):

SET NOCOUNT ON
DECLARE @Loops INT SET @Loops = 1 
DECLARE @RESULT INT

WHILE @Loops <= 2000000 
BEGIN
    IF COALESCE('123', '456') = '456'  
            SET @RESULT = 1 
    SET @Loops = @Loops + 1   
END

GO

On Production machine, 16 Virtual Processors (20 to 30% busy), we get the following result:

Completes in 3 minutes

On test machine, 4 Virtual Processors (also around 20 to 30% busy) we get the following:

Completes in 1 second

I've tried running a few benchmarks on the production machine, but they don't show any problems, and always show the production machine CPU at least twice as powerful as test machine.

Is there some SQL Server setting that might be configured wrongly? Any idea how to troubleshoot this issue?

Other Infrastructure Information:

  • Both databases have
    • "max degree of parallelism"set to 1
    • "cost threshold for parallelism" set to 5
    • Azure VM storage is Premium SSD (P30)
  • Production (slow) is Standard_D14_v2
  • Test (fast) is Standard_D12_v2
  • Data, temp and logs are separated
  • Data is striped across 3 striped P20 or P30
  • temp on 4 striped P20 or P30
  • log on single P20 or P30

Note the 'problem' database is running always on Availability Group, we are wondering if that may be a factor here.

  • Are both databases using the same compatibility level? Is the Power Plan on both servers set to "High Performance"? – HandyD Feb 26 at 5:26
  • All database have compatibility level=120. Power Plan is set to "High Performance "on both – Patrick Feb 26 at 6:09
3

Rather than focusing on the hardware first, or the availability group even, it would be good to get a handle on what this "query" (test case) is waiting on.

To do that, you could run Paul Randal's script for Capturing wait statistics for a period of time, or sp_BlitzFirst from the open source First Responder's Kit. Or you could just poll sp_WhoIsActive periodically and see what the test query is waiting on in each sample.

Since I'm on 2016, I'm going to use sys.dm_exec_session_wait_stats because it's super easy to do, and it's 11:30 pm and I'm tired.

I ran your test query in SSMS against one of my AG boxes (finished in less than 2 seconds), grabbed the session ID, and then ran this:

SELECT *
FROM sys.dm_exec_session_wait_stats
WHERE session_id = @spid;

The results came out like this:

screenshot of query results

I ran this from a jump box, so that explains the small amount of ASYNC_NETWORK_IO. The other main wait there is SOS_SCHEDULER_YIELD, which makes sense - this was a CPU-bound task getting switched off the scheduler periodically (or maybe missing its quantum, this is a VM and there's other work going on as well including SSAS, AG stuff, production workload, scheduled jobs, etc). And it was only 141 ms during a 2000-ish ms query.

I ran the same test on my local instance, which is barely doing anything other than writing this answer (query finished in 1 second):

another screenshot of query results

There were no significant waits at all.

The wait stats for your benchmark should tell the story in your situation.


Any answer we could give would likely just be speculation without the wait info (maybe there's other CPU load you're not aware of on the "slow server," or the server is experiencing thread exhaustion due to the AG or other queries, or there are "poison waits" like THREADPOOL or RESOURCE_SEMAPHORE, etc).

  • Thanks, great to have somewhat analytic approach here. We don't have dm_exec_session_wait_stats in version 2014 so I try to monitor with sp_WhoIsActive. Run for 60 seconds, and check state, I see CPU returned is 61,651 (presumablyh that's milliseconds). More interesting is status which is constantly with value 'runnable', I guessing this means that the process is losing it's slot on the processor for some reason. – Patrick Feb 26 at 5:55
  • StackExchange won't let me edit comment, but want to add if I bump up the loop count on test instance I see similar behaviour, sp_WhoIsActive is constantly showing status of 'runnable' – Patrick Feb 26 at 6:01
  • Try to analyze with XEvents, in particular sp_sqltrace. Interesting the test (fast) shows waiting on the following: [6sig]6ms=SOS_SCHEDULER_YIELD(1991) | 1ms=LATCH_SH(1) For the prod (slow) database shows no wait events. I don't really understand this, I would expect the results to be reversed. – Patrick Feb 26 at 7:06
2

OK, we've got to the bottom of it. There was an extended event, DYNPERF_AX_CONTEXTINFO, seems part of "Performance Analyzer for Dynamics". Disabling that event and the performance of this artificial testcase on production database is now similar to test database. For reference the problem event is as below:

CREATE EVENT SESSION [DYNPERF_AX_CONTEXTINFO] ON SERVER
ADD EVENT sqlserver.sql_statement_completed(SET collect_statement=(1)
    ACTION(sqlserver.session_id)
    WHERE ([sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N'%select @CONTEXT_INFO =%') AND NOT [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N'%model%')))
ADD TARGET package0.event_file(SET filename=N'C:\SQLTrace\DYNPERF_AX_CONTEXTINFO.xel',max_file_size=(50),max_rollover_files=(10))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_MULTIPLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON)
GO

It looks like the sql_statement_completed event is getting triggered inside the loop. Also interesting that it appears to be the 'like_i_sql_unicode_string' evaluation that seems to be causing the problem rather then the event logging itself.

  • Thanks for sharing that finding. You can mark it as the answer, too. Can you maybe also share the query/view you used to see that event beeing hot? – eckes Feb 26 at 9:59
  • 2
    Sure, I will, I need to wait 20 hours before I can accept. I didn't work through with Support Analyst to identify problem, but apparently they created an Extended Event session identify the problem. Looks like I need to study this Extended Event stuff, looks quite powerful if maybe a bit dangerous in the wrong hands :) – Patrick Feb 26 at 10:06

Your Answer

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

Not the answer you're looking for? Browse other questions tagged or ask your own question.