Dsc v5 get-psdrive abnormal I/O

This topic contains 5 replies, has 3 voices, and was last updated by Profile photo of Zuldan Zuldan 4 months, 3 weeks ago.

Viewing 6 posts - 1 through 6 (of 6 total)
  • Author
    Posts
  • #38470
    Profile photo of brik brac
    brik brac
    Participant

    Hello,
    I am currently having a major I/O performance issue when using dsc v5. I've been using dsc (v4) for almost 2 years without any issue, but last week I installed WMF5.0 on all servers (250 servers running Win2K8R2) and I started to have some abnormal disk latencies on my servers.
    Process Monitor showed that WMI host process was doing a lot of WriteFile operation to this folder: C:\Windows\System32\config\systemprofile\AppData\Local\Microsoft\Windows\PowerShell\CommandAnalysis\PowerShell_AnalysisCacheEntry_*
    Which apparently is some kind of cache folder for imported modules.
    http://www.powertheshell.com/how-module-command-discovery-works-in-psv3/
    The amount of operation is increasing over time up to 200.000 operations each time dsc pull is triggered…

    I've then used DSC debug mode to find out which module/resource was causing this, it turned out that write operations are done each time get-psdrive command is called, which is also calling the module manifest Microsoft.Powershell.Security.psd1
    The get-psdrive command is used at several places, like in the default Registry resource for instance, which can be called more than 10 times in my configurations.
    Here is the stack trace of the WMI host process when writing the code analysis files:
    ntdll.dll!ZwWriteFile+0xa
    KERNELBASE.dll!WriteFile+0x7b
    kernel32.dll!WriteFile+0x36
    [Native Frame: IL Method without Metadata]
    [Managed to Unmanaged Transition]
    mscorlib.dll!System.IO.FileStream.WriteFileNative+0x9b
    mscorlib.dll!System.IO.FileStream.WriteCore+0x67
    mscorlib.dll!System.IO.FileStream.Write+0xff
    System.Runtime.Serialization.dll!System.Xml.XmlBinaryNodeWriter.FlushBuffer+0x27
    System.Runtime.Serialization.dll!System.Xml.XmlStreamNodeWriter.GetBuffer+0x2d
    System.Runtime.Serialization.dll!System.Xml.XmlBinaryNodeWriter.WriteName+0x8a
    System.Runtime.Serialization.dll!System.Xml.XmlBinaryNodeWriter.WriteStartElement+0xe3
    System.Runtime.Serialization.dll!System.Xml.XmlBinaryNodeWriter.WriteStartElement+0x12d
    System.Runtime.Serialization.dll!System.Xml.XmlBaseWriter.WriteStartElement+0x57
    System.Runtime.Serialization.dll!System.Runtime.Serialization.XmlWriterDelegator.WriteStartElement+0x23
    [Unmanaged to Managed Transition]
    [Native Frame: IL Method without Metadata]
    [Managed to Unmanaged Transition]
    System.Runtime.Serialization.dll!System.Runtime.Serialization.CollectionDataContract.WriteXmlValue+0x41
    System.Runtime.Serialization.dll!System.Runtime.Serialization.XmlObjectSerializerWriteContext.InternalSerialize+0x6d
    System.Runtime.Serialization.dll!System.Runtime.Serialization.XmlObjectSerializerWriteContext.InternalSerializeReference+0x6f
    [Unmanaged to Managed Transition]
    [Native Frame: IL Method without Metadata]
    [Managed to Unmanaged Transition]
    System.Runtime.Serialization.dll!System.Runtime.Serialization.ClassDataContract.WriteXmlValue+0x31
    [Unmanaged to Managed Transition]
    [Native Frame: IL Method without Metadata]
    [Managed to Unmanaged Transition]
    System.Runtime.Serialization.dll!System.Runtime.Serialization.CollectionDataContract.WriteXmlValue+0x41
    System.Runtime.Serialization.dll!System.Runtime.Serialization.XmlObjectSerializerWriteContext.InternalSerialize+0x6d
    System.Runtime.Serialization.dll!System.Runtime.Serialization.XmlObjectSerializerWriteContext.InternalSerializeReference+0x6f
    [Unmanaged to Managed Transition]
    [Native Frame: IL Method without Metadata]
    [Managed to Unmanaged Transition]
    System.Runtime.Serialization.dll!System.Runtime.Serialization.ClassDataContract.WriteXmlValue+0x31
    System.Runtime.Serialization.dll!System.Runtime.Serialization.DataContractSerializer.InternalWriteObjectContent+0x11c
    System.Runtime.Serialization.dll!System.Runtime.Serialization.DataContractSerializer.InternalWriteObject+0x39
    System.Runtime.Serialization.dll!System.Runtime.Serialization.XmlObjectSerializer.WriteObjectHandleExceptions+0x285
    System.Runtime.Serialization.dll!System.Runtime.Serialization.XmlObjectSerializer.WriteObject+0x85
    System.Management.Automation.dll!System.Management.Automation.AnalysisCache.SerializeToFile+0x2ec
    System.Management.Automation.dll!System.Management.Automation.AnalysisCache.Cache+0x556
    System.Management.Automation.dll!System.Management.Automation.AnalysisCache.CacheExportedCommands+0x6b8
    System.Management.Automation.dll!Microsoft.PowerShell.Commands.ModuleCmdletBase.LoadUsingModulePath+0x380
    System.Management.Automation.dll!Microsoft.PowerShell.Commands.ImportModuleCommand.ImportModule_LocallyViaName+0xb8c
    System.Management.Automation.dll!Microsoft.PowerShell.Commands.ImportModuleCommand.ProcessRecord+0x501
    System.Management.Automation.dll!System.Management.Automation.CommandProcessor.ProcessRecord+0x3e8
    System.Management.Automation.dll!System.Management.Automation.CommandProcessorBase.DoExecute+0xe5
    System.Management.Automation.dll!System.Management.Automation.Internal.PipelineProcessor.SynchronousExecuteEnumerate+0x183
    System.Management.Automation.dll!System.Management.Automation.Runspaces.LocalPipeline.InvokeHelper+0x77b
    System.Management.Automation.dll!System.Management.Automation.Runspaces.LocalPipeline.InvokeThreadProc+0x2ce
    System.Management.Automation.dll!System.Management.Automation.Runspaces.LocalPipeline.StartPipelineExecution+0x321
    System.Management.Automation.dll!System.Management.Automation.Runspaces.PipelineBase.CoreInvoke+0x2e5
    System.Management.Automation.dll!System.Management.Automation.Runspaces.PipelineBase.Invoke+0x24
    System.Management.Automation.dll!Worker.ConstructPipelineAndDoWork+0x2de
    System.Management.Automation.dll!System.Management.Automation.PowerShell.CoreInvokeHelper+0x350
    System.Management.Automation.dll!System.Management.Automation.PowerShell.CoreInvoke+0x48e
    System.Management.Automation.dll!System.Management.Automation.PowerShell.CoreInvoke+0x1ba
    System.Management.Automation.dll!System.Management.Automation.CommandDiscovery.AutoloadSpecifiedModule+0x309
    System.Management.Automation.dll!System.Management.Automation.SessionStateInternal.MountDefaultDrive+0x220
    Microsoft.PowerShell.Commands.Management.dll!Microsoft.PowerShell.Commands.GetPSDriveCommand.BeginProcessing+0x1b
    System.Management.Automation.dll!System.Management.Automation.Cmdlet.DoBeginProcessing+0x61
    System.Management.Automation.dll!System.Management.Automation.CommandProcessorBase.DoBegin+0x255
    System.Management.Automation.dll!System.Management.Automation.CommandProcessor.DoBegin+0x15e
    System.Management.Automation.dll!System.Management.Automation.Internal.PipelineProcessor.Start+0x263
    System.Management.Automation.dll!System.Management.Automation.Internal.PipelineProcessor.SynchronousExecuteEnumerate+0xcd
    System.Management.Automation.dll!System.Management.Automation.PipelineOps.InvokePipeline+0x278
    [Unmanaged to Managed Transition]
    [Native Frame: IL Method without Metadata]
    [Managed to Unmanaged Transition]
    System.Management.Automation.dll!System.Management.Automation.Interpreter.LightLambda.RunVoid1+0x85
    System.Management.Automation.dll!System.Management.Automation.PSScriptCmdlet.RunClause+0x325
    System.Management.Automation.dll!System.Management.Automation.CommandProcessorBase.Complete+0xb9
    System.Management.Automation.dll!System.Management.Automation.CommandProcessorBase.DoComplete+0x15d
    System.Management.Automation.dll!System.Management.Automation.Internal.PipelineProcessor.DoCompleteCore+0xc1
    System.Management.Automation.dll!System.Management.Automation.Internal.PipelineProcessor.SynchronousExecuteEnumerate+0x19b
    System.Management.Automation.dll!System.Management.Automation.Runspaces.LocalPipeline.InvokeHelper+0x77b
    System.Management.Automation.dll!System.Management.Automation.Runspaces.LocalPipeline.InvokeThreadProc+0x2ce
    System.Management.Automation.dll!System.Management.Automation.Runspaces.LocalPipeline.StartPipelineExecution+0x321
    System.Management.Automation.dll!System.Management.Automation.Runspaces.PipelineBase.CoreInvoke+0x2e5
    System.Management.Automation.dll!System.Management.Automation.Runspaces.PipelineBase.Invoke+0x24
    System.Management.Automation.dll!Worker.ConstructPipelineAndDoWork+0x2de
    System.Management.Automation.dll!Worker.CreateRunspaceIfNeededAndDoWork+0x244
    System.Management.Automation.dll!System.Management.Automation.PowerShell.CoreInvokeHelper+0x319
    System.Management.Automation.dll!System.Management.Automation.PowerShell.CoreInvoke+0x48e
    System.Management.Automation.dll!System.Management.Automation.PowerShell.CoreInvoke+0x1ba
    System.Management.Automation.dll!System.Management.Automation.PowerShell.Invoke+0xf6
    Microsoft.Windows.DSC.CoreConfProviders.dll!Microsoft.PowerShell.DesiredStateConfiguration.Internal.ResourceProviderAdapter.ExecuteCommand+0x45e
    Microsoft.Windows.DSC.CoreConfProviders.dll!Microsoft.PowerShell.DesiredStateConfiguration.Internal.ResourceProviderAdapter.ExecuteProviderCommand+0x672
    Microsoft.Windows.DSC.CoreConfProviders.dll!Microsoft.PowerShell.DesiredStateConfiguration.Internal.ResourceProviderAdapter.TestTargetResource+0xec
    Microsoft.Windows.DSC.CoreConfProviders.dll!Microsoft.PowerShell.DesiredStateConfiguration.Internal.DscPluginManagedEntryWrapper.Test+0x14f
    [Unmanaged to Managed Transition]
    [Native Frame: IL Method without Metadata]
    clr.dll!GetMetaDataInternalInterface+0xd163
    clr.dll!GetMetaDataInternalInterface+0x71e9a
    [Managed to Unmanaged Transition]
    [AppDomain Transition]
    [Unmanaged to Managed Transition]
    clr.dll!GetMetaDataInternalInterface+0x6abcf
    clr.dll!GetMetaDataInternalInterface+0x71e15
    clr.dll!GetMetaDataInternalInterface+0xd10d
    DscCore.dll!DllGetClassObject+0x38eaa
    DscCore.dll!DllGetClassObject+0x3fcd1
    DscCore.dll!DllGetClassObject+0x3d6c6
    DscCore.dll!DllGetClassObject+0x3c1fc
    DscCore.dll!DllGetClassObject+0x3d328
    DscCore.dll!DllGetClassObject+0x16964
    DscCore.dll!DllGetClassObject+0x17454
    DscCore.dll!DllGetClassObject+0x166db
    DscCore.dll!DllGetClassObject+0x14703
    DscCore.dll!DllGetClassObject+0x14913
    DscCore.dll!DllGetClassObject+0x1ab34
    DscCore.dll!DllGetClassObject+0xef1a
    DscCore.dll!DllGetClassObject+0x23aee
    DscCore.dll!DllGetClassObject+0x2545b
    ntdll.dll!TpCallbackMayRunLong+0x32b
    ntdll.dll!TpDisassociateCallback+0x2f2
    kernel32.dll!BaseThreadInitThunk+0xd
    ntdll.dll!RtlUserThreadStart+0x21

    I've setup a new server running Win 2012R2, and the behavior is the same.
    I currently have no idea how to fix this.
    Has anybody experienced the same behavior? Can someone explain why this cache entry is being recreated each time the command is called?
    Any suggestion is welcome at this point...
    Thanks

    briac

    #38472
    Profile photo of Arie H
    Arie H
    Participant

    We've seen similar issues before, specifically with the registry resource having the time running the configuration script running 1 sec and gradually increasing to minutes during a day. A restart to the server lowered it back to 1 sec.

    I remember an issue was raised in uservoice but don't think I've seen any official word on this. You might want to open one yourself addind all the logs and material to aid them in pinpointing the problem.

    My initial thought was to write my own registry resource, and even opened an issue on the the github repo as I found the coding itself was lacking consideration of performance, but seems its much more low level then that.

    #38521
    Profile photo of brik brac
    brik brac
    Participant

    Thanks for your feedback Arie, as suggested I created a post on the uservoice :
    https://windowsserver.uservoice.com/forums/301869-powershell/suggestions/13703175-get-psdrive-abnormal-i-o
    Hopefully someone will pick it up...
    In the meanwhile I've tested listing physical drives using WMI class instead of get-psdrive cmdlet, and the problem doesn't show up, but this is not a solving anything....

    briac

    #38522
    Profile photo of Zuldan
    Zuldan
    Participant

    Brik we have the exact same issue in our environment. The disk activity slowly starts creeping up and consistency checks take longer and longer to run. It's a massive issue for us because we use Riverbed SteelFusions under our VM's at remote offices. Basically C: gets replicated over the WAN realtime back to our datacenter. Over time PS5 DSC generates a HUGE amount of IO in the CommandAnalysis directory. I'm 100% this is a bug and I'm glad someone else is seeing it too.

    I found terrible work around but it seems to work. Set a scheduled task to kill all wmiprvse.exe processes every 24 hours. This appears to be as good as rebooting the server. The disk IO that was slowly building up massively drops. If I didn't have this scheduled task running on all 200 servers I would have to decommission DSC from the entire environment and DSC would be banned.

    I'm also using a dirty hack to reduce WAN traffic and Microsoft would probably vomit but there's nothing else I could do..... I'm using a symbolic link to redirect the CommandAnalysis directory to another disk that isn't replicated over the WAN.

    If you put up a UserVoice I'll vote up on it. I fear though Microsoft will only look into it only if it has 100 plus votes or so. I'm certain this issue is occurring on every else's environment they just don't realise it.

    #38523
    Profile photo of Zuldan
    Zuldan
    Participant

    @brak, just wondering if you're also seeing the xRegistry resource increasingly taking longer to run? http://powershell.org/forums/topic/every-registry-resource-takes-25-seconds-to-set/

    Arie has pointed out in the past that xRegistry uses Get-PSDrive a lot.

    #39026
    Profile photo of Zuldan
    Zuldan
    Participant

    Microsoft are going to get this one fixed! yay

    "Zachary Alexander (Program Manager, Windows Server) responded · May 13, 2016 We fixed this on an internal build. Investigating when this fix will go public."

    https://windowsserver.uservoice.com/forums/301869-powershell/suggestions/13703175-get-psdrive-abnormal-i-o

Viewing 6 posts - 1 through 6 (of 6 total)

You must be logged in to reply to this topic.