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:
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):
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:
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.