0

I've lately noticed that repeatedly writing the bytes to the same document in LINQPad ended up taking veery long: over 10 seconds.
It happens at least for DOCX and DOTX files, I suspect other Office file types are also problematic.
When I've created a simple repro application:

public static void Main(string[] args)
{
    var i = 0;
    var sw = Stopwatch.StartNew();
    do
    {
        sw.Restart();
        Run();
        sw.Stop();
    }
    while (++i < 50 && (i < 2 || sw.Elapsed < TimeSpan.FromSeconds(2)));
    Console.WriteLine($"I: {i}; Took: {sw.Elapsed.TotalSeconds:0.####} sec");
}

private static void Run()
{
    using (var site = new SPSite("SP SE Root Site URL"))
    using (var web = site.OpenWeb())
    {
        var bytes = File.ReadAllBytes(@"Empty DOCX file path");
        var destFile = web.GetFile("Shared%20Documents/existingFileName.docx");
        destFile.SaveBinary(bytes);
    }
}

It fails always with I: 13 :D. I know, I'm just having a bad luck.
It happens on my dev machines with SP 2019 and SP SE. On both after upgrading to May 2023 CU from some 2022 or older CUs.
It is still happening after upgrading to July CU on SP SE and June CU on SP 2019. It doesn't happen on my colleagues machines, even with the same CU setup. It doesn't happen on our test machines, with the same CU.
ULS logs are also having a 10 second whole, somewhere at the end of all Updating events.
When I attached VS debugger and paused the debugger during that pause I saw this call stack:

[Managed to Native Transition]
[Native to Managed Transition]
[Managed to Native Transition]
mscorlib.dll!System.IO.FileStream.Dispose(bool disposing)
Microsoft.SharePoint.dll!Microsoft.SharePoint.CoordinatedStreamBuffer.SPCoordinatedFileStream.Dispose(bool disposing)
mscorlib.dll!System.IO.Stream.Close()
Microsoft.SharePoint.dll!Microsoft.SharePoint.CoordinatedStreamBuffer.SPCoordinatedLockBytesBase.Close()
Microsoft.SharePoint.dll!Microsoft.SharePoint.FileStore.DisposableLockBytes.Dispose()
Microsoft.Cobalt.Base.dll!Cobalt.DisposalEscrow.Dispose()
Microsoft.SharePoint.dll!Microsoft.SharePoint.CobaltStream.Dispose()
Microsoft.SharePoint.dll!Microsoft.SharePoint.SPFileStreamManager.BindFileInfoToInput(ref Microsoft.SharePoint.Library.SPFileInfo fileInfo)
[Native to Managed Transition]
[Managed to Native Transition]
Microsoft.SharePoint.dll!Microsoft.SharePoint.Library.SPRequest.PutFile(string bstrUrl, Microsoft.SharePoint.Library.StorePath spWebRelativeUrl, object punkFile, long cbFile, object punkSPFileMgr, object punkFFM, Microsoft.SharePoint.Library.SPFileSaveParams sfsp, out Microsoft.SharePoint.Library.SPFileInfo pFileProps, out uint pdwVirusCheckStatus, out string pVirusCheckMessage, out string pEtagReturn, out byte piLevel, out int pbIgnoredReqProps, out int pcNonLimitedPrincipals)
Microsoft.SharePoint.dll!Microsoft.SharePoint.SPFile.SaveBinaryInternal(System.IO.Stream file, long fileSizeToSave, Microsoft.SharePoint.CoordinatedStreamBuffer.ISPFileStreamManager spmgr, bool isBackgroundSave, string checkInComment, bool checkRequiredFields, bool autoCheckoutOnInvalidData, bool bIsMigrate, bool bIsPublish, bool bForceCreateVersion, string lockIdMatch, Microsoft.SharePoint.SPUser modifiedBy, System.DateTime timeCreated, System.DateTime timeLastModified, object varProperties, Microsoft.SharePoint.SPFileFragmentPartition partitionToCheck, Microsoft.SharePoint.SPFileFragmentId fragmentIdToCheck, Microsoft.SharePoint.SPFileFragmentPartition[] fragPartitionsToDelete, string csvPartsToDelete, System.IO.Stream formatMetadata, string etagToMatch, bool bSyncUpdate, Microsoft.SharePoint.SPFile.SPLockType lockType, string lockId, System.TimeSpan lockTimeout, bool refreshLock, bool requireWebFilePermissions, bool failIfRequiredCheckout, bool validateReqFields, System.Guid newDocId, bool bypassMaxFileCheck, bool bypassQuotaCheck, bool bypassVirusScan, Microsoft.SharePoint.SPVirusCheckStatus newVirusStatus, int newVirusVendorId, string newVirusInfo, byte[] newVirusInfoEx, bool bUseTimeLastModified, bool bUseTimeCreated, bool persistBITSInfo, System.Guid BITSSessionId, System.Guid originatorId, string multiAuthEditActivityUserIds, out Microsoft.SharePoint.SPVirusCheckStatus virusCheckStatus, out string virusCheckMessage, out string etagReturn, out bool ignoredRequiredProps, out Microsoft.SharePoint.Library.SPFileInfo fileProps)
Microsoft.SharePoint.dll!Microsoft.SharePoint.SPFile.SaveBinary(System.IO.Stream file, Microsoft.SharePoint.SPFileSaveBinaryParameters parameters)
Microsoft.SharePoint.dll!Microsoft.SharePoint.SPFile.SaveBinary(System.IO.Stream file, bool checkRequiredFields, bool createVersion, string etagMatch, string lockIdMatch, System.IO.Stream fileFormatMetaInfo, bool requireWebFilePermissions, out string etagNew)
Microsoft.SharePoint.dll!Microsoft.SharePoint.SPFile.SaveBinary(byte[] file)

What matches to ULS logs which are mentioning diposing of CobaltStream around the pause.
Unfortunately this is where my debugging skills failed me. I've checked XEvents on SQL server. Nothing happens during the pause. I've looked into ProcMon and it also didn't hint at anything useful. And given the repetitiveness of going from several hundred milliseconds to over 10 seconds just looks like it adds 10 second Thread.Sleep but from the stack trace it looks like it happens somewhere in the native code.

Did anyone had similar issue or know how to further debug this?

As this only happens on my devboxes I will probably create new ones and burn those to the ground. But it would be nice to know the cause, if it would appear somewhere else in the future.

0

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Browse other questions tagged or ask your own question.