UserManager.FindById is slow

Question

I using this code (where context is OAuthGrantCustomExtensionContext):

var userManager = context.OwinContext.GetUserManager<ApplicationUserManager>();
ApplicationUser appUser1 = await userManager.FindByIdAsync("My user id"); // 31 seconds to execute
ApplicationUser appUser2 = await userManager.FindByIdAsync("My user id"); // 1 milisecond to execute

The execution of the function FindByIdAsync takes 31 seconds on the first time. On the second execution it's takes only <1 MS. I also checked how fast is my DB by running a "SELECT... WHERE..." query - and it's really fast - <1 MS.

I also noticed in this output inside the "Output Window":

Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll The thread 0x1598 has exited with code 0 (0x0). Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.Entity.Infrastructure.RetryLimitExceededException' in EntityFramework.dll 'iisexpress.exe' (CLR v4.0.30319: /LM/W3SVC/6/ROOT-1-131126169736320764): Loaded 'EntityFrameworkDynamicProxies-EntityFramework'. Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.SqlClient.SqlException' in System.Data.dll Exception thrown: 'System.Data.Entity.Core.EntityCommandExecutionException' in EntityFramework.dll Exception thrown: 'System.Data.Entity.Core.EntityCommandExecutionException' in EntityFramework.dll Exception thrown: 'System.Data.Entity.Core.EntityCommandExecutionException' in EntityFramework.dll Exception thrown: 'System.Data.Entity.Core.EntityCommandExecutionException' in EntityFramework.dll 'iisexpress.exe' (CLR v4.0.30319: /LM/W3SVC/6/ROOT-1-131126169736320764): Loaded 'EntityFrameworkDynamicProxies-ObjectModelLayer'. 'iisexpress.exe' (CLR v4.0.30319: /LM/W3SVC/6/ROOT-1-131126169736320764): Loaded 'EntityFrameworkDynamicProxies-Microsoft.AspNet.Identity.EntityFramework'.

The output above is collected from the time my machine executed this line:

ApplicationUser appUser1 = await userManager.FindByIdAsync("My user id");

In the other lines of code, the Output Window was empty. (which can explain why they was so fast).

As you can see, alot of SqlException are thrown while this code line. It's seems to me like a "retry" mechanism that try agian and agian to execute some logic but it failed. I woundering if this is the reason why this taking so long?

I looking for:

1. Way to see exectly what is this SqlException? maybe I'll fix this and this code will run faster.
2. How to fix the FindByIdAsync to make it work fast (<5 seconds) every time?

Thank you for support!

UPDATE

I found a useful way to catch first chance exceptions. With this code:

AppDomain.CurrentDomain.FirstChanceException +=
(object source, FirstChanceExceptionEventArgs e) =>
{
    Console.WriteLine("FirstChanceException event raised in {0}: {1}", AppDomain.CurrentDomain.FriendlyName, e.Exception.Message);
};

So, I ran the code and collected the thrown exceptions. Got the following exception for 18 times:

The server principal "XXX" is not able to access the database "master" under the current security context. Database 'master' on server 'XXX.net' is not currently available. Please retry the connection later. If the problem persists, contact customer support, and provide them the session tracing ID of 'XXXXXXX-68E9-4FDD-9E3D-92BE27438835'. Login failed for user 'XXX'.

My user is really not allowed to access the "master" table. So, it's make sense. I change my DB connection string to another user with permission to access the "master" table - and now it's working fast! (less then 3 seconds).

After giving the right permissions, I still got this exception in the log (for 7 times):

Invalid object name 'dbo.EdmMetadata'.

Questions:

1. I don't understand why the function FindByIdAsync need to access the master table???
2. How to fix the error "Invalid object name 'dbo.EdmMetadata'."?

Answer 1

6 years later, I am still getting similar behavior with the latest libraries for Identity and Entity-Framework. The first call to userManager.Get[Something] takes about 5 seconds; subsequent calls are 3-10 milliseconds. Could it be that Identity is trying to check/recreate the underlying database on the first call?