Every 'Registry' resource takes 25 seconds to 'Set'

I have roughly 85 resource configs for each server. 21 of those are using the Registry resource.

If I apply a DSC config to a freshly built Windows 2012 R2 (WMF 5 RTMv2) server, each Registry config takes less than 1 second to ‘Set’. However, after 24 hours or so each Registry resource is taking at least 25 seconds to ‘Set’. The other 64 configs still take less than 1 second.

If I reboot the server, each Registry resource goes back to taking under 1 second to ‘Set’. Is anyone else seeing this behavior?

Registry SetRegisteredOwner
{
Ensure = ‘Present’
Force = $True
Key = ‘HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Microsoft\Windows NT\CurrentVersion’
ValueName = ‘RegisteredOwner’
ValueType = ‘String’
ValueData = $Node.RegisteredOwner
}

VERBOSE: [LABSERVER01]: [[Registry]SetRegisteredOwner] Found registry key value ‘HKLM:\SOFTWARE\Wow6432Node\Microsoft\Windows NT\CurrentVersion\RegisteredOwner’ with type ‘String’ and data ‘IT’
VERBOSE: [LABSERVER01]: LCM: [ End Test ] [[Registry]SetRegisteredOwner] in 25.9840 seconds.

Hi,

Do you install any software by default, during the provision? Especially any AV ones ?

Do you use cross-node dependency in your resources ?

The fact it goes back to ‘normal’ after restart sounds to me like cache or memory depending process on the node. Perhaps monitoring the node with few of the sysinternals tools will assist in pinpointing the source of this.

Hi Arie, thank you for the quick response.

> Do you install any software by default, during the provision? Especially any AV ones ?

Yes our standard server software gets provisioned including AV. I disabled AV on a server and tried to do a consistency check but the Register resource still takes a very long time to process.

Any other ideas?

Zuldan, roughly how much time it is taking between “[Start Test]” and “Found registry key” messages and “Found registry key” and “[End Test]” messages?

Hi Nitin, here are the timings; (title should be ‘set’ and ‘test’ take 25+ seconds)

In a new test I performed, it’s taking 31 seconds to get from “Start Test” to “Found registry key value”

Start Resource 0.5 seconds
Start Test -> 31 seconds
-> “Found registry key value”
End Test -> 0.5 seconds
Skip Set -> 0.5 seconds
End Resource -> 0.5 seconds

It appears that loading the module $env:windir\System32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\DSCResources\MSFT_RegistryResource\MSFT_RegistryResource.psm1 is taking a long time. Can you try importing this module directly in PS and call Test-TargetResource to check if it is taking approx same time:

  1. import-module $env:windir\System32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\DSCResources\MSFT_RegistryResource\MSFT_RegistryResource.psm1
  2. MSFT_RegistryResource\Test-TargetResource -Key HKLM:\SOFTWARE -ValueName TestValue -ValueData TestValue

Looks like the search itself is taking the long time, not the loading of the module.

Zuldan, do the 21 resource configs have a lot of reg keys in them each or just one per config ?

From what I see in the resource, its implementing a lot of PSDrives with a Script scope. I know this means the drive will be removed once the script is done, but shouldn’t there be a Remove-PSDrive as well for at least good closure dev practices?

From the LCM point of view you can turn debug mode to true and look in the logs to look for issues.

I still think you should also use sysinternal monitoring tools after a server restart and through out a day to look for processes getting bigger in terms of memory through the time period and compare it to normal server behavior

Hi Nitin, here are the results.

[TESTSERVER01]: PS C:> Measure-Command -Expression { import-module $env:windir\System32\WindowsPowerShell\v1.0\Modul
es\PSDesiredStateConfiguration\DSCResources\MSFT_RegistryResource\MSFT_RegistryResource.psm1 }.

Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 88
Ticks : 884084
TotalDays : 1.02324537037037E-06
TotalHours : 2.45578888888889E-05
TotalMinutes : 0.00147347333333333
TotalSeconds : 0.0884084
TotalMilliseconds : 88.4084

[TESTSERVER01]: PS C:> Measure-Command -Expression { MSFT_RegistryResource\Test-TargetResource -Key HKLM:\SOFTWARE -ValueName TestValue -ValueData }

Days : 0
Hours : 0
Minutes : 0
Seconds : 1
Milliseconds : 265
Ticks : 12656205
TotalDays : 1.46483854166667E-05
TotalHours : 0.00035156125
TotalMinutes : 0.021093675
TotalSeconds : 1.2656205
TotalMilliseconds : 1265.6205

[TESTSERVER01]: PS C:> MSFT_RegistryResource\Test-TargetResource -Key HKLM:\SOFTWARE -ValueName TestValue -ValueData
TestValue
False

It looks like the delay only occurs when the resource is run from the DSC engine. I ran a consistency check right after performing the tests and Registry was taking 31 seconds again.

@Arie,

-> Zuldan, do the 21 resource configs have a lot of reg keys in them each or just one per config ?

Only 1 reg key per config.

Ok hopefully this will help… I’m now using xRegistry but getting the same delay with it. I added some verbose to get timing on how long certain parts of Test-TargetResource is taking. I hope this helps with the diagnosis.

VERBOSE: [SERVERLAB01]: LCM: [ Start Resource ] [[xRegistry]MyConfig]
VERBOSE: [SERVERLAB01]: LCM: [ Start Test ] [[xRegistry]MyConfig]
VERBOSE: [SERVERLAB01]: [[xRegistry]MyConfig] 06:06:45 111111111111111111111111
VERBOSE: [SERVERLAB01]: [[xRegistry]MyConfig] 06:06:53 2222222222222222222222222
VERBOSE: [SERVERLAB01]: [[xRegistry]MyConfig] 06:07:00 3333333333333333333333333
VERBOSE: [SERVERLAB01]: [[xRegistry]MyConfig] 06:07:00 4444444444444444444444444444444444
VERBOSE: [SERVERLAB01]: [[xRegistry]MyConfig] 06:07:06 55555555555555555555555555555
VERBOSE: [SERVERLAB01]: [[xRegistry]MyConfig] 06:07:06 666666666666666666666666666666
VERBOSE: [SERVERLAB01]: [[xRegistry]MyConfig] Found registry key value ‘HKLM:\SOFTWARE\CompanyVersion’ with type ‘DWord’ and data ‘1004’
VERBOSE: [SERVERLAB01]: [[xRegistry]MyConfig] 06:07:06 7777777777777777777777777777777
VERBOSE: [SERVERLAB01]: LCM: [ End Test ] [[xRegistry]MyConfig] in 20.8750 seconds.
VERBOSE: [SERVERLAB01]: LCM: [ Skip Set ] [[xRegistry]MyConfig]
VERBOSE: [SERVERLAB01]: LCM: [ End Resource ] [[xRegistry]MyConfig]

------------Snip---------------
Write-Verbose “$(Get-Date -format “hh:mm:ss”) 111111111111111111111111”

# Perform any required setup steps for the provider
SetupProvider -KeyName ([ref]$Key)

# Query if the RegVal related parameters have been specified
$ValueNameSpecified = $PSBoundParameters.ContainsKey("ValueName")
$ValueTypeSpecified = $PSBoundParameters.ContainsKey("ValueType")
$ValueDataSpecified = $PSBoundParameters.ContainsKey("ValueData")

Write-Verbose "$(Get-Date -format "hh:mm:ss") 2222222222222222222222222"

# If an empty string ValueName has been specified and no ValueType and no ValueData has been specified,
# treat this case as if ValueName was not specified and target the Key itself. This is to cater the limitation
# that both Key and ValueName are mandatory now and we must special-case like this to target the Key only.
if (($ValueName -eq "") -and !$ValueTypeSpecified -and !$ValueDataSpecified)
{
    $ValueNameSpecified = $false
}

# Now, query the specified key
$keyInfo = Get-TargetResourceInternal -Key $Key -Verbose:$false

Write-Verbose "$(Get-Date -format "hh:mm:ss") 3333333333333333333333333"

# ----------------
# ENSURE = PRESENT
if ($Ensure -ieq "Present")
{
    # If key doesn't exist, the test fails
    if ($keyInfo.Ensure -ieq "Absent")
    {
        Write-Verbose ($localizedData.RegKeyDoesNotExist -f $Key)

        return $false
    }

    # If $ValueName, $ValueType and $ValueData are not specified, the simple existence of the Regkey satisfies the Ensure=Present condition, test is successful
    if (!$ValueNameSpecified -and !$ValueDataSpecified -and !$ValueTypeSpecified)
    {
        Write-Verbose ($localizedData.RegKeyExists -f $Key)

        return $true
    }

    Write-Verbose "$(Get-Date -format "hh:mm:ss") 4444444444444444444444444444444444"

    # IF THE CONTROL REACHED HERE, THE KEY EXISTS AND A REGVALUE ATTRIBUTE HAS BEEN SPECIFIED

    # Get the appropriate display name for the specified ValueName (to handle the Default RegValue case)
    $valDisplayName = GetValueDisplayName -ValueName $ValueName

    # Now query the specified Reg Value
    $valData = Get-TargetResourceInternal -Key $Key -ValueName $ValueName -Verbose:$false

    # If the Value doesn't exist, the test has failed
    if ($valData.Ensure -ieq "Absent")
    {
        Write-Verbose ($localizedData.RegValueDoesNotExist -f "$Key\$valDisplayName")

        return $false
    }

    Write-Verbose "$(Get-Date -format "hh:mm:ss") 55555555555555555555555555555"

    # IF THE CONTROL REACHED HERE, THE KEY EXISTS AND THE SPECIFIED (or Default) VALUE EXISTS

    # If the $ValueType has been specified and it doesn't match the type of the found RegValue, test fails
    if ($ValueTypeSpecified -and ($ValueType -ine $valData.ValueType))
    {
        Write-Verbose ($localizedData.RegValueTypeMismatch -f "$Key\$valDisplayName", $ValueType)

        return $false
    }

    # If an explicit ValueType has not been specified, given the Value already exists in Registry, assume the ValueType to be of the existing Value
    if (!$ValueTypeSpecified)
    {
        $ValueType = $valData.ValueType
    }

    Write-Verbose "$(Get-Date -format "hh:mm:ss") 666666666666666666666666666666"

    # If $ValueData has been specified, match the data of the found Regvalue.
    if ($ValueDataSpecified -and !(ValueDataMatches -RetrievedValue $valData -ValueType $ValueType -ValueData $ValueData))
    {
        # Since the $ValueData specified didn't match the data of the found RegValue, test failed
        Write-Verbose ($localizedData.RegValueDataMismatch -f "$Key\$valDisplayName", $ValueType, (ArrayToString -Value $ValueData))

        return $false
    }

    # IF THE CONTROL REACHED HERE, ALL TESTS HAVE PASSED FOR THE SPECIFIED REGISTRY VALUE AND IT COMPLETELY MATCHES, REPORT SUCCESS

    Write-Verbose ($localizedData.RegValueExists -f "$Key\$valDisplayName", $valData.ValueType, (ArrayToString -Value $valData.Data))

    Write-Verbose "$(Get-Date -format "hh:mm:ss") 7777777777777777777777777777777"

    return $true
}

---------snip-----------

So it’s taking almost 10 seconds to process the following code. Anyone have any idea why there would be so much delay?

Perform any required setup steps for the provider

SetupProvider -KeyName ([ref]$Key)

Query if the RegVal related parameters have been specified

$ValueNameSpecified = $PSBoundParameters.ContainsKey(“ValueName”)
$ValueTypeSpecified = $PSBoundParameters.ContainsKey(“ValueType”)
$ValueDataSpecified = $PSBoundParameters.ContainsKey(“ValueData”)

Kinda fits with what i was thinking at the start.

Since you already changed the MSFT_xRegistryResource.psm1 file, do add the following:

After SetUpProvider and before the three $PSBoundParameters, add another Write-Verbose command. Im still preety sure its the PSDrives inside SetUpProvider, but to be safe it would be nice to see where those almost 10 sec are spent.

In SetupProvider function, after the set of IF statements and before MountRequiredRegistryHives, add a Write-Verbose command, do so after MountRequiredRegistryHives and before ValidatePSDrive as well.

The code uses waaaayyy too many $KeyName.Value.ToString() unnecessarily for every if statement. Not that this in itself should explain for almost 10 sec excution time but its just a bit of “bad” programming method. Not to mention the use of IF statements in SetupProvider is wrong, its should be a Case statement as its causing unnecesasry IF checks when a value is found based on $keyName early on.

Thanks for sticking to the problem, Zuldan. Forces me to go deeper in the code and find these issues :slight_smile:

Arie, thank you for persisting with this. I think your suspicions are correct. It’s really weird they are using PSDrive to perform registry stuff. It would be much quicker to just connect to the registry directly.

The verbose now looks like this

-------snip-------------
Write-Verbose “$(Get-Date -format “hh:mm:ss”) 111111111111111111111111”

# Perform any required setup steps for the provider
SetupProvider -KeyName ([ref]$Key)

Write-Verbose "$(Get-Date -format "hh:mm:ss") 2222222222222222222222222"

---------snip------------

SetUpProvider is taking 10 seconds.

VERBOSE: [TESTSERVER01]: Starting consistency engine.
VERBOSE: [TESTSERVER01]: Checking consistency for current configuration.
VERBOSE: [TESTSERVER01]: LCM: [ Start Resource ] [[xRegistry]MyConfig]
VERBOSE: [TESTSERVER01]: LCM: [ Start Test ] [[xRegistry]MyConfig]
VERBOSE: [TESTSERVER01]: [[xRegistry]MyConfig] 08:24:17 111111111111111111111111
VERBOSE: [TESTSERVER01]: [[xRegistry]MyConfig] 08:24:27 2222222222222222222222222
VERBOSE: [TESTSERVER01]: [[xRegistry]MyConfig] 08:24:38 3333333333333333333333333
VERBOSE: [TESTSERVER01]: [[xRegistry]MyConfig] 08:24:38 4444444444444444444444444444444444
VERBOSE: [TESTSERVER01]: [[xRegistry]MyConfig] 08:24:46 55555555555555555555555555555
VERBOSE: [TESTSERVER01]: [[xRegistry]MyConfig] 08:24:46 666666666666666666666666666666
VERBOSE: [TESTSERVER01]: [[xRegistry]MyConfig] Found registry key value ‘HKLM:\SOFTWARE\CompanyVersion\Build’ with type ‘DWord’ and data ‘1004’
VERBOSE: [TESTSERVER01]: [[xRegistry]MyConfig] 08:24:46 7777777777777777777777777777777
VERBOSE: [TESTSERVER01]: LCM: [ End Test ] [[xRegistry]MyConfig] in 29.1870 seconds.
VERBOSE: [TESTSERVER01]: LCM: [ Skip Set ] [[xRegistry]MyConfig]
VERBOSE: [TESTSERVER01]: LCM: [ End Resource ] [[xRegistry]MyConfig]

I’m now trying to time the code in SetupProvider but I can’t get it to display Verbose or Write to a file which makes me think the function is cached in memory and doesn’t have my changes.

param
(
    [ValidateNotNull()]
    [ref] $KeyName
)

"$(Get-Date -format "hh:mm:ss") SetupProvider 111111111111111111111111" | Out-File -FilePath E:\timing.txt -Append

# Fix $KeyName if required
if (!$KeyName.Value.ToString().Contains(":"))
{

I got the timings for SetupProvider. It appears MountRequiredRegistryHives and ValidatePSDrive are the time killers here. 4 seconds each.

09:05:54 SetupProvider 111111111111111111111111
09:05:54 SetupProvider 222222222222222222222222
09:05:58 SetupProvider 333333333333333333333333
09:06:02 SetupProvider 444444444444444444444444

FUNCTION SetupProvider{ param ( [ValidateNotNull()] [ref] $KeyName ) “$(Get-Date -format “hh:mm:ss”) SetupProvider 111111111111111111111111” | Out-File -FilePath E:\timing.txt -Append # Fix $KeyName if required if (!$KeyName.Value.ToString().Contains(“:”)) { if ($KeyName.Value.ToString().StartsWith(“hkey_users”,“OrdinalIgnoreCase”)) { $KeyName.Value = $KeyName.Value.ToString() -replace “hkey_users”, “HKUS:” } elseif ($KeyName.Value.ToString().StartsWith(“hkey_current_config”,“OrdinalIgnoreCase”)) { $KeyName.Value = $KeyName.Value.ToString() -replace “hkey_current_config”, “HKCC:” } elseif ($KeyName.Value.ToString().StartsWith(“hkey_classes_root”,“OrdinalIgnoreCase”)) { $KeyName.Value = $KeyName.Value.ToString() -replace “hkey_classes_root”, “HKCR:” } elseif ($KeyName.Value.ToString().StartsWith(“hkey_local_machine”,“OrdinalIgnoreCase”)) { $KeyName.Value = $KeyName.Value.ToString() -replace “hkey_local_machine”, “HKLM:” } elseif ($KeyName.Value.ToString().StartsWith(“hkey_current_user”,“OrdinalIgnoreCase”)) { $KeyName.Value = $KeyName.Value.ToString() -replace “hkey_current_user”, “HKCU:” } else { $errorMessage = $localizedData.InvalidRegistryHiveSpecified -f $Key ThrowError -ExceptionName “System.ArgumentException” -ExceptionMessage $errorMessage -ExceptionObject $KeyName -ErrorId “InvalidRegistryHive” -ErrorCategory InvalidArgument } } “$(Get-Date -format “hh:mm:ss”) SetupProvider 222222222222222222222222” | Out-File -FilePath E:\timing.txt -Append # Mount any required registry hives MountRequiredRegistryHives -KeyName $KeyName.Value.ToString() “$(Get-Date -format “hh:mm:ss”) SetupProvider 333333333333333333333333” | Out-File -FilePath E:\timing.txt -Append # Check the target PSDrive to be a valid Registry Hive root ValidatePSDrive -Key $KeyName.Value.ToString() “$(Get-Date -format “hh:mm:ss”) SetupProvider 444444444444444444444444” | Out-File -FilePath E:\timing.txt -Append}

From your previous timing and latest, it seems both functions grow in execution time at the same rate, doubling the execution time for each session.

The use of PSDrive is to make it available as if it was a directory to ease reg keys management. But alot of the execution time is going on everything else except setting the key or querying the keys existence. There are so many tests and double checking inside that I’m surprised you see it taking 1sec at the start.

Just the code in SetupProvider I managed to rewrite it to take 50% less time but that isn’t the time “spender”.

Might have to write your own dsc resource to get better performance, while making sure your case is on UserVoice so PS team can try and fix it.

One of the PS team members wrote a very interesting article about debugging dsc in v5. Think its worth a good read now.

Thanks for your help Arie. It looks like it’s time to write my own Registry resource. All the PSDrive use and text conversion in the current resource is nuts.

Or, go to the githib. Fork the dsc resource to your repo, write it in a more efficient manner and open an issue and ask them to go over it and if its good it will be merged into the main code so everyone using it will benefit. I might beat you to it, given the time :wink:

Yes I could fork it but the problem is I don’t like the current design. I would want to write a more efficient version (which I’ll probably never get time to do).

My boss is laughing at me because I’ve spent months selling him DSC and he has a chuckle because servers are taking 30+ minutes to perform a consistency check on each server :frowning:

I’ll happily be your first beta tester your optimised version of xRegistry :slight_smile:

You should sell DevOps as an idea, a thought, a mindset. The tools then become less of a point.

DSC is simply a tool among many that you will have to use and combine to match your needs. The fact that you can write and implement your version of a resource is blessing as you dont have to rely on someone else’s free time to support you or extend it to match your specific needs, when its an OSS projects. The added value is giving back to the community, that’s why xDSCResources went public.

@Arie, I totally agree. I’m currently reading The Phoenix Project :wink: The problem is the boss walked in the door one day and said I’m going with SCCM for software deployment (which was never designed to be used with servers) unless you have another solution. I knew DSC could do software deployment as well as configuration so I said skip SCCM and go with DSC. He then gave me a couple of months to build a DSC system with a work flow system. I kinda did things in reserve. Oops :stuck_out_tongue:

Now back tot he Registry issue. I have a sneaky feeling it has something to do with AV (McAfee in my case).

  1. Rebooted the server
  2. Performed a consistency check, xRegistry timed at 75 seconds per config (yes it happens right after a reboot now)
  3. I disabled McAfee, performed another consistency check,xRegistry timed at 75 seconds per config
  4. Left McAfee disabled and rebooted the server
  5. Performed a consistency check, xRegistry timed at 1.5 seconds per config

Here’s the confusing part…

  1. Re-enabled McAfee and rebooted the server
  2. Performed a consistency check, xRegistry timed at 1.5 seconds per config

So I’m just taking it as it ‘may’ be McAfee.

Does anyone know what process DSC uses? I could tell the Security Team to make a couple of exclusions in McAfee (I have a feeling it uses WmiPrvSE.exe some how).