U4-5157 - Membership.GetUser() causes 13 SQL queries, including duplicates

Created by Asbjørn Riis-Knudsen 27 Jun 2014, 20:44:15 Updated by Shannon Deminick 08 Jul 2014, 09:01:15

Relates to: U4-5069

I have a simple partial view to show the currently logged in member. I was browsing around the mini profiler (great tool, btw) and noticed, that my little partial view was generating 13 SQL queries to the database just displaying the current user name and a link to the profile page. After experimenting a bit, I found that it is simply the line Membership.GetUser(); that causes this. I presume this is because it updates the last active information in the database. This seems excessive for just getting the ID of the currently logged in member. I hardcoded the member ID as a test to get rid of this line and reduced the render time (according to the mini profiler) from 85 ms to 20 ms - and from 13 database queries to 0.

This is running on 6.2, but given that 6.2 uses the member API from v7.1, I expect it also occurs on v7.1 and newer. I can't test that right now, but I shall do so as soon as possible.

Would it be possible to add a simple and efficient way to get the currently logged in member (perhaps something like Umbraco.GetLoggedInMember())?

This is the relevant code in my partial view: @if(Request.IsAuthenticated) { var user = Membership.GetUser(); var minside = Model.Content.AncestorOrSelf(1).Descendant("MinSide");

var member = ApplicationContext.Services.MemberService.GetByProviderKey(user.ProviderUserKey);

var nameWords = member.Name.Split(' ');

<a href="@minside.Url">@member.Name</a> @:|


using (Html.BeginUmbracoForm("LogOff", "LoginSurface", null, new { id = "logoff-form" }))
{
    
    <button type="submit" id="submit" name="submit" value="logout">Log af</button>
}
 

}

This is the 13 SQL queries: 14.70 ms
RazorView.Render: ~/Views/TextPage.cshtml — 4.40 ms

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+14.7 ms Reader

48.6 ms

b__3 ExecuteAction ExecuteReaderWithRetry ExecuteReaderWithRetry ExecuteReaderWithRetry MoveNext Fetch PerformGetByQuery GetByQuery GetByUsername GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render SELECT umbracoNode.*, cmsContent.contentType, cmsContentType.alias AS ContentTypeAlias, cmsContentVersion.VersionId, cmsContentVersion.VersionDate, cmsContentVersion.LanguageLocale, cmsMember.Email, cmsMember.LoginName, cmsMember.Password, cmsPropertyData.id AS PropertyDataId, cmsPropertyData.propertytypeid, cmsPropertyData.dataDate, cmsPropertyData.dataInt, cmsPropertyData.dataNtext, cmsPropertyData.dataNvarchar, cmsPropertyType.id, cmsPropertyType.Alias, cmsPropertyType.Description, cmsPropertyType.Name, cmsPropertyType.mandatory, cmsPropertyType.validationRegExp, cmsPropertyType.helpText, cmsPropertyType.sortOrder AS PropertyTypeSortOrder, cmsPropertyType.propertyTypeGroupId, cmsPropertyType.dataTypeId, cmsDataType.controlId, cmsDataType.dbType FROM [umbracoNode] INNER JOIN [cmsContent] ON [cmsContent].[nodeId] = [umbracoNode].[id] INNER JOIN [cmsContentType] ON [cmsContentType].[nodeId] = [cmsContent].[contentType] INNER JOIN [cmsContentVersion] ON [cmsContentVersion].[ContentId] = [umbracoNode].[id] INNER JOIN [cmsMember] ON [cmsMember].[nodeId] = [cmsContent].[nodeId] LEFT JOIN [cmsPropertyType] ON [cmsPropertyType].[contentTypeId] = [cmsContent].[contentType] LEFT JOIN [cmsDataType] ON [cmsDataType].[nodeId] = [cmsPropertyType].[dataTypeId] LEFT JOIN [cmsPropertyData] ON [cmsPropertyData].[propertytypeid] = [cmsPropertyType].[id] AND cmsPropertyData.versionId = cmsContentVersion.VersionId WHERE ([umbracoNode].[nodeObjectType] = '39eb0f98-b348-42a1-8662-e7eb18487560') AND umbracoNode.id IN (SELECT DISTINCT(umbracoNode.id) FROM [umbracoNode] INNER JOIN [cmsContent] ON [cmsContent].[nodeId] = [umbracoNode].[id] INNER JOIN [cmsContentType] ON [cmsContentType].[nodeId] = [cmsContent].[contentType] INNER JOIN [cmsContentVersion] ON [cmsContentVersion].[ContentId] = [umbracoNode].[id] INNER JOIN [cmsMember] ON [cmsMember].[nodeId] = [cmsContent].[nodeId] LEFT JOIN [cmsPropertyType] ON [cmsPropertyType].[contentTypeId] = [cmsContent].[contentType] LEFT JOIN [cmsDataType] ON [cmsDataType].[nodeId] = [cmsPropertyType].[dataTypeId] LEFT JOIN [cmsPropertyData] ON [cmsPropertyData].[propertytypeid] = [cmsPropertyType].[id] AND cmsPropertyData.versionId = cmsContentVersion.VersionId WHERE ([umbracoNode].[nodeObjectType] = '39eb0f98-b348-42a1-8662-e7eb18487560') AND (upper([cmsMember].[LoginName]) = '105106')) ORDER BY [cmsContentVersion].[VersionDate] DESC , ([umbracoNode].[sortOrder])

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+65.7 ms

Scalar

0.6 ms

b__9 ExecuteAction ExecuteScalarWithRetry ExecuteScalarWithRetry ExecuteScalarWithRetry ExecuteScalar ExecuteScalar PerformCount GetAll BuildFromDtos PerformGetByQuery GetByQuery GetByUsername GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render SELECT COUNT(*) FROM [umbracoNode] INNER JOIN [cmsContentType] ON [cmsContentType].[nodeId] = [umbracoNode].[id] WHERE ([umbracoNode].[nodeObjectType] = '9b5416fb-e72f-45a9-a07b-5a9a2709ce43') AND ([umbracoNode].[id] <> 0)

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+67.5 ms

Reader

3.8 ms

b__3 ExecuteAction ExecuteReaderWithRetry ExecuteReaderWithRetry ExecuteReaderWithRetry MoveNext Fetch GetPropertyCollection BuildFromDtos PerformGetByQuery GetByQuery GetByUsername GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render SELECT * FROM [cmsPropertyData] INNER JOIN [cmsPropertyType] ON [cmsPropertyData].[propertytypeid] = [cmsPropertyType].[id] WHERE ([cmsPropertyData].[contentNodeId] = 1107) AND ([cmsPropertyData].[versionId] = 'd30d4ccc-2e92-4b87-982b-88b1a5c37627')

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+72.1 ms

Scalar

0.3 ms

b__9 ExecuteAction ExecuteScalarWithRetry ExecuteScalarWithRetry ExecuteScalarWithRetry ExecuteScalar AddOrUpdateContentXml Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 int = 1107;

SELECT COUNT(nodeId) FROM cmsContentXml WHERE nodeId = @0

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+75.1 ms

Reader

0.3 ms

MoveNext SingleOrDefault PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 int = 1107;

SELECT [cmsContent].[pk], [cmsContent].[nodeId], [cmsContent].[contentType] FROM [cmsContent] WHERE nodeId = @0

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+75.9 ms

NonQuery

0.4 ms

b__0 ExecuteAction ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry Update Update Update PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 int = 0, @1 int = -1, @2 int = 0, @3 smallint = 1, @4 nvarchar(4000) = N'-1,1107', @5 int = 53, @6 nvarchar(40) = N'f33f9b1e-a085-4152-9719-bbee56939c5a', @7 nvarchar(4000) = N'Asbjørn Knudsen', @8 nvarchar(40) = N'39eb0f98-b348-42a1-8662-e7eb18487560', @9 datetime = '2012-07-20T01:29:32', @10 int = 1107;

UPDATE [umbracoNode] SET [trashed] = @0, [parentID] = @1, [nodeUser] = @2, [level] = @3, [path] = @4, [sortOrder] = @5, [uniqueID] = @6, [text] = @7, [nodeObjectType] = @8, [createDate] = @9 WHERE [id] = @10

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+76.7 ms

Reader

0.7 ms

MoveNext SingleOrDefault PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 nvarchar(40) = N'd30d4ccc-2e92-4b87-982b-88b1a5c37627';

SELECT [cmsContentVersion].[id], [cmsContentVersion].[ContentId], [cmsContentVersion].[VersionId], [cmsContentVersion].[VersionDate], [cmsContentVersion].[LanguageLocale] FROM [cmsContentVersion] WHERE VersionId = @0

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+77.7 ms

NonQuery

0.2 ms

b__0 ExecuteAction ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry Update Update Update PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 int = 1107, @1 nvarchar(40) = N'd30d4ccc-2e92-4b87-982b-88b1a5c37627', @2 datetime = '2014-06-27T22:38:36', @3 nvarchar = null, @4 int = 124;

UPDATE [cmsContentVersion] SET [ContentId] = @0, [VersionId] = @1, [VersionDate] = @2, [LanguageLocale] = @3 WHERE [id] = @4

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+78.4 ms

NonQuery

0.4 ms

b__0 ExecuteAction ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry Update Update Update PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 int = 1107, @1 nvarchar(40) = N'd30d4ccc-2e92-4b87-982b-88b1a5c37627', @2 int = 63, @3 nvarchar = null, @4 nvarchar = null, @5 nvarchar = null, @6 nvarchar(4000) = N' 1116 1117 ', @7 int = 716;

UPDATE [cmsPropertyData] SET [contentNodeId] = @0, [versionId] = @1, [propertytypeid] = @2, [dataInt] = @3, [dataDate] = @4, [dataNvarchar] = @5, [dataNtext] = @6 WHERE [id] = @7

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+79.2 ms

DUPLICATE NonQuery

0.3 ms

b__0 ExecuteAction ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry Update Update Update PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 int = 1107, @1 nvarchar(40) = N'd30d4ccc-2e92-4b87-982b-88b1a5c37627', @2 int = 65, @3 nvarchar = null, @4 nvarchar = null, @5 nvarchar = null, @6 nvarchar(4000) = N' 1116 1117 ', @7 int = 744;

UPDATE [cmsPropertyData] SET [contentNodeId] = @0, [versionId] = @1, [propertytypeid] = @2, [dataInt] = @3, [dataDate] = @4, [dataNvarchar] = @5, [dataNtext] = @6 WHERE [id] = @7

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+80.0 ms

DUPLICATE NonQuery

0.3 ms

b__0 ExecuteAction ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry Update Update Update PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 int = 1107, @1 nvarchar(40) = N'd30d4ccc-2e92-4b87-982b-88b1a5c37627', @2 int = 81, @3 nvarchar = null, @4 nvarchar = null, @5 nvarchar(4000) = N'64831728', @6 nvarchar = null, @7 int = 6146;

UPDATE [cmsPropertyData] SET [contentNodeId] = @0, [versionId] = @1, [propertytypeid] = @2, [dataInt] = @3, [dataDate] = @4, [dataNvarchar] = @5, [dataNtext] = @6 WHERE [id] = @7

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+80.7 ms

DUPLICATE NonQuery

0.3 ms

b__0 ExecuteAction ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry Update Update Update PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 int = 1107, @1 nvarchar(40) = N'd30d4ccc-2e92-4b87-982b-88b1a5c37627', @2 int = 82, @3 nvarchar = null, @4 nvarchar = null, @5 nvarchar = null, @6 nvarchar(4000) = N'Flytterupgyden 58 5471 Søndersø', @7 int = 6147;

UPDATE [cmsPropertyData] SET [contentNodeId] = @0, [versionId] = @1, [propertytypeid] = @2, [dataInt] = @3, [dataDate] = @4, [dataNvarchar] = @5, [dataNtext] = @6 WHERE [id] = @7

4.00 ms
RazorView.Render: ~/Views/Partials/LoginStatus.cshtml — 4.00 ms

RazorView.Render: ~/Views/Partials/LoginStatus.cshtml

T+85.0 ms

NonQuery

0.2 ms

b__0 ExecuteAction ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry ExecuteNonQueryWithRetry Update Update Update PersistUpdatedItem PersistUpdatedItem Commit Commit Save GetUser Execute ExecutePageHierarchy ExecutePageHierarchy Render Execute ExecutePageHierarchy ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy b__6 WriteTo Write RenderSurrounding PopContext ExecutePageHierarchy Render DECLARE @0 nvarchar(4000) = N' 1116 1117 1116 1117 64831728 ', @1 int = 1107;

UPDATE [cmsContentXml] SET [xml] = @0 WHERE [nodeId] = @1

7.00 ms
RazorView.Render: ~/Views/Partials/LoginStatus.cshtml — 6.30 ms

1 Attachments

Download miniprofilerdump.txt

Comments

Bradley Kronson 30 Jun 2014, 21:00:02

I am seeing this too - I'm also not understanding why getting a member in this manner should cause the member properties to be updated via SQL ?


Bradley Kronson 30 Jun 2014, 21:07:23

This could be related to the SQL deadlocks I am seeing in U4-5069 - it looks like every page in a site that is access controlled is updating the member several times - I am seeing 100+queries all related to member access and updating...


Shannon Deminick 01 Jul 2014, 06:28:16

In 6.2 we have the MembershipHelper which is exposed directly on all UmbracoViewPage views as @Members you should use that instead of going directly to the membership provider.

I'm sure we can also improve perf more by request based caching or similar but you should have a look the methods you can use as opposed to what you are currently doing:

https://github.com/umbraco/Umbraco-CMS/blob/6.2.2/src/Umbraco.Web/Security/MembershipHelper.cs


Asbjørn Riis-Knudsen 01 Jul 2014, 10:51:41

@Shannon Thanks, hadn't noticed that at all. I'll have a look, but it will have to wait until next week, as I'm currently away from my computer.


Asbjørn Riis-Knudsen 05 Jul 2014, 12:31:02

I have now had a chance to try out the new MembershipHelper. First of all, it is much easier to work with nad it does improve performance, we're now down to around 60 ms and 3 sql queries which is bit more in line with what I would expect. Should this bug be closed then?


Shannon Deminick 07 Jul 2014, 00:56:26

Great! thanks for the feedback, will close.


Chad T 08 Jul 2014, 02:17:33

Revisiting this as even when using the Membership Helper, we're having issues, the following code: @Members.GetCurrentMember().Name

Is executing 33 queries. The majority of which are updates, it's seemingly going through every property on the member and updating them individually. This is on 7.1.0. I've attached a copy pasta dump of the mini profiler bits.


Shannon Deminick 08 Jul 2014, 02:20:27

@Chad - there's a bunch of fixes in later versions and more so in 7.1.5.

You'll need to test the latest versions. Also, you shouldn't just keep calling the method like:

@Members.GetCurrentMember().Name @Members.GetCurrentMember().SomeOtherProperty

you should be storing the GetCurrentMember result as a variable and then access it's variables.


Chad T 08 Jul 2014, 04:19:42

Cheers @Shannon - am waiting for 7.1.5 final to drop before tackling the upgrade purpose. Will revisit then.


Shannon Deminick 08 Jul 2014, 04:23:11

Cool no worries, waiting for seb to get back from holidays so we can get a date for release. In the meantime there's a few people running 7.1.5 from the nightly: http://nightly.umbraco.org/umbraco%207.1.5/

There's some good fixes in there if you feel like testing on dev or whatever.


Chad T 08 Jul 2014, 04:46:37

OK, tested 7.1.5, no change, still 33 queries - exactly the same as the log posted earlier. Will see if I can dig in and find out more. Have also come across a different issue compounding things with regard to "public access". It seems that also looks up member details, which is chaining things all together, causing 127 queries - I've disabled public access for now... one thing at a time :)


Shannon Deminick 08 Jul 2014, 04:50:43

yeah that's no good, also check out this issue: http://issues.umbraco.org/issue/U4-5069

I wonder if for whatever reason the 7.1.5 from the nightly didn't contain the update fix from that issue. Anyways, keep me posted, i'll re-open this and look into things this week.


Chad T 08 Jul 2014, 04:55:59

Hey @Shannon, MemberService actually seems fine, it's the MemberHelper that is doing something bizarre:

@ApplicationContext.Services.MemberService.GetByUsername(User.Identity.Name).Name

3 queries, no duplicates, no updates.

@Members.GetByUsername(User.Identity.Name)

6 Queries - 3 duplicates (basically doubling up what happens above).

Anything to do with "GetCurrentMember...", all hell seems to break loose.


Shannon Deminick 08 Jul 2014, 08:04:43

Cool, can duplicate and fixing now


Shannon Deminick 08 Jul 2014, 08:53:14

Ok, that's all fixed now.

The MembershipHelper will request cache some of it's getters and I've fixed the duplicate query thing too. So now if you use GetCurrentMember() as many times during a single request it will only ever do a lookup once. Since this same query is used for GetCurrentMemberId and a few other things too, it will save queries for those operations too. Other things that are request cached now are MembershipHelper.GetByEmail, MembershipHelper.GetByUsername, MembershipHelper.GetById, MembershipHelper.GetByProviderKey


Priority: Normal

Type: Bug

State: Fixed

Assignee: Shannon Deminick

Difficulty: Normal

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions: 7.1.0, 6.2.0, 7.1.1, 7.1.2, 7.1.3, 6.2.1, 7.1.4, 6.2.2

Due in version: 7.1.5, 6.2.2

Sprint:

Story Points:

Cycle: