I have an intermittent issue that I can't seem to get to the bottom of whereby a .NET Framework 4.6 MVC API (C#) uses an Entity Framework 6 (runtime v4.0.30319) stored procedure call that takes a long time to respond.
The stored procedure is hosted on Azure SQL DB.
It is an unremarkable procedure, it interrogates a couple of tables to give a nutritionist their clients' latest data and website interactions.
ALTER PROCEDURE [PORTAL].[GetNutritionistCustomers]
@id_usernut varchar(20)
AS
WITH Activity AS (
SELECT LastActivity = MAX(ExecutionDate),
ded.UserName
FROM portal.DailyExecutionData ded
WHERE ded.ExecutionDate < GETDATE()
GROUP BY ded.UserName
),
Logging AS (
SELECT LastLogin = MAX(l.LoggedOnDate),
l.UserName
FROM PORTAL.Logins l
WHERE l.LoginType = 'Direct Client'
GROUP BY l.UserName
)
SELECT unc.CompanyCode,
a.ACCOUNT,
ad.ADDRESS1,
un.ID_UserNut,
ueu.ExpirationDate,
Expired = CAST(CASE WHEN ueu.ExpirationDate < GETDATE() THEN 1 ELSE 0 END AS BIT),
LastActive = la.LastActivity,
l.LastLogin
FROM UK_Nutritionist un
JOIN UK_NutCompany unc ON un.ID_UserNut = unc.ID_UserNut
JOIN UK_EnabledUsers ueu ON unc.CompanyCode = ueu.UserName
JOIN Klogix.ACCOUNT a ON ueu.ID_User = a.ACCOUNTID
LEFT JOIN Klogix.ADDRESS ad ON a.ADDRESSID = ad.ADDRESSID AND ad.IsPrimary = 1
LEFT JOIN Activity la ON ueu.UserName = la.UserName
LEFT JOIN Logging l ON ueu.UserName = l.UserName
WHERE un.ID_UserNut = @id_usernut
Run in SSMS or ADS this procedure takes on average about 50-100ms to complete. This is consistent, the tables are well indexed and the query plan is all index seeks. There are no Key or RID lookup red flags.
Having investigated with profiler, I've determined that what happens is EF creates a connection, calls the procedure. I can see the RPC entered, EF reaches it connection timeout period, and then we get RPC completed, and the data returns to EF, and the code spins out a list of pocs to return to the caller in json.
[HttpGet]
[Route("Customers")]
public HttpResponseMessage Get()
{
try
{
if (IsTokenInvalid(Request))
return Request.CreateResponse(HttpStatusCode.Unauthorized);
var nutritionistCustomers = new ExcdbEntities().GetNutritionistCustomers(TokenPayload.Nutritionist).Select(x => new NutritionistCustomers()
{
Account = x.ACCOUNT,
Address = x.ADDRESS1,
CompanyCode = x.CompanyCode,
ExpirationDate = x.ExpirationDate,
expired = x.Expired,
LastActive = x.LastActive,
LastLogin = x.LastLogin
}).ToList();
return Request.CreateResponse(HttpStatusCode.OK, GenerateResponse(nutritionistCustomers))
}
catch (Exception e)
{
return Request.CreateResponse(HttpStatusCode.InternalServerError, GenerateResponse(e));
}
}
If I change the timeout on the connection then the amount of time that SQL waits before releasing the data changes.
I thought it might be something to do with the Azure app service that hosts the API, but it turns out that running it in debug in Visual Studio has the same issue.
The short term fix is to recompile the stored procedure. This will then return the data immediately. But at some undetermined point in the future the same procedure will suddenly manifest this behaviour again.
Only this procedure does this, all other EF interactions, whether linq to sql table or view interrogations, and all other procedures seem to behave well. This has happened before in a now legacy system that had the same architecture, though it was a different procedure on a different database.
Whilst shortening the timeout is a workaround, it's a system wide value, and even 10 seconds, enough to cope with system hiccouphs, is way too long for this customer selection screen, which should be instantaneous. Also I would rather fix the underlying problem, if anyone has any clue what might be going on.
I have considered an OPTION_RECOMPILE on the statement, but it just feels wrong to do so.
If anyone else has experienced this and has any insight I'd be most grateful is it's driving me to distraction.
CodePudding user response:
For an as yet unknown reason, there is an uncommitted transaction against one of the tables in the query when this issue arises. Whilst SSMS doesn't care using its default context settings, the context settings that EF sets up means the execution is waiting on a lock release. I'm not sure I understand why this returns when the EF connection times out. Perhaps it's just a coincidence, or not.
Either way changing the transaction isloation setting in the sproc compilation context, or indeed putting (NOLOCK) hints on the select statement resolves the immediate problem.
Though of course discovering the reason for the uncommitted transaction is more important.
Obviously talking to myself is the story of my life, the burden of the geek, it's why I dont go to parties.