1

I have this line of code within a request of an ApiController of an Azure Mobile App Web API:

var user = t.TrackDependency(() => context.Users.SingleOrDefault(x => x.Email == loginRequest.Id || x.Name == loginRequest.Id), "GetUser");


Here is the result from Application Insights:

slow web api request

We can see that while the line of code took 2613ms, the actual query call to the database took 190ms. While this is an edge case it happens often enough to get complaining users about slow performance.

The thing is I have no idea where the difference could come from. Note this is not due to a cold start, the app was warm when this exact call happened.

The second line is the actual call to the database endpoint. Before that it is not database related.

ps: the graph is from application insights. They capture the call to the database and I add my onwn data through the TrackDependency method.

UPDATE

Today I got more data thanks to Application Insights sampling (great tool!). Here are the results (this is not the exact request call instance but this is the same problem):

context.Database.CompatibleWithModel long call

It clearly shows that context.Database.CompatibleWithModel(false) is the culprit. It is called by the call to InitializeDatabase of my custom implementation of IDatabaseInitializer. My custom intializer is set at Startup.
I found another unanswered question on SOF with the same issue

Why does it take so long?

InitializeDatabase is not always called and I don't know when it is called and why.

I found another culprit:

EntityConnection.Open waiting time

Now we see that EntityConnection.Open is waiting something. Are there some locks on the connection? So far the call to the database endpoint is still not made so we're still on EntityFramework here.

UPDATE 2

There are two issues in that post:

  • Why is CompatibleWithModel slow? There are many articles about startup time improvements. This is not be adressed in that SOF question.
  • Why is EntityConnection.Open blocking. This is not related to EntityFramework but is general to getting a connection which takes up to 3 seconds if not called within a 5 minutes windows. I raised that problem in a specific post.


Hence there is no more questions in that post which and it could be deleted but may still be useful as an analysis of tracking down lost time in Web Api calls.

Community
  • 1
  • 1
François
  • 3,164
  • 25
  • 58
  • This is server-side? In an API or table controller? How does it get called? What's the latency between mobile app and server? You've not given enough information to diagnose. I suspect that when you do have enough information, you will know where the inefficiency is. It's normally in the LINQ to SQL piece (part of Entity Framework) – Adrian Hall Feb 22 '17 at 22:57
  • Are both the Azure Mobile App and the SQL Database hosted within the same Azure Region? – Chris Pietschmann Feb 23 '17 at 01:27
  • @chris In that exact case no. But the second line duration is the entire call to the database endpoint. When it is in the same region it doesn't take 190ms but more 8ms. The issue is the time before calling the db endpoint. It lies into EF and linq to sql – François Feb 23 '17 at 07:13
  • @AdrianHall It's an Apicontroller and the graph is from application insights on the portal so it's server side. How it's called and latency between app and server is irrelevant IMHO unless explained otherwise – François Feb 23 '17 at 07:14
  • Nice isolation of the problem. Unfortunately, I don't know EF6 or the SQL Server driver well enough to comment here. Azure Mobile Apps does use end to end encryption to the SQL instance where available (which I'm guessing is SQL Azure). – Adrian Hall Feb 23 '17 at 17:31
  • Opened a new narrowed question: http://stackoverflow.com/questions/42422941/entity-framework-6-blocked-time-waiting-for-a-connection – François Feb 23 '17 at 18:00

0 Answers0