Just setup New Relic on our site and we noticed some odd spikes in one of our webapi calls.
At this point I have the problem boiled down to a single EF query that I moved out to its own method so I could use New Relic to instrument it..
The only thing the method does is
//I changed this from ToListAsync to ToList to see if it would help
var result = Context.Data.Where(x=> x.id = id).ToList();
return result;
That's it..
Using New Relic and also logging out all the SQL queries I'm fairly positive the issue isn't with the query being slow. New Relic says the method is only spending an average of 339 ms running against the DB and I see similar numbers from the trace data coming from EF. But the methods average execution time is 16 seconds.
Normally this method executes in under 2 seconds but every so often EF just seems to go off into lala land and it takes 60 or 70 seconds to finish whatever it's doing. But I've never seen the DB query itself take longer then 500 ms. And the query is retrieving pretty much the exact same dataset every time it runs..
I noticed in the logs that the long wait time was always between executing the query and closing the connection.. Here's an example output from the logs
- Application: 2015-02-17T10:04:11 PID[3556] Information -- Completed in 6 ms with result: SqlDataReader Application: Application:
- 2015-02-17T10:04:11 PID[3556] Information Application: Application:
- 2015-02-17T10:04:22 PID[3556] Information Closed connection at 2/17/2015 10:04:22 AM +00:00
Notice the completion time is 6 ms but then there's a 11 second lag before getting to close connection
- I've tried removing async for this call but it doesn't help
- I tried using ConfigureAwait(false) on everything to see if it's some issue with trying to return to the original context
- I've tried manually managing the connection myself.. So opening at the very beginning then closing at the very end
This can't be from load because right now there's literally 2 users beta testing the Azure site... So the load is pretty much non existent.
I've tried to recreate this locally but haven't been able to... And I'm not really sure where to go from here debugging the issue besides slowly gutting the EF parts for something simpler like Dapper to see if that behaves more consistently.
Technology Stack:
- Sql Azure
- Azure websites scaled up to two instances
- EF 6 Async features
- web api
