Dsc v5 get-psdrive abnormal I/O

DSC
1

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

2

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.

3

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

4

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.

5

@brak, just wondering if you’re also seeing the xRegistry resource increasingly taking longer to run? https://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.

6

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