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

This topic contains 21 replies, has 3 voices, and was last updated by Profile photo of Zuldan Zuldan 8 months, 1 week ago.

  • Author
    Posts
  • #36026
    Profile photo of Zuldan
    Zuldan
    Participant

    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.

  • #36029
    Profile photo of Arie H
    Arie H
    Participant

    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.

  • #36228
    Profile photo of Zuldan
    Zuldan
    Participant

    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?

  • #36284
    Profile photo of Nitin Gupta
    Nitin Gupta
    Participant

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

  • #36304
    Profile photo of Zuldan
    Zuldan
    Participant

    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

  • #36325
    Profile photo of Nitin Gupta
    Nitin Gupta
    Participant

    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

  • #36352
    Profile photo of Arie H
    Arie H
    Participant

    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

  • #36353
    Profile photo of Zuldan
    Zuldan
    Participant

    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.

  • #36594
    Profile photo of Zuldan
    Zuldan
    Participant

    @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———–

  • #36642
    Profile photo of Zuldan
    Zuldan
    Participant

    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")

  • #36692
    Profile photo of Arie H
    Arie H
    Participant

    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 🙂

  • #36733
    Profile photo of Zuldan
    Zuldan
    Participant

    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(":"))
    {

  • #36744
    Profile photo of Zuldan
    Zuldan
    Participant

    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}

  • #36776
    Profile photo of Arie H
    Arie H
    Participant

    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.

  • #36816
    Profile photo of Zuldan
    Zuldan
    Participant

    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.

  • #36824
    Profile photo of Arie H
    Arie H
    Participant

    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 😉

  • #36838
    Profile photo of Zuldan
    Zuldan
    Participant

    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 🙁

    I'll happily be your first beta tester your optimised version of xRegistry 🙂

  • #36869
    Profile photo of Arie H
    Arie H
    Participant

    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.

  • #36932
    Profile photo of Zuldan
    Zuldan
    Participant

    @Arie, I totally agree. I'm currently reading The Phoenix Project 😉 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 😛

  • #36933
    Profile photo of Zuldan
    Zuldan
    Participant

    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...

    6. Re-enabled McAfee and rebooted the server
    7. 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).

  • #36948
    Profile photo of Arie H
    Arie H
    Participant

    I feel your 'pain' with SCCM. Its not mean to provision servers or worry about state. Else it would go head to head vs puppet or chef and it isnt.

    Seems were back to my initial reply to your question at the top of this thread.

    Any chance you uninstall the agent, restart and try and ask your Security team to exclude that node for the day of testing or use a server that hasnt gone through your normal hardning procedures ?

  • #37145
    Profile photo of Zuldan
    Zuldan
    Participant

    @Arie H, apologies for the delay, I managed to get some more time to work on this.

    I removed the AV software and the server still has the same lag with xRegistry. The delay is occurring across all 200+ servers (different hardware). I guess my only hope now is your wonderful xRegistry re-write.

You must be logged in to reply to this topic.