VMware Horizon Community
SummaCollege
Hot Shot
Hot Shot
Jump to solution

Random logon delay up to approx 120sec

We are running floating desktops of Windows 10 v1703 and v1607 on VMware Horizon 7.2 and UEM 9.2.0.

What we are experiencing is a seemingly random logon delay that extends the logon up to 120sec. Monitoring reveals that the delay seems to increase in steps of approx 30sec. This delay doesn't seem to happen on our physical desktops.

Initialy we thought this might be related to UEM, so i created a thread on the UEM forum: Random logon delay when using UEM

At the end of troubleshooting we came to the conslusion we might be better off discussing this in a Horizon forum

After a lot of testing we now disabled all user policies (we thought one of the GPO settings would be to blame) but after this, the delays are still present.

During testing we started logging in several times. The first 4 logins were very fast, about 8 seconds!! The 5th login again was very slow.

The user vmlm logfile summary showed me the following result:

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Logon Time: 71.20 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Logon Start To Hive Loaded Time: 64.53 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Logon Start To Classes Hive Loaded Time: 64.64 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Profile Sync Time: 0.00 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Windows Folder Redirection Apply Time: 0.00 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Shell Load Time: 5.25 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Total Logon Script Time: 0.00 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] User Policy Apply Time: 0 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Machine Policy Apply Time: 0 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Group Policy Software Install Time: 0.00 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Free Disk Space Available To User: 26 GB

When searching throughout the log i found this delay:

2017-12-05T14:50:45.415 TRACE (0f00-0844) [LogonMonitor::StartShellLoadMonitor] Shell Load Monitor Started. Session: 1

2017-12-05T14:50:45.415 INFO (0f00-0844) [LogonMonitor::Logon] LOGON: User: SUMMACOLLEGE\icttestprsalg02, Session: 1

2017-12-05T14:50:46.227 TRACE (0f00-0dc8) [LogonMonitor::ProcessLogonEvent] Event Id: 1, Session: 1

2017-12-05T14:50:46.227 TRACE (0f00-0dc8) [LogonMonitor::ProcessLogonEvent] Profile Started. Session: 1

2017-12-05T14:51:50.603 INFO (0f00-0dc8) [LogonMonitor::MatchUserPolicyEvent] Assigned User Policy ActivityID {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007} to Session 1

2017-12-05T14:51:50.603 TRACE (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 4001, ActivityID: {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007}, Account: SUMMACOLLEGE\icttestprsalg02, Session: 1

2017-12-05T14:51:50.603 TRACE (0f00-0de8) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5314, ActivityID: {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007}, Account: , Session: 1

2017-12-05T14:51:50.603 INFO (0f00-0de8) [LogonMonitor::ProcessGroupPolicyEvent] Network Bandwidth: 40154 kbps, Slow link Threshold: 500 kbps, Slow Link: False

2017-12-05T14:51:50.603 TRACE (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5327, ActivityID: {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007}, Account: , Session: 1

2017-12-05T14:51:50.603 INFO (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Network Bandwidth On One Connection: 5019309 kbps

2017-12-05T14:51:50.603 TRACE (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5326, ActivityID: {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007}, Account: , Session: 1

2017-12-05T14:51:50.603 INFO (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Domain Controller Discovery Time: 0.22 seconds, Error Code: 0

2017-12-05T14:51:50.650 TRACE (0f00-0dc8) [LogonMonitor::ProcessLogonEvent] Event Id: 5, Session: 1

2017-12-05T14:51:50.650 INFO (0f00-0dc8) [LogonMonitor::GetLogonStartTimeToHiveLoadedTime] Logon Start To Hive Loaded Time: 64.53 seconds. Session: 1

Don't know exactly what is happening when this delay occurs, but to me it looks like it happens before it is searching/waiting/retreiving assigned user policies. Am i right?

I have attached the logfiles from this session, including vmlm.txt

What i do find strange and i can't figure out what it means or determine if its related to the slow logins, is the fact there are a lot of the following messages throughout the whole logfile:

2017-12-05T14:51:50.603 TRACE (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Failed to find Session for User PolicyEvent Id: 5314, ActivityID: {2CF6B09C-6762-4ABD-9468-84A4DC9A87B2}, Account:

I hope someone over here can be of any assistance, i am a bit lost researching this issue...

1 Solution

Accepted Solutions
SummaCollege
Hot Shot
Hot Shot
Jump to solution

Looks like we fixed the issue here. There were 2 things that needed fixing.

1) There were inconsistencies in PERC driver versions across different ESX hosts. I guess this was the main culprit. Also impacted VDI user experience during recompose actions.

2) One of the required printer drivers were missing from the Golden Image and thus was installed during login.

After fixing both of the above, logintimes of our floating desktop averages between 25 - 30 sec. Not that bad...

Now lets hope the issue is indeed permanently fixed.

View solution in original post

Reply
0 Kudos
5 Replies
sjesse
Leadership
Leadership
Jump to solution

Do you have any group policy objects associated with these desktops, can you disable them? I've tried to remove as many gpos from our desktops since I saw this before, any user based settings we try to do in UEM first.

Reply
0 Kudos
sjesse
Leadership
Leadership
Jump to solution

The way I'm reading it is its the first group policy that is being applied for that user.

Reply
0 Kudos
SummaCollege
Hot Shot
Hot Shot
Jump to solution

I need to take a closer look on this in the morning, because we already disabled all user policies on the OU the test user reside in and enabled inheritance blocking to make sure nothing's inherited from above.

Reply
0 Kudos
SummaCollege
Hot Shot
Hot Shot
Jump to solution

We have implemented vRealize for Horizon to gather more info. In the vRealize dashboard we see the slow logins, but still can't figure out why. Also need to learn how to interpret the vRealize data.

Reply
0 Kudos
SummaCollege
Hot Shot
Hot Shot
Jump to solution

Looks like we fixed the issue here. There were 2 things that needed fixing.

1) There were inconsistencies in PERC driver versions across different ESX hosts. I guess this was the main culprit. Also impacted VDI user experience during recompose actions.

2) One of the required printer drivers were missing from the Golden Image and thus was installed during login.

After fixing both of the above, logintimes of our floating desktop averages between 25 - 30 sec. Not that bad...

Now lets hope the issue is indeed permanently fixed.

Reply
0 Kudos