MemberService.SetLastLogin creates blocks and deathlocks on umbracoPropertyData

mcl-sz commented 2 years ago

Which exact Umbraco version are you using? For example: 9.0.1 - don't just write v9

8.18.4

Bug summary

It looks like the SetLastLogin function is causing blocking on the umbracoProperyData table. This causes in particular listviews to become slow or give timeouts.

Specifics

We found out that the query thats giving the trouble is:

/* (comment inserted by DPA)
Character Range: 69 to 743
Waiting on statement: 

UPDATE [umbracoPropertyData] 
   SET [umbracoPropertyData].[dateValue]=@0  
WHERE ([umbracoPropertyData].[id] IN 
   (
   SELECT [umbracoPropertyData].[id] AS [Id] 
   FROM [umbracoPropertyData] 
   WITH 
      (
         UPDLOCK
      ) 
   INNER JOIN [cmsPropertyType] 
   ON ([cmsPropertyType].[id] = [umbracoPropertyData].[propertyTypeId]) 
   INNER JOIN [umbracoContentVersion] 
   ON ([umbracoContentVersion].[id] = [umbracoPropertyData].[versionId]) 
   INNER JOIN [umbracoNode] 
   ON ([umbracoNode].[id] = [umbracoContentVersion].[nodeId]) 
   INNER JOIN [cmsMember] 
   ON ([cmsMember].[nodeId] = [umbracoNode].[id]) 
   WHERE (([umbracoNode].[nodeObjectType] = @1)) 
  AND (([cmsPropertyType].[Alias] = @2)) 
  AND (([cmsMember].[LoginName] = @3))
   ))

We are receiving the following error messages:

2022-08-17 09:22:17.413 +02:00 [Error] Exception ("cffeaa55"). System.Data.SqlClient.SqlException (0x80131904): Transaction (Process ID 114) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction. at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action 1 wrapCloseInAction) at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted) at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource 1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource 1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) at System.Data.SqlClient.SqlCommand.ExecuteNonQuery() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func 1 func) in D:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172 at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd) at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args) at Umbraco.Core.Persistence.Repositories.Implement.MemberRepository.SetLastLogin(String username, DateTime date) at Umbraco.Core.Services.Implement.MemberService.SetLastLogin(String username, DateTime date) in D:\a\1\s\src\Umbraco.Core\Services\Implement\MemberService.cs:line 810

And

2022-08-17 13:16:29.965 +02:00 [Error] Exception ("571dc748"). System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded. The statement has been terminated. at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted) at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) at System.Data.SqlClient.SqlCommand.ExecuteNonQuery() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func) in D:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172 at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd) at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args) at Umbraco.Core.Persistence.SqlSyntax.SqlServerSyntaxProvider.ObtainWriteLock(IDatabase db, TimeSpan timeout, Int32 lockId) in D:\a\1\s\src\Umbraco.Core\Persistence\SqlSyntax\SqlServerSyntaxProvider.cs:line 285 at Umbraco.Core.Persistence.SqlSyntax.SqlServerSyntaxProvider.WriteLock(IDatabase db, Int32[] lockIds) in D:\a\1\s\src\Umbraco.Core\Persistence\SqlSyntax\SqlServerSyntaxProvider.cs:line 278 at Umbraco.Core.Scoping.Scope.LockInner(IUmbracoDatabase db, Guid instanceId, Dictionary2& locks, HashSet1& locksSet, Action2 obtainLock, Action3 obtainLockTimeout, Nullable1 timeout, Int32[] lockIds) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 956 at Umbraco.Core.Scoping.Scope.EagerWriteLockInner(IUmbracoDatabase db, Guid instanceId, Nullable1 timeout, Int32[] lockIds) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 910 at Umbraco.Core.Scoping.Scope.EnsureDbLocks() in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 487 at Umbraco.Core.Scoping.Scope.get_Database() in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 330 at Umbraco.Core.Persistence.Repositories.Implement.DocumentRepository.PersistUpdatedItem(IContent entity) in D:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\DocumentRepository.cs:line 757 at Umbraco.Core.Cache.DefaultRepositoryCachePolicy2.Update(TEntity entity, Action1 persistUpdated) in D:\a\1\s\src\Umbraco.Core\Cache\DefaultRepositoryCachePolicy.cs:line 136 at Umbraco.Core.Services.Implement.ContentService.CommitDocumentChangesInternal(IScope scope, IContent content, ContentSavingEventArgs saveEventArgs, IReadOnlyCollection1 allLangs, Int32 userId, Boolean raiseEvents, Boolean branchOne, Boolean branchRoot) in D:\a\1\s\src\Umbraco.Core\Services\Implement\ContentService.cs:line 1257 at Umbraco.Core.Services.Implement.ContentService.Unpublish(IContent content, String culture, Int32 userId) in D:\a\1\s\src\Umbraco.Core\Services\Implement\ContentService.cs:line 1031 at Umbraco.Web.Editors.ContentController.PostUnpublish(UnpublishContent model) at lambda_method(Closure , Object , Object[] ) at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass6_2.b2(Object instance, Object[] methodParameters) at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken) --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Controllers.ApiControllerActionInvoker.d1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Filters.ActionFilterAttribute.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.ActionFilterAttribute.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Controllers.ActionFilterResult.d5.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.AuthorizationFilterAttribute.d3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.AuthorizationFilterAttribute.d3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.AuthorizationFilterAttribute.d3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Filters.AuthorizationFilterAttribute.d3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Controllers.ExceptionFilterResult.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Web.Http.Controllers.ExceptionFilterResult.d6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Web.Http.Dispatcher.HttpControllerDispatcher.d15.MoveNext() ClientConnectionId:c311c60c-bb50-4b8c-9087-5b426d2b24d4 `

Steps to reproduce

It's hard to reproduce. We have an intranet with 2000 concurrent members and it happens randomly.

Expected result / actual result

It would be nice if these locks can be avoided because they affect the speed of all other properties stored in umbracoPropertyData. Perhaps it would be better if the LastLoginDate was not stored as a property but instead as a column in the cmsMember table.

github-actions[bot] commented 2 years ago

Hi there @mcl-sz!

Firstly, a big thank you for raising this issue. Every piece of feedback we receive helps us to make Umbraco better.

We really appreciate your patience while we wait for our team to have a look at this but we wanted to let you know that we see this and share with you the plan for what comes next.

We'll assess whether this issue relates to something that has already been fixed in a later version of the release that it has been raised for.
If it's a bug, is it related to a release that we are actively supporting or is it related to a release that's in the end-of-life or security-only phase?
We'll replicate the issue to ensure that the problem is as described.
We'll decide whether the behavior is an issue or if the behavior is intended.

We wish we could work with everyone directly and assess your issue immediately but we're in the fortunate position of having lots of contributions to work with and only a few humans who are able to do it. We are making progress though and in the meantime, we will keep you in the loop and let you know when we have any questions.

Thanks, from your friendly Umbraco GitHub bot :robot: :slightly_smiling_face:

kjac commented 1 year ago

Hi @mcl-sz,

Thank you for reporting this - and apologies for the late response 😢

We're having a hard time reproducing this issue. Since it's been a while, I was hoping you might have a little more information that might help us track this down?

mcl-sz commented 1 year ago

Hi @kjac,

It is indeed difficult to reproduce the problem because it mainly occurs on heavily used membersites.

Because the "umbracoMemberLastLogin" is updated everytime a member logs in, tablelocks are occuring on the umbracoPropertyData table. This has resulted in the backoffice functioning very slowly or not functioning at all, for example when a listview needs to be filled with nodes.

We solved this for our site by taking MemberService.SetLastLogin out of the login process and creating a simple MemberAuditService that stores the MemberId and date in a separate table.

This solved our problem, because the umbracoProperty table is no longer used, but the date in the backoffice (and LastLoginDate property) is no longer updated. But we prefer this shortcoming to a bad or non-functioning back office.

kjac commented 1 year ago

Thanks @mcl-sz 👍 I'll bring this one back to the team for further discussion.

umbraco / Umbraco-CMS