23 03 2011

So why the hell’s it so slow?


This post follows on from my last one when I looked at the developer dashboard to gain insight into where the performance issues came from when you have a large list with lots of item level permissions.

In this post I’ll take a deeper look, using the SQL Server Profiler tool to see what data is being passed around, to confirm my assumptions that large lists with lots of unique item permissions slow down at the database level.

To analyse this better, I decided to use the code from my last post to create 2 identical lists. One was a custom list with 20k items in, all inheriting permissions as default. A second list would have every single item have unique permissions, as I did in the previous experiment. Doing this just lets me have both lists there so I can switch between the two to see what’s going on.

The thing I noticed last time was a particular query which took an incredibly long time to execute, one that started DECLARE @DocParentIdForRF. The thing with the developer dashboard is that it hides a varbinary parameter which is passed in. This varbinary is used in the generate of a table variable in this query (look at the snippet from the end of my last post to see this).

You notice in the developer dashboard output that when we have item level permissions, a stored procedure is executed that is not when we don’t have the item level permissions – one called proc_GetUniqueScopesInList.

It turns out that the word “scope” is used to describe what is visible from a certain context (well, duh!), and even in SharePoint, a Scope is the visible of an item from a security context!

So, fire up the SQL Server Profiler, start a new trace and filter it out by your application pool identity (this makes reading this A LOT easier).

When I refresh the page with the inherited permissions (NOT the item-level permissions), I notice that the DECLARE @DocParentIdForRF looks like this – with no varbinary parameter… (click for larger image). Stop the trace as soon as the page has loaded, makes the trace easier to read.

Let’s clear the output, restart the trace and load the list with the item-level permissions, you’ll notice the same query looks like this now:

See that huge black blob at the bottom? That’s the varbinary parameter that the developer dashboard hides from you. Where’d the hell that come from? Look up. See the proc_GetUniqueScopesInList procedure? Have a look at the length of time to execute it…

… Next to nothing! It’s a quick, high optimised (select a couple of columns from this table where these 3 columns match these values), using a table-valued function.

Let’s go back to that huge black blob in the screenshot from before. If I get the entirety of that data (starting from the “@L10IMG=0x” somewhere in there, to the end, and dump it into Notepad++ as a quick way of seeing how long it is, it’s a rather cumbersome 640084 characters long (or there abouts). As a hunch, divide it by 32 (the length of a GUID) and you’ll get 20,002. Not far off the number of items in that list, is it?

An item-level permission in SharePoint is represented in the content database in a table called “Perms”, where each item has the ACL stored as a mask.

When you load up a huge list with lots of item level permissions, a single operation gets every single GUID associated with the ACL for that item and passes that back to the data access layer of SharePoint. When the database retrieves the actual list item data, it will pass in all of the ACL Guids back in as one long string, all concatenated together. The query to get the data creates a table variable re-assembles the the item level ACL Guid associated with each item. How the rest of the query deals with this is anyone’s guess at the moment – this table variable might just be passed back to the calling COM object (though I thought they couldn’t be used this way….) for the COM object to then sort out which item should be visible to which “scope” (or ACL).

So, what can we take away form this? Passing 640k of data about the place, for a SQL Query to do some substring math and converting to Guids will soon bring your database server to its knees. This is one request and it takes 2000ms to work. Imagine if you have 5 requests per second or more hitting this list! If you think you’re gonna need them, might be time to re-architect the solution.

SharePoint 2010 Performance with Item Level Permissions Summary Links – Show Images For Groups