Recently I faced a cpu hang by a w3wp process of one of the application pools. The process stayed on roughly 50% of cpu usage, which caused performance issues for the other processes running on the WFEs. Recycling the application pool helped at first, but after a few moments the process started spiking again, slowing everything down.
First thing to do is check the ULS logs: nothing special there. It was also pretty hard to pinpoint one specific line as a cause to the high cpu usage.
On to more specific analysis then: Process Explorer. The tool is great for checking your process threads and checking the callstack that is causing any interference.
Below is an example of how the stack window looks:
The method that was hanging during the issue was GetMetadatainternalinterfacefromplublic. Not much more info was available from the stack window. There was no custom code involved during the performance decrease, so further investigation was needed. I noted down the thread id and made a dump of the running process using task manager:
Once the dump was created, I installed DebugDiag v1.2. Analysis of the dump was pretty straight forward using the performance analyzers:
The callstack of the thread with entry point mscorwks!GetMetaDataInternalInterfaceFromPublic was:
System.Data.SqlClient.TdsParserStateObject.WritePacket(Byte) System.Data.SqlClient.TdsParser.WriteByteArray(Byte[], Int32, Int32, System.Data.SqlClient.TdsParserStateObject) System.Data.SqlClient.TdsParser.WriteValue(System.Object, System.Data.SqlClient.MetaType, Byte, Int32, Int32, Int32, System.Data.SqlClient.TdsParserStateObject) System.Data.SqlClient.TdsParser.TdsExecuteRPC(System.Data.SqlClient._SqlRPC[], Int32, Boolean, System.Data.Sql.SqlNotificationRequest, System.Data.SqlClient.TdsParserStateObject, Boolean) System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(System.Data.CommandBehavior, System.Data.SqlClient.RunBehavior, Boolean, Boolean) System.Data.SqlClient.SqlCommand.RunExecuteReader(System.Data.CommandBehavior, System.Data.SqlClient.RunBehavior, Boolean, System.String, System.Data.Common.DbAsyncResult) System.Data.SqlClient.SqlCommand.RunExecuteReader(System.Data.CommandBehavior, System.Data.SqlClient.RunBehavior, Boolean, System.String) System.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior, System.String) System.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior) Microsoft.SharePoint.Utilities.SqlSession.ExecuteReader(System.Data.SqlClient.SqlCommand, System.Data.CommandBehavior, Microsoft.SharePoint.Utilities.SqlQueryData, Boolean) Microsoft.SharePoint.SPSqlClient.ExecuteQueryInternal(Boolean) Microsoft.SharePoint.SPSqlClient.ExecuteQuery(Boolean) DomainNeutralILStubClass.IL_STUB(System.String, System.String, System.Object, Int32, System.Object, Microsoft.SharePoint.Library.PutFileOpt, System.String, System.String, Int32, Int32, System.Object, System.Object, System.Object, System.String, Byte, Int64, System.String, System.String, System.String, Int32, System.String, Int32, Int32, Int32, System.Guid, UInt32 ByRef, System.String ByRef, System.String ByRef, Byte ByRef, Int32 ByRef) Microsoft.SharePoint.Library.SPRequest.PutFile(System.String, System.String, System.Object, Int32, System.Object, Microsoft.SharePoint.Library.PutFileOpt, System.String, System.String, Int32, Int32, System.Object, System.Object, System.Object, System.String, Byte, Int64, System.String, System.String, System.String, Int32, System.String, Int32, Int32, Int32, System.Guid, UInt32 ByRef, System.String ByRef, System.String ByRef, Byte ByRef, Int32 ByRef) Microsoft.SharePoint.SPFile.SaveBinaryStreamInternal(System.IO.Stream, System.String, Boolean, Boolean, Boolean, Boolean, Boolean, System.String, Microsoft.SharePoint.SPUser, System.DateTime, System.Object, Microsoft.SharePoint.SPFileFragmentPartition, Microsoft.SharePoint.SPFileFragmentId, Microsoft.SharePoint.SPFileFragmentPartition[], System.IO.Stream, System.String, Boolean, SPLockType, System.String, System.TimeSpan, Boolean, Boolean, Boolean, Boolean, System.Guid, Microsoft.SharePoint.SPVirusCheckStatus ByRef, System.String ByRef, System.String ByRef, Boolean ByRef) Microsoft.SharePoint.Library.SPServerStorageBridge Microsoft.SharePoint.SPSecurity Microsoft.SharePoint.Utilities.SecurityContext.RunAsProcess(CodeToRunElevated) Microsoft.SharePoint.SPSecurity.RunWithElevatedPrivileges(System.Threading.WaitCallback, System.Object) Microsoft.SharePoint.SPSecurity.RunWithElevatedPrivileges(CodeToRunElevated) Microsoft.SharePoint.Library.SPServerStorageBridge.Microsoft.SharePoint.Library.IServerStorageBridge.PutStreams(Microsoft.SharePoint.Library.IStreamBridge, Microsoft.SharePoint.Library.IStreamBridge, System.String, Boolean, UInt64, System.String, System.String, System.String, Int32, System.String, Int32, Boolean, Boolean, Boolean, System.String ByRef, Boolean ByRef, System.String ByRef, UInt32 ByRef) Microsoft.SharePoint.Utilities.SandboxServerBigBridge.CallServerStorageBridge_PutStreams(Microsoft.SharePoint.Utilities.SandboxMessageType, Microsoft.SharePoint.Utilities.SandboxCommunicator) Microsoft.SharePoint.Utilities.SandboxServerBigBridge.EventLoopFor(Microsoft.SharePoint.Utilities.SandboxMessageType, Microsoft.SharePoint.Utilities.SandboxCommunicator) Microsoft.SharePoint.Utilities.SPUtility.PerformSandboxOperation(Microsoft.SharePoint.Utilities.SandboxCommunicator, Microsoft.SharePoint.Utilities.ExecuteCellStorageBinaryRequestParameters) Microsoft.SharePoint.Utilities.SPUtility.ExecuteCellStorageBinaryRequest(Microsoft.SharePoint.SPFile, Boolean, System.IO.Stream, Boolean, System.Guid ByRef, System.String, Boolean, System.String, Boolean, System.String, System.String, System.String, Int64, System.String, Int64, Boolean, System.String ByRef, Boolean ByRef, Int32 ByRef, System.String ByRef, Boolean ByRef, Boolean ByRef, Int32 ByRef) Microsoft.SharePoint.SoapServer.CellStoragesImpl Microsoft.SharePoint.SoapServer.CellStoragesImpl.FProcessSubRequests(System.Xml.XmlReader, System.Xml.XmlWriter, Microsoft.SharePoint.SPFile, System.Collections.Generic.Dictionary`2, ResourceQuota) Microsoft.SharePoint.SoapServer.CellStoragesImpl.FProcessRequest(Microsoft.SharePoint.SPWeb, System.Xml.XmlReader, System.Xml.XmlWriter, System.Collections.Generic.Dictionary`2, ResourceQuota) Microsoft.SharePoint.SoapServer.CellStoragesImpl System.ServiceModel.Channels.BodyWriter.WriteBodyContents(System.Xml.XmlDictionaryWriter) System.ServiceModel.Channels.Message.OnWriteMessage(System.Xml.XmlDictionaryWriter) System.ServiceModel.Channels.MtomMessageEncoder.WriteMessage(System.ServiceModel.Channels.Message, System.IO.Stream, System.String, System.String, System.String, Boolean) System.ServiceModel.Channels.HttpOutput.WriteStreamedMessage(System.TimeSpan) System.ServiceModel.Channels.HttpOutput.Send(System.TimeSpan) System.ServiceModel.Channels.HttpRequestContext.OnReply(System.ServiceModel.Channels.Message, System.TimeSpan) System.ServiceModel.Channels.RequestContextBase.Reply(System.ServiceModel.Channels.Message, System.TimeSpan) System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.Reply(System.ServiceModel.Dispatcher.MessageRpc ByRef) System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessageCleanup(System.ServiceModel.Dispatcher.MessageRpc ByRef) System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(System.ServiceModel.Dispatcher.MessageRpc ByRef) System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage4(System.ServiceModel.Dispatcher.MessageRpc ByRef) System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean) System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(System.ServiceModel.Channels.RequestContext, Boolean, System.ServiceModel.OperationContext) System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(System.ServiceModel.Channels.RequestContext, System.ServiceModel.OperationContext) System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(System.IAsyncResult) System.ServiceModel.Diagnostics.Utility System.ServiceModel.AsyncResult.Complete(Boolean) System.ServiceModel.Channels.InputQueue`1 System.ServiceModel.Channels.InputQueue`1[[System.__Canon, mscorlib]].EnqueueAndDispatch(Item, Boolean) System.ServiceModel.Channels.InputQueue`1[[System.__Canon, mscorlib]].EnqueueAndDispatch(System.__Canon, System.ServiceModel.Channels.ItemDequeuedCallback, Boolean) System.ServiceModel.Channels.InputQueueChannel`1[[System.__Canon, mscorlib]].EnqueueAndDispatch(System.__Canon, System.ServiceModel.Channels.ItemDequeuedCallback, Boolean) System.ServiceModel.Channels.SingletonChannelAcceptor`3[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Enqueue(System.__Canon, System.ServiceModel.Channels.ItemDequeuedCallback, Boolean) System.ServiceModel.Channels.SingletonChannelAcceptor`3[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Enqueue(System.__Canon, System.ServiceModel.Channels.ItemDequeuedCallback) System.ServiceModel.Channels.HttpChannelListener.HttpContextReceived(System.ServiceModel.Channels.HttpRequestContext, System.ServiceModel.Channels.ItemDequeuedCallback) System.ServiceModel.Activation.HostedHttpTransportManager.HttpContextReceived(System.ServiceModel.Activation.HostedHttpRequestAsyncResult) System.ServiceModel.Activation.HostedHttpRequestAsyncResult.BeginRequest() System.ServiceModel.Activation.HostedHttpRequestAsyncResult.OnBeginRequest(System.Object) System.ServiceModel.PartialTrustHelpers.PartialTrustInvoke(System.Threading.ContextCallback, System.Object) System.ServiceModel.Activation.HostedHttpRequestAsyncResult.OnBeginRequestWithFlow(System.Object) System.ServiceModel.Channels.IOThreadScheduler System.ServiceModel.Channels.IOThreadScheduler System.ServiceModel.Channels.IOThreadScheduler System.ServiceModel.Channels.IOThreadScheduler System.ServiceModel.Channels.IOThreadScheduler System.ServiceModel.Diagnostics.Utility System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*) User Time 01:37:04.765 Kernel time 00:00:05.553
Notice the User Time of over 1h30! Seems that a SQL statement was staying open. When taking the creation time of the thread, I was able to check the ULS logs with more info. There were calls to a certain OneNote file and the _vti_bin/cellstorage.svc/cellstorageservice.svc was called. There were also CsiSrvExe.exe processing starting at that point.
OneNote uses the Core Storage Infrastructure service to send user edits to the SharePoint server. This server stores the master copy of the notebook. The Core Storage Infrastructure service processes file writes by storing them in a hot table and then periodically flushing those writes to the actual file. Anyway, there was something seriously going wrong with this web service.
Using the command to list the requests:
C:\Windows\System32\inetsrv\appcmd.exe list request
I was able to determine an open connection that never was closed:
REQUEST "a90000018000473e" (url:POST /_vti_bin/cellstorage.svc/CellStorageService, time:1874982 msec, client:0.0.0.0, stage:ExecuteRequestHandler, module:ManagedPipelineHandler)
Checking the web.config of the web services, everything seemed fine and it should force close after a timeout. I searched for other experiences with the CellStorageService and found the following discussion:
The post by Doc WattsMan led me to the solution: switching from Kerberos to NTLM and back, the service seemed to be “resetted” and everything runs fine since then. I’m still trying to figure out which update caused the trouble, but in the meantime you can try the solution for yourself.
Bram Nuyts 