9

I am running an Azure SQL database under the S2 edition (50 DTUs). Normal use of the server usually hangs around 10% DTU. However, this server regularly gets into a state where it will send DTU usage of the database to 85-90% for hours. Then all of a sudden it goes back down to the normal 10% usage.

enter image description here

Queries against the server from the application still seem to be operating quickly during this overloaded state.

I can scale the server from S2 => anything (S3 for example) => S2 and it seems to clear out whatever state it is hung in. But then a few hours later it will again repeat the same overloaded state cycle. Another weird thing I've noticed is that if I run this server on an S3 plan (100 DTU) 24/7 I have not observed this behavior. It only seems to occur when I have downscaled the database to an S2 plan (50 DTU). On the S3 plan I am always sitting at 5-10% DTU usage. Obviously underutilized.

I've checked into Azure SQL query reports looking for rogue queries, but I don't really see anything unusual and it shows my queries using resources as I would expect.

enter image description here

As we can see here though, the usage is all coming from Data IO. If I change the performance report here to show top Data IO queries by MAX, we see this:

enter image description here

Looking at these long running quires seems to point to statistics updates. Not really anything running from my application. For example, query 16302 there shows:

SELECT StatMan([SC0], [SC1], [SC2], [SB0000]) FROM (SELECT TOP 100 PERCENT [SC0], [SC1], [SC2], step_direction([SC0]) over (order by NULL) AS [SB0000]  FROM (SELECT [UserId] AS [SC0], [OrganizationId] AS [SC1], [Id] AS [SC2] FROM [dbo].[Cipher] TABLESAMPLE SYSTEM (1.250395e+000 PERCENT) WITH (READUNCOMMITTED) ) AS _MS_UPDSTATS_TBL_HELPER ORDER BY [SC0], [SC1], [SC2], [SB0000] ) AS _MS_UPDSTATS_TBL  OPTION (MAXDOP 16)

But then again, the report also shows that these queries are only using a small percentage of the Data IO usage on the server (< 4%). I also run statistics updates (and index rebuilds) on the entire database on a weekly basis as part of its regular maintenance.

Here is another report that shows MAX data IO queries for a timespan that covers several hours only during the high-resource-usage incident.

enter image description here

As we can see, not really any queries reporting significant data IO usage.

I have also ran sp_who2 and sp_whoisacive on the database and do not really see anything jumping out at me (though I will admit I am not an expert with these tools).

How do I figure out what is going on here? I don't think any of my application queries are to blame for this resource usage and I get the feeling that there is some internal process running in the background on the server that is killing it.

  • So you're seeing that there are update stats running, which naturally is going to have some decent I/O cost associated, right? If that query is 4% of the total IO for over the course of 24 hours do you think it could still be a contributor to the spikes you see in the graph? I'd be hesitant to use the word "overloaded" when you're not maxing out your DTU and your query performance is still acceptable, as well. Why is it an issue that the server is utilizing its resources differently over time? – LowlyDBA Apr 30 '18 at 16:20
  • @LowlyDBA I am not sure how I could validate that the query is what is causing this. When it is only showing 4% usage I would not think that would lead to nearly 100% usage of the overall DTU threshold. There is a lot of usage unaccounted for here. Basically I am trying to figure out why this is happening. The constant hours-long spikes are putting the server very near 100%, and as mentioned this doesn't seem to happen at all when I double the DTU resources available (S3 plan). – kspearrin Apr 30 '18 at 16:29
  • Remember DTU isn't just I/O, it is also CPU and memory. So comparing the two probably isn't a helpful metric. What does the query performance insight tool give you for a visual breakdown of resources in a smaller window (just the hours you see the spike)? – LowlyDBA Apr 30 '18 at 16:36
  • @LowlyDBA The report screenshots I have posted above seem to clearly indicate the the resources are all coming from Data IO. CPU and Log IO are not really much of a factor. For example, looking at queries by Max CPU% only points to the largest offender using just 2% over several hours while the problem is occurring. Screenshot: imgur.com/rxyMLc9 – kspearrin Apr 30 '18 at 16:37
  • 1
    @DirkBoer In our case, this seems related to statistics aggregate queries running on the server. We turned off automatic statistics on certain tables to help resolve the problem. – kspearrin May 27 at 12:22
1

Given that during the spike(s) your log activity is minimal we can assume there isn't any (or much) DUI going on.

You mention at one point that the spike doesn't affect performance, and at another that it does. Which is it?

You also mention that this goes away after a scale operation. This makes sense as it's analogous to an on-premise restart which will effectively kill all processes etc.

Do I assume correctly in guessing that this database is being accessed from the application-tier? If so, I suspect that your connections are not being closed properly. The garbage collector is supposed to take care of these eventually (which shouldn't be relied upon), but I've seen this exact situation occur because of unclosed connections from the app-tier. In our case, the application was so busy that we eventually received concurrent connection errors which is what lead us to the problem.

Try the following query during the spike:

SELECT
    c.session_id, c.net_transport, c.encrypt_option,
    s.status,
    c.auth_scheme, s.host_name, s.program_name,
    s.client_interface_name, s.login_name, s.nt_domain,
    s.nt_user_name, s.original_login_name, c.connect_time,
    s.login_time
FROM sys.dm_exec_connections AS c
JOIN sys.dm_exec_sessions AS s
    ON c.session_id = s.session_id
ORDER BY c.connect_time ASC

If I'm correct, you'll find a whole bunch of records returned with the status of Sleeping, or worse Running. If that's the case you have even bigger problems in the app-tier.

We can further debug this by copying the database, using the following query (using basic tier to avoid excessive costs), and monitoring for this behaviour.

CREATE DATABASE Database1_copy AS COPY OF Database1 ( EDITION = 'basic' );
  • 1
    Yes, the database is accessed from an application tier, but as far as I can tell all connections are properly wrapped in using statements. The info I posted in the original question seems to indicate that data IO is responsible for the spikes. – kspearrin Jun 9 '18 at 17:08
  • 1
    @pimbrouwers : Can you explain specifically why a connection in a state of sleeping / running is bad? My understanding of connection pooling was that the connections could be in such a state as part of normal operation. – obaylis Jan 21 at 9:31

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.