Recently I’ve been looking at the ULS in a bit more detail. In short I’ve been focussing on anything in the following categories:
I wrote a PowerShell script that monitors the ULS logs and sends me emails when anything occurs within the above categories.
One of the errors that I have found quite often is the SPReaderWriterLock. What do these errors mean?
Something is trying to read or write while something else is updating the same item. In other words the item has been locked.
OWSTIMER Service generates the following error twice :
SPReaderWriterLock named [SPInitializeOnceLock] held for 3104 milliseconds. Call stack: at Microsoft.SharePoint.Utilities.SPReaderWriterLock.SPReaderWriterLockScope.Dispose() at Microsoft.SharePoint.Workflow.SPNoCodeXomlCompiler.get_ReferencedAssemblies() at Microsoft.SharePoint.Workflow.SPNoCodeXomlCompiler.SubCompiler.AddReferenceableAssemblies(WorkflowCompilerParameters theParameters) at Microsoft.SharePoint.Workflow.SPNoCodeXomlCompiler.SubCompiler.DoCompile(WorkflowCompilerParameters parameters, String xomlSource, String assemblyName, CompilationPacket& packet, DirectoryInfo& tempDir)
Explanation: In my case two Nintex workflows try to update the same item.
miiserver returns the following 2 messages:
SPReaderWriterLock named [Process Context Lock] held for 1357 milliseconds. Call stack: at Microsoft.SharePoint.Utilities.SPReaderWriterLock.SPReaderWriterLockScope.Dispose() at Microsoft.SharePoint.SPProcessContext.Get[T]() at Microsoft.SharePoint.Administration.SPConfigurationDatabase.get_Farm() at Microsoft.SharePoint.Administration.SPConfigurationDatabase.SPFileSystemCacheWatcher.OnChanged(Object source, FileSystemEventArgs e) at System.IO.FileSystemWatcher.CompletionStatusChanged(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* overlappedPointer) at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)
SPReaderWriterLock named [Process Context Lock] waited 109 milliseconds to acquire lock. Call stack: (enable Verbose for stack trace)
Explanation: The SharePoint config database is being updated at the same time
PowerShell generates the following twice in my logs
SPReaderWriterLock named [XmlDocumentCache_Items] waited 141 milliseconds to acquire lock. Call stack: (enable Verbose for stack trace)
There is a theme here. Whenever this error (Unexpected messages really shoud not appear in your SharePoint logs) occurs there are always two messages. They are always fairly similar or the same.
So how do we avoid this. Better coding? Perhaps.
It can be quite tricky in languages like PowerShell or Nintex to get enough control over item level locks. However there is something you can do.
- Always make sure that only one automated process updates items
- No ‘spaghetti workflows’ where workflows trigger other workflows. It is better to create a single workflow.
- Keep all logic in a single place. a mix of PowerShell scripts, Event handlers and workflows is not a good idea.
And then I find a 4th example:
SPReaderWriterLock named [SPObjectCachedItem] waited 140 milliseconds to acquire lock. Call stack: (enable Verbose for stack trace)
Just a single entry referring to the Object Cache…