In an earlier article I have discussed that all SPSite and SPWeb (and potentially also PublishingWeb) objects need to be properly disposed to avoid memory pressure situations. Roger Lamb has a nice summary of coding patterns which will actually cause such leaking objects and also provides information about how such code would have to be adjusted to avoid such leaks.
In this article I will provide some details about how a sharepoint administrator is able to isolate if the site contains custom code which does not properly dispose these objects and also how to isolate the components that are leaking these objects.
As discussed in my earlier article each SPWeb and SPSite object holds a reference to an SPRequest object which holds a reference to a SharePoint COM object that is responsible to communicate with the backend SQL server. The dispose of the SPWeb and SPSite object is necessary to ensure that the SPRequest object will release the COM object and also all the memory allocated by this COM object is released.
In SharePoint v2 the only way to identify such leaking objects was to analyze a memory dump - which usually required that a support case with Microsoft has to be opened to identify the code that is not correctly disposing the SPWeb or SPSite objects.
SharePoint v3 on the other hand contains code which monitors correct disposal of SPRequest objects (and therefore correct disposal of SPWeb and SPSite objects). This code has two different features:
I will now discuss how these build in features can be used to identify how expensive (in regards of SPRequest allocations) your site design is and also if the code contains any controls which don not properly dispose SPWeb and SPSite objects.
Usually you would think that if you don't add any custom code to your page that only one SPSite and one SPWeb object should be required (the site collection and the site the page lives in) but this is not correct. The reason is that all the master pages contain three navigation controls: The Top navigation, the Breadcrumb control and the Left Navigation control.
Per default these navigation controls are bound to one of the Site Map Providers shipped with SharePoint. To show the elements in the navigation control the control queries the site map provider which will now enumerate the sites in the sharepoint database to retrieve the title and the URL to be displayed on the navigation control. Each of the enumerated sites will be instantiated during the enumeration to retrieve these properties. That means if you have a navigation control configured to enumerate 3 levels of sites and on each level you have 20 sites that you will end up with more than 400 SPRequest objects. So you need to be very careful with how to configure your navigation controls and also how many sites to create on each level!
A valid question now could be: why does the site map provider not dispose each of the objects directly after it retrieved the URL and the Title? That should reduce the number of parallel existing SPRequest objects heavily. Indeed that would be correct. But remember: you have usually multiple navigation controls on a single page! Disposing these objects directly after the properties have been read would mean that for each navigation control on the page the same objects have to be retrieved from the database again and again - which would impact the performance of the site. To avoid this the items retrieved by the navigation controls are cached to ensure that other navigation controls needing the same items can leverage them without causing additional requests to the backend database. The caveat is that the overall memory consumption of the site will go up through this implementation.
As indicated in the overview section SharePoint v3 monitors how many SPRequest objects exist in parallel on the same thread. As soon as SharePoint identifies that with a new allocation the number of SPRequest objects exceeds a configurable threshold SharePoint will create the following entry into the ULS log:
12/12/2007 12:29:54.05 w3wp.exe (0x1380) 0x126C Windows SharePoint Services General 0 Medium Potentially excessive number of SPRequest objects (14) currently unreleased on thread 5. Ensure that this object or its parent (such as an SPWeb or SPSite) is being properly disposed. Allocation Id for this object: {2DF92EAD-4959-4A21-8BA0-FBD91E8FDD48} Stack trace of current allocation: at Microsoft.SharePoint.SPRequestManager.Add(SPRequest request, Boolean shareable)
The default threshold to get the above warning is 8 - which is actually far to small for real live scenarios as we have seen that with navigation controls on your master pages you will for sure exceed this number. As you can see in the sample above the warning outlines that 14 SPRequest objects live in parallel on the same thread. As we have seen before with navigation controls a larger number of SPRequest objects is absolutly normal and as expected. So you can expect the ULS log to be filled up with many similar warnings.
You should inspect the ULS logs of your site and verify what are the highest numbers in these warnings to get an idea about how expensive your current site design currently is in regards to memory consumption through allocated SPRequest objects. If the number is higher than 150 you might need to consider to change the design of your site or the number of levels to show in your navigation controls to reduce the memory footprint.
Afterwards you can fine tune the threshold to avoid unnecessary warnings. This can be done by adjusting the threshold through the following a registry key (e.g. to 50):
HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSettings LocalSPRequestWarnCount = 50
HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSettings
LocalSPRequestWarnCount = 50
The actual number to configure here depends on your site structure. After setting this registry key you need to restart the sharepoint services and the application pools (or restart the server) to ensure that the settings get effective.
Also be aware that you will only see the above warning if you have configured diagnostic logging for the General category to at least Medium level - which is actually the default. So if you haven't changed the configuration of diagnostic logging you will see these warnings.
One method (not completely reliable but a good indicator) is to monitor the ULS log message mentioned in the last section. If the number for some threads gets higher and higher during the livetime of a thread, without going down to the configured threshold again the chance is high that there is some code which does not properly dispose SPWeb and SPSite objects.
Be aware that you cannot just look at the callstack listed in these messages to identify the bad code as this warning will be written during allocation of the objects! This message does NOT indicate that the object is not properly disposed! So you can only use it as an indicator that some code might be wrong but not to identify the module causing the problem!
To identify the bad code we need to use a different approach.
As mentioned in the Overview section SharePoint not only monitors the number of SPRequest objects allocated by each thread but also checks if SPRequest objects still exist at the end of each thread and create the following message into the ULS log.
05/01/2007 12:58:47.31 w3wp.exe (0x105C) 0x09A8 Windows SharePoint Services General 8l1n High An SPRequest object was not disposed before the end of this thread. To avoid wasting system resources, dispose of this object or its parent (such as an SPSite or SPWeb) as soon as you are done using it. This object will now be disposed. Allocation Id: {5BFFCA4B-3B91-45BF-98CD-0BB508BE30EE} To determine where this object was allocated, create a registry key at HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSettings. Then create a new DWORD named SPRequestStackTrace with the value 1 under this key.
Be aware that the livetime of a thread can be much longer as a single request. As SharePoint only checks if undisposed SPRequest objects exist when the thread ends and not at the end of each request the number of entries of this type can be much smaller than you might expect. So you might have to search in multiple ULS logs and not just the latest for this warning (you can actually search for the string 8l1n as this is the unique identifier for this message).
In addition: if the object has been disposed by the garbage collector then you will see a slightly different message stating that the garbage collector reclaimed the object:
05/01/2007 14:48:43.32 w3wp.exe (0x105C) 0x09A8 Windows SharePoint Services General 8l1n High An SPRequest object was reclaimed by the garbage collector instead of being explicitly freed. To avoid wasting system resources, dispose of this object or its parent (such as an SPSite or SPWeb) as soon as you are done using it. Allocation Id: {098092FF-E4D9-4BA3-B2B8-5C6CE9B96554} To determine where this object was allocated, create a registry key at HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSettings. Then create a new DWORD named SPRequestStackTrace with the value 1 under this key.
To identify which code is responsible for the problem after you identified the problem you have two options:
HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSettings SPRequestStackTrace = 1
SPRequestStackTrace = 1
The second option is more reliable as it will ensure that you get a callstack for each of the 8l1n messages. Be aware that after setting this registry key you need to restart the sharepoint services and the application pools (or restart the server) to ensure that the settings get effective.
[Update: 2010-10-18: SharePoint 2010: For SP 2010 the method is different. See here for details]
By analyzing the emitted callstack you should then be able to identify the component causing the problem.
Stefan,
Even after setting SPRequestStackTrace to 1 and running iisreset, we are still *not* getting stack traces for the 8l1n messages.
Do you know why this might be ?
Thanks,
Kim
[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSetting]
"SPRequestStackTrace"="1"
Hi Kim,
the registry key above is wrong. You used "HeapSetting" where it should be "HeapSettings". Notice the missing "s" at the end.
Cheers,
Stefan
Sorry, I copied the information from a different site when I wa composing the blog comment. But we actually did use the HeapSettings
Below is what we've set.
Have you actually seen it generate a stack trace for the 8l1n messages ? What's interesting is that we do get stack traces for the SPRequest warning messages. I assume that this one setting controls the stack trace for both sets. So why is a stack trace appearing for one set and not the other ?
Also, I wonder if there's anything else we need to configure to get the stack traces displayed for the 8l1n messages. This is a bit frustrating as it seems to me that these are the actually useful stack traces...
Windows Registry Editor Version 5.00
[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSettings]
"SPRequestStackTrace"=dword:00000001
yes I use it quite often when working on customer cases. Around 2-3 times a month.
Its always working.
Thanks for your help ! I restarted sharepoint services and the www publishing service, and I'm seeing the allocation stack traces for the 8l1n messages. :).
Best,
Kim.
I'm not sure if I'm reading this correctly, but it looks like I am getting stack traces for the 'object was not disposed before the end of this thread.' Interestingly, I *am* getting stack traces for the 'object was reclaimed by the garbage collector instead of being explicitly freed.' I thought both stack traces were controlled by the same registry value ?
Am I misreading this ? Do you have any insight into why this might be ?
****************************************************************
04/13/2009 10:19:25.02 : w3wp.exe (0x0CA8) 0x129CWindows SharePoint Services General 8l1nMonitorable
An SPRequest object was not disposed before the end of this thread. To avoid wasting system resources, dispose of this object or its parent (such as an SPSite or SPWeb) as soon as you are done using it. This object will now be disposed. Allocation Id: {7B27433F-4E67-491A-BA7F-B274D9048165} To determine where this object was allocated, create a registry key at HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSettings. Then create a new DWORD named SPRequestStackTrace with the value 1 under this key.
An SPRequest object was reclaimed by the garbage collector instead of being explicitly freed. To avoid wasting system resources, dispose of this object or its parent (such as an SPSite or SPWeb) as soon as you are done using it. Allocation Id: {A143F475-52DD-45BC-B897-AF4C9BEFFBC1} This SPRequest was allocated at
at Microsoft.SharePoint.Library.SPRequest..ctor()
at Microsoft.SharePoint.SPGlobal.CreateSPRequestAndSetIdentity(Boolean bNotGlobalAdminCode, String strUrl, Boolean bNotAddToContext, Byte[] UserToken, String userName, Boolean bIgnoreTokenTimeout, Boolean bAsAnonymous)
at Microsoft.SharePoint.SPWeb.InitializeSPRequest()
at Microsoft.SharePoint.SPWeb.EnsureSPRequest()
at Microsoft.SharePoint.SPWeb.get_Request()
at Microsoft.SharePoint.SPFieldCollection.EnsureFieldsSafeArray(Boolean bGetFullXML)
at Microsoft.SharePoint.SPFieldCollection.Undirty(Boolean bGetFullXML)
at Microsoft.SharePoint.SPFieldCollection.Undirty()
at Microsoft.SharePoint.SPBaseCollection.System.Collections.IEnumerable.GetEnumerator()
at GreyPkgWFApproval.Utils.getMissingFields(SPList spList, String[] listColumns)
that is interesting. Haven't seen this.
Anyway: the stack clearly shows the 3rd party control that is causing the leak.
This is pretty weird, but it might help other people who may have run into the same issue (stack trace not appearing for the 'object was not disposed before the end of this thread').
I tried configuring the related IIS application pool so that it would recycle the worker process after 1 request. This actually caused the stack trace to start appearing for the above type messages. Then, to double-check, I de-selected the 'Recycle worker process(number of requests)' option and noted that the stack trace no longer appeared. Instead it presented the misleading message about setting the SPRequestStackTrace DWORD value to 1 -- misleading because it had already been set.
Finally, I set the 'Recyle worker process (number of requests)' to 10 and the stack trace appeared again for the above 'end of thread' type messages.
By the way, for all of the above experiments, I had the 'Recycle worker processes(in minutes)' also selected and set to 15 minutes.
So I think this may be a bizarre Microsoft bug, where the 'end of thread' stack traces only appears if the number of requests item is selected.
Between the two log messages below, the only change I made was to select and set the 'Recycle worker process (number of requests')
to 10.
04/13/2009 14:40:31.96 : w3wp.exe (0x1428) 0x1470Windows SharePoint Services General 8l1nMonitorable
An SPRequest object was not disposed before the end of this thread. To avoid wasting system resources, dispose of this object or its parent (such as an SPSite or SPWeb) as soon as you are done using it. This object will now be disposed. Allocation Id: {A00EAB6F-6BF1-4A5D-A502-AD330B3C3373} To determine where this object was allocated, create a registry key at HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Shared Tools\Web Server Extensions\HeapSettings. Then create a new DWORD named SPRequestStackTrace with the value 1 under this key.
04/13/2009 14:47:43.22 : w3wp.exe (0x1400) 0x14F0Windows SharePoint Services General 8l1nHigh
An SPRequest object was not disposed before the end of this thread. To avoid wasting system resources, dispose of this object or its parent (such as an SPSite or SPWeb) as soon as you are done using it. This object will now be disposed. Allocation Id: {0C8F72A4-C270-442F-B7A6-11BE72E7849A} This SPRequest was allocated at
at Microsoft.SharePoint.SPSite.GetSPRequest()
at Microsoft.SharePoint.SPSite.get_Request()
at Microsoft.SharePoint.SPSite.GetReusableAclForScope(Guid scopeId)
at Microsoft.SharePoint.Publishing.AclCache.GetAclForScope(Guid scopeId)
at Microsoft.SharePoint.Publishing.CachedArea..ctor(PublishingWeb area, String id, String parentId, String title, String url, String description, CachedObjectFactory factory)
at Microsoft.SharePoint.Publishing.CachedArea.CreateCachedArea(PublishingWeb area, CachedObjectFactory factory, String parentId)
at Microsoft.SharePoint.Publishing.CachedObjectFactory.CreateObject(PublishingWeb area, String parentUrl)
at Microsoft.SharePoint.Publishing.CachedObjectFactory.CreateObject(PublishingWeb area)
Just an update -- this might be useful to other people as well:
Basically, it looks like the IIS application pool property 'Recycle worker process (number of requests)' is the critical property to set, and the only one that generates a stack trace for the 'object was not disposed before the end of this thread' message. It's best to leave the other recycle options deselected, as if they trigger, they actually won't generate a stack trace. I've verified this for the 'Recycle worker processes (in minutes)' option.
I have not verified whether the Memory recycling options also generate a stack trace for the 'object was not disposed before the end of this thread' message(s).
Issue: SharePoint Sites may log “Excessive SPRequest Objects,” under normal use. When I first saw this
Hey Stefan,
We implemented your recommended changed on our QA SharePoint WFE server and then the WFE started throwing the following error for some unknown reason:
Server Error in '/' Application.
--------------------------------------------------------------------------------
Specified cast is not valid.
Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code.
Exception Details: System.InvalidCastException: Specified cast is not valid.
Source Error:
An unhandled exception was generated during the execution of the current web request. Information regarding the origin and location of the exception can be identified using the exception stack trace below.
Stack Trace:
[InvalidCastException: Specified cast is not valid.]
Microsoft.SharePoint.SPRequestManager.get_SPRequestsPerThreadWarning() +588
Microsoft.SharePoint.SPRequestManager.Add(SPRequest request, Boolean shareable) +695
Microsoft.SharePoint.SPGlobal.CreateSPRequestAndSetIdentity(Boolean bNotGlobalAdminCode, String strUrl, Boolean bNotAddToContext, Byte[] UserToken, String userName, Boolean bIgnoreTokenTimeout, Boolean bAsAnonymous) +2626
Microsoft.SharePoint.SPRequestManager.GetContextRequest(SPRequestAuthenticationMode authenticationMode) +192
Microsoft.SharePoint.Administration.SPFarm.get_RequestNoAuth() +25
Microsoft.SharePoint.ApplicationRuntime.SPHttpHandler.get_Hash() +162
Microsoft.SharePoint.ApplicationRuntime.SPHttpHandler.get_AppDomainIdHeader() +152
Microsoft.SharePoint.ApplicationRuntime.SPHttpHandler.OverrideExecuteUrlPath() +507
System.Web.DefaultHttpHandler.BeginProcessRequest(HttpContext context, AsyncCallback callback, Object state) +83
System.Web.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() +8677954
System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) +155
Version Information: Microsoft .NET Framework Version:2.0.50727.3603; ASP.NET Version:2.0.50727.3082
The only way to get the WFE back online was to removed the registry entries and restart the services.
Researching the particular error yielded nothing except one Google cached paged that had the same problem on 9/29/09.
Do you have any ideas what might have caused the server to behave like that? (I'm not expecting you to miraculously know or be able to resolve the problem, but I'm hoping you might have seen a server do that before when applying these entries)
Thanks
C
Hi Cornelius,
I have never seen this.
But the error indicates that you entered the registry value with the incorrect type. Did you use DWORD or string?
It should be a DWORD.
I have a strange error here.I have a content source. Whenever crawl runs,SQL connections goes too high. and only thing i got in the ULS logs is below
Potentially excessive number of SPRequest objects (12) currently unreleased on thread 9. Ensure that this object or its parent (such as an SPWeb or SPSite) is being properly disposed. Allocation Id for this object: {329BFC8D-6CB9-4C18-8048-72166ABE4E08} Stack trace of current allocation: at Microsoft.SharePoint.SPRequestManager.Add(SPRequest request, Boolean shareable) at Microsoft.SharePoint.SPGlobal.CreateSPRequestAndSetIdentity(Boolean bNotGlobalAdminCode, String strUrl, Boolean bNotAddToContext, Byte[] UserToken, String userName, Boolean bIgnoreTokenTimeout, Boolean bAsAnonymous) at Microsoft.SharePoint.SPWeb.InitializeSPRequest() at Microsoft.SharePoint.SPWeb.EnsureSPRequest() at Microsoft.SharePoint.SPWeb.get_Request() at Microsoft.SharePoint.SPWeb.SetMondoPr...
...ocHint(Int32 hint) at Microsoft.SharePoint.SPSite.OpenWeb(Guid gWebId, Int32 mondoHint) at Microsoft.SharePoint.SoapServer.CWebChange.CheckDB() at Microsoft.SharePoint.SoapServer.CWebChange..ctor(CChange parentChange, String strID, Boolean fDeleteEvent) at Microsoft.SharePoint.SoapServer.CSiteChange.GetWeb(String strID, Boolean fDeleteEvent) at Microsoft.SharePoint.SoapServer.SiteDataImpl.ProcessChanges(CChange change, SPChangeCollection spChangeCollection, SPChangeToken& spLastChangeToken, Int64& lTimeLeft) at Microsoft.SharePoint.SoapServer.SiteDataImpl.GetChanges(CChange change, SPChangeToken& spChangeToken_Start, SPChangeToken spChangeToken_End, Int64 lTimeout) at Microsoft.SharePoint.SoapServer.SiteDataImpl.GetChanges(ObjectType objectType, String contentDa...
1...tabaseId, String& startChangeId, String& endChangeId, Int32 Timeout, Boolean& moreChanges) at Microsoft.SharePoint.SoapServer.SiteData.GetChanges(ObjectType objectType, String contentDatabaseId, String& LastChangeId, String& CurrentChangeId, Int32 Timeout, Boolean& moreChanges) at System.RuntimeMethodHandle._InvokeMethodFast(Object target, Object[] arguments, SignatureStruct& sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner) at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture, Boolean skipVisibilityChecks) at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) at System.Web.Services... Windows SharePoint Services General 0 Medium ....Protocols.LogicalMethodInfo.Invoke(Object target, Object[] values) at System.Web.Services.Protocols.WebServiceHandler.Invoke() at System.Web.Services.Protocols.WebServiceHandler.CoreProcessRequest() at System.Web.Services.Protocols.SyncSessionlessHandler.ProcessRequest(HttpContext context) at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) at System.Web.HttpApplication.ApplicationStepManager.ResumeSteps(Exception error) at System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(HttpContext context, AsyncCallback cb, Object extraData) at System.Web.HttpRuntime.ProcessRequestInternal(HttpWo...
...rkerRequest wr) at System.Web.HttpRuntime.ProcessRequestNoDemand(HttpWorkerRequest wr)
Looks like the same error. But it happnes with crawl ? Any pointers. we have custom webparts. But RendertoIndexer property is already set to false. So webparts are not loaded during crawl. So what might be the reason of such high number of SP Requests ?
Hi Subhasis,
this is expected and by design. During crawl the same happens as if you would browse to the website. Except that crawl puts a pretty high load on the site. Every single instantiated SPWeb objects maintains its own SQL connection. As the crawler uses multiple threads to crawl the site it is like a load test against your site. All the navigation controls on the pages will get instantiated and will instantiate SPWeb objects.
So the only way to reduce the number of SQL connections would be to reduce the number of threads the crawler is using.