Owin- Slow CompatibleWithModel call

2019-06-01 22:57发布

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.

0条回答
登录 后发表回答