horizon 7.11 with DEM slow logins

[nettech1]

Hi,

We are seeing extremely slow (over 250 sec) logins for all of our users. The DEM portion of the login is only 28 sec, don't thing it could get much better.

2020-06-10 14:13:38.917 [DEBUG] Launched FlexEngine in DirectFlex mode

2020-06-10 14:13:38.927 [INFO ] Done (28768 ms) [<<IFP#cc07aa4b-T5]

According to vmlm log we are spending a lot of time loading shell and applying user policy.

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] ****************** Session Summary (User: CORP\hbeckenbauer, Session: 1) *****************

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Logon Time: 245.46 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Logon Start To Hive Loaded Time: 10.14 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Logon Start To Classes Hive Loaded Time: 12.98 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Profile Sync Time: 0.00 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Windows Folder Redirection Apply Time: 0.00 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Shell Load Time: 88.96 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Total Logon Script Time: 0.00 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] User Policy Apply Time: 69 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Machine Policy Apply Time: 0 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Group Policy Software Install Time: 0.78 seconds

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] Free Disk Space Available To User: 109 GB

2020-06-10T15:16:56.911 INFO (0f94-01b8) [LogonMonitor::LogSummary] *****************************************************************************************

Here is a list of processes taking the longest to startup

300 sec system -  C:\Windows\System32\svchost.exe -k AppReadiness -p -s AppReadiness

277 sec system - C:\Windows\System32\svchost.exe -k netsvcs -p -s BITS

125 sec system -  C:\Windows\system32\svchost.exe -k LocalSystemNetworkRestricted -p -s NgcSvc

125 sec system - C:\Windows\system32\wbem\WmiApSrv.exe

122 sec system - C:\Windows\system32\SearchFilterHost.exe 0 788 792 800 8192 796

122 sec system - C:\Windows\system32\svchost.exe -k LocalSystemNetworkRestricted -s WPDBusEnum

121 sec system - C:\Windows\system32\SearchFilterHost.exe 0 788 792 800 8192 796

120 sec system - C:\Windows\system32\SearchFilterHost.exe 0 788 792 800 8192 796

116 sec system - C:\Windows\system32\svchost.exe -k netsvcs -p -s DsmSvc

116 sec system - C:\Windows\system32\wbem\wmiprvse.exe -secured -Embedding

111 sec system - C:\Windows\system32\wbem\wmiprvse.exe -secured -Embedding

140 sec 0 0 PolicyActivityId : {1421a901-b55f-4428-8ed9-cc81bc9f7a14} | PrincipalSamName : CORP\hbeckenbauer | IsMachine : User | IsDomainJoined : true | IsBackgroundProcessing : false | IsAsyncProcessing : false | IsServiceRestart : false | ReasonForSyncProcessing : Synchronous policy

198 sec hbeckenbauer - C:\Windows\system32\SearchProtocolHost.exe Global\UsGthrFltPipeMssGthrPipe_S-1-5-21-1644491937-1500820517-839522115-27442_ Global\UsGthrCtrlFltPipeMssGthrPipe_S-1-5-21-1644491937-1500820517-839522115-27442 1 -2147483646 "Software\Microsoft\Windows Search""Mozilla/4.0 (compatible; MSIE 6.0; Windows NT; MS Search 4.0 Robot)""C:\ProgramData\Microsoft\Search\Data\Temp\usgthrsvc""DownLevelDaemon""1"

111 sec hbeckenbauer  - C:\Windows\system32\DllHost.exe /Processid:{AB8902B4-09CA-4BB6-B78D-A8F59079A8D5}

108 sec hbeckenbauer  - C:\Windows\System32\RuntimeBroker.exe -Embedding

108 sec hbeckenbauer  - C:\Windows\system32\backgroundTaskHost.exe -ServerName:CortanaUI.AppXy7vb4pc2dr3kc93kfc509b1d0arkfb2x.mca

96 sec system - C:\Windows\system32\PrintIsolationHost.exe -Embedding

91 sec system - C:\Windows\system32\PrintIsolationHost.exe -Embedding

90 sec - CSEElaspedTimeInMilliSeconds : 90984 | ErrorCode : 0x0 | CSEExtensionName : VMware Dynamic Environment Manager | CSEExtensionId : {007f7799-28f8-4c22-af9d-c80e8555723e}

90 sec hbeckenbauer  - C:\Windows\System32\RuntimeBroker.exe -Embedding

89 sec system - C:\Windows\sysWOW64\wbem\wmiprvse.exe -secured -Embedding

88 sec hbeckenbauer - C:\Windows\system32\backgroundTaskHost.exe -ServerName:microsoft.windowslive.mail.AppXck8wg1kmbyhcav4m1f20qdp9js3rp7e4.mca

85 sec hbeckenbauer  - C:\Windows\system32\backgroundTaskHost.exe -ServerName:App.AppXmtcan0h2tfbfy7k9kn8hbxb6dmzz1zh0.mca

81 sec hbeckenbauer - C:\Program Files\Microsoft Office\root\Office16\msoia.exe scan upload

80 sec hbeckenbauer  - C:\Program Files\VMware\VMware View\Agent\bin\vmlm_helper.exe

75 sec hbeckenbauer  - C:\Windows\System32\RuntimeBroker.exe -Embedding

74 sec hbeckenbauer  - C:\Windows\system32\backgroundTaskHost.exe -ServerName:MicrosoftEdge.AppXbnf56tvebb2bnpah2t4s0emv5ws4vxt1.mca

71 sec hbeckenbauer  - C:\Windows\system32\backgroundTaskHost.exe -ServerName:CortanaUI.AppXy7vb4pc2dr3kc93kfc509b1d0arkfb2x.mca

63 sec hbeckenbauer  - C:\Windows\system32\backgroundTaskHost.exe -ServerName:App.AppX53ypgrj20bgndg05hj3tc7z654myszwp.mca

60 sec hbeckenbauer  - C:\Windows\system32\backgroundTaskHost.exe -ServerName:CortanaUI.AppXy7vb4pc2dr3kc93kfc509b1d0arkfb2x.mca

Any help is greatly appreciated.

We are on instant clones with 7.11 agent and 11.0.5 tools. Windows 10 1909 optimized with b1160

Thank you!

[sjesse]

"User Policy Apply Time: 69 seconds" 

Do you have the any gpo loopback policy enabled? If not check the gpos that are applied to the user from the users's ou. I'd suggest appliying the replace mode to remove any gpo's that are to the user and replace them with DEM policies

Group Policy Loopback Processing – Part 2: Replace Mode and Merge Mode – 4sysops

[nettech1]

Yes loopback is enabled in replace mode

DEMdev​ do you see anything that should be focused on specifically?

Thanks

[nettech1]

X axis - seconds

Y axis - processes

[sjesse]

Other than DEM and Horizon are you using any other software like appvolumes of fslogix? I'd remove them down to a test pool with just the parent image and check the login, then add one at a time and see which one is the longest. Dem can do stuff duiring the user apply time but so can app volumes if your using that.

[nettech1]

nope, not using appvolumes or fslogix

[DEMdev]

Hi nettech1,

DEMdev do you see anything that should be focused on specifically?

Not directly, no.

As you already mentioned, 2020-06-10 14:13:38.927 [INFO ] Done (28768 ms) [<<IFP#cc07aa4b-T5] indicates that DEM only consumed 28.768 seconds at logon.

I'm a bit confused about that 90 sec - CSEElaspedTimeInMilliSeconds : 90984 | ErrorCode : 0x0 | CSEExtensionName : VMware Dynamic Environment Manager | CSEExtensionId : {007f7799-28f8-4c22-af9d-c80e8555723e}, though. Is that for the same logon? As that would indicate it took 90 seconds instead of 29...

[nettech1]

I'm a bit confused about that 90 sec - CSEElaspedTimeInMilliSeconds : 90984 | ErrorCode : 0x0 | CSEExtensionName : VMware Dynamic Environment Manager | CSEExtensionId : {007f7799-28f8-4c22-af9d-c80e8555723e}, though. Is that for the same logon? As that would indicate it took 90 seconds instead of 29...

Sorry for the confusion, this was the experience before. I switched all of the drive mapping to run asynchronously and DEM times went down to 25 from 90

It was a log from another log in

[nettech1]

this seems very similar to our experience  - Long Logon times Win10 1903 with dual monitors - Page 2 - XenDesktop 7.x - Discussions 

[nettech1]

Login with DisableAcrylicBackgroundOnLogon set to 1

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] ****************** Session Summary (User: CORP\mvurme, Session: 1) *****************

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Logon Time: 27.81 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Logon Start To Hive Loaded Time: 1.52 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Logon Start To Classes Hive Loaded Time: 1.77 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Profile Sync Time: 0.00 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Windows Folder Redirection Apply Time: 0.00 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Shell Load Time: 12.83 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Total Logon Script Time: 0.00 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] User Policy Apply Time: 12 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Machine Policy Apply Time: 0 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Group Policy Software Install Time: 0.11 seconds

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] Free Disk Space Available To User: 109 GB

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] ****************************************************************************************

[DEMdev]

Hi nettech1,

Wow. That is impressive. Great find!

2020-06-15T 06:29:13.388 INFO (0fbc-1e90) [LogonMonitor::LogSummary] User Policy Apply Time: 12 seconds

Just to make sure: are these new VMLM figures from the same setup as the one you used for your original post? In other words, did DEM's logon also speed up because of this change, as it previously took 28.7 seconds?

[nettech1]

DEM's time has NOT been affected by the blurred Login background. Originally we had 50+ sec times for DEM due to multiple  synchronous drive mappings and a script that was pointing to a deleted bat file. That policy was set to wait 40 sec.

All other login processes were affected by the new beautiful default HD background

Why MS blurred Login background and not gave option to reverse it? - Microsoft Community

[DEMdev]

Hi nettech1,

DEM's time has NOT been affected by the blurred Login background.

I couldn't imagine it would have; just wanted to make sure, thanks!