Random logon delay when using UEM

[SummaCollege]

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

What we are experiencing is that after enabling UEM, a random delay of about 1,5 - 2 min is added during logon. This is only happening when we immediately logon after initiating a shutdown of another machine. If we wait for about 15min after shutdown, the logon delay is not present.

We enabled verbose status messaging during logon and notice that the delay is not happening on the same part of the logon process every time. Its randomly waiting on Flexengine policy or User profile service to be applied (or any other part of logon it seems). During this delay we also noticed that the UEM console freezes and we are unable to operate the console! When the lock is gone, the logon process continues. During this delay we checked and there seems to be no lock on the UEM profile files or config files.

After logon, all seems to operate just fine.

We enabled debug logging mode for UEM and no errors or warning present.

Does anyone have a clue what could cause this?

[JohnTwilley]

I have this same issue.

We are running the UEM 9.0 profiles on an EMC Isilon, and I get these types of locks all the time.

It is slowly driving me crazy, and I'm looking into other solutions for hosting my UEM profile data.  I need a dependable CIFs share...is that asking too much?

[Pim_van_de_Vis]

Thanks for mentioning the storage solution John, this would definitely be my first question.

SummaCollege​ what kind of file storage are you using to host the SMB shares for UEM?

Please try to (temporary) move the file shares to a Windows 2008R2 or newer fileserver and see if you can reproduce the issue. Just to pinpoint where this is coming from.

[DEMdev]

SummaCollege​,

The fact that the UEM management console also freezes when your logon hangs is a strong indication that this is related to storage. The UEM agent has no dependency on the management console, but they both depend on the configuration share.

Can you share a UEM log file for a slow logon? Alternatively, do you see any big "time gaps" between subsequent lines in the UEM log file for a slow logon?

[JohnTwilley]

I don't have a debug log to share, but I have seen delays in the logs.

I'm going down the road of trying to disable OpLocks in our Isilon cluster.  

Our Isilon SMB share is behind about 30 IP addresses (nodes) and the TTL is around Zero.  (Every time you ping, you get a different IP address.)

I'm thinking that the nature of the UEM product is to connect/reconnect as it accesses the zip files, and Oplocks may be interfering.

I know that I battle the UEM console, and suffer from File Locks while trying to edit/save the .ini files.  I'm hoping this is the issue, because I can't think of anything else.

If not, I will put it behind some DFS shares in VCenter.

John

[DEMdev]

Thanks for the additional info, JohnTwilley​.

UEM isn't doing anything special w.r.t. accessing or locking files. It just asks Windows to enumerate files from a folder, read files, write files, etc, without doing anything special.

[jmatz135]

From our environment it is all the isilon and oplocks that causes this issue.  I think you can actually set the locking time down from the default of 2 minutes which helps.  There may also be different software code revisions of the actual oplock code on the isilon that you can play with (I'm not the storage guy).  I've also had an issue with if you had your desktop or documents redirected and tried to run a batch or command prompt shortcut from that location elevated as administrator it would take like 30 seconds to launch as you are actually trying to open the file as 2 different users of the same user id which causes the oplocking mechanism to go haywire.

[DEMdev]

Thanks @jmatz135!

I'm not a storage guy either :-), so I'll try to read up a bit on oplocks and related topics. I did read something about oplock timeouts which default to 35 seconds. Do any of you happen to see 35-second delays between subsequent lines in UEM log files?

[CraigC75]

Did you find out more information on this, or get this resolved?  I am running into the same issue, and curious if you were able to resolve this with Isilon.  Thanks

[JohnTwilley]

I had the Storage Team disable OpLocks on our Isilon SMB shares for UEM.  (Both User Profiles & Configuration)

So far, I really think it has helped!  It is quick and easy from the Isilon management console.  I'd share the commands...but I don't have them.

You can give them this from EMC Support:

              For SMB related inquiries, please provide the following commands output:

isi smb shares view YourShareNameHere | grep –i oplock

isi_gconfig registry.Services.lwio.Parameters.Drivers.srv.smb2.EnableLeases

Side Note:

You can test with the following Client registry setting to disable Opportunistic Locks from a client PC.

Turn Off Client requests for OpLocks for SMB

[HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\services\mrxsmb\Parameters]

"OplocksDisabled"=dword:00000001

This is not what I’d like to use going forward, as it will turn off OpLocks for All SMB shares, not just the Isilon ones.

[SummaCollege]

Unfortunately we haven't found a solution yet. We also tried disabling opportunistic locks but it did not help.

So for us, the search continuous...

[SummaCollege]

Unfortunately we are still noticing frequent, but random login delays.

I have added 2 zipfiles each with login monitoring logfiles for both cases

Delay 1:

Sometimes the delay seems to originate from the Folder Redirection part when viewing vmlm logfile, but we cant figure out what's causing this.

vmlm.txt

2017-11-30T19:24:14.093 INFO (0f50-0c54) [LogonMonitor::ProcessWFREvent] Windows Folder Redirection Processing Started

2017-11-30T19:25:53.403 INFO (0f50-0c54) [LogonMonitor::ProcessWFREvent] Windows Folder Redirection Processing Finished

This looks like a 1:39 delay!

But when cross referencing this with the vmlm file regarding the user login, different info is presented.

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Logon Time: 111.37 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Logon Start To Hive Loaded Time: 0.37 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Logon Start To Classes Hive Loaded Time: 0.47 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Profile Sync Time: 0.00 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Windows Folder Redirection Apply Time: 0.00 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Shell Load Time: 3.37 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Total Logon Script Time: 0.00 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] User Policy Apply Time: 106 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Machine Policy Apply Time: 0 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Group Policy Software Install Time: 0.42 seconds

2017-11-30T19:25:57.840 INFO (0f50-178c) [LogonMonitor::LogSummary] Free Disk Space Available To User: 26 GB

Folder redirection Apply Time: 0.00 sec

Both info from the same login session don't match, and i can;t figure out why.

When the delayed login is completed, the folder redirection is functioning properly. Also there is not a single error logged in the eventviewer regarding folder redirection, the only related message is from Winlogon logging that login is taking a long time.

Delay 2:

Other slow logins show a different source of delay:

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Logon Time: 76.44 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Logon Start To Hive Loaded Time: 42.71 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Logon Start To Classes Hive Loaded Time: 42.88 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Profile Sync Time: 0.00 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Windows Folder Redirection Apply Time: 0.00 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Shell Load Time: 3.97 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Total Logon Script Time: 0.00 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] User Policy Apply Time: 28 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Machine Policy Apply Time: 0 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Group Policy Software Install Time: 0.38 seconds

2017-11-30T19:43:24.358 INFO (0f8c-07fc) [LogonMonitor::LogSummary] Free Disk Space Available To User: 26 GB

This is annoying me and my collegues for a while now and prevents us from moving from pilot phase to production.

[Pim_van_de_Vis]

do you also happen to have UEM flexengine logs?

[SummaCollege]

I don't have the logs from those sessions any more, so i logged in a few times to get you some new logging data including flexengine logs.

Both logins were slow but logs show different sources for the delay.

Login 1:

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Logon Time: 89.03 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Logon Start To Hive Loaded Time: 0.67 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Logon Start To Classes Hive Loaded Time: 0.80 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Profile Sync Time: 0.00 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Windows Folder Redirection Apply Time: 0.00 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Shell Load Time: 3.77 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Total Logon Script Time: 0.00 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] User Policy Apply Time: 83 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Machine Policy Apply Time: 0 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Group Policy Software Install Time: 0.42 seconds

2017-12-01T10:41:57.013 INFO (0d40-0f5c) [LogonMonitor::LogSummary] Free Disk Space Available To User: 26 GB

Login 3:

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Logon Time: 117.60 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Logon Start To Hive Loaded Time: 64.76 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Logon Start To Classes Hive Loaded Time: 64.87 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Profile Sync Time: 0.00 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Windows Folder Redirection Apply Time: 0.00 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Shell Load Time: 3.41 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Total Logon Script Time: 0.00 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] User Policy Apply Time: 48 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Machine Policy Apply Time: 0 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Group Policy Software Install Time: 0.61 seconds

2017-12-01T10:53:15.527 INFO (0cc0-15f8) [LogonMonitor::LogSummary] Free Disk Space Available To User: 26 GB

I am a bit lost at the moment, we can't get to the source of the delay...

[Pim_van_de_Vis]

Those UEM logs indicated that UEM needed 3.9 seconds and 4.7 seconds at logon. So the delay does not seem to be coming from UEM.

Maybe a GPO or logon script? Or AppVolumes?

[DEMdev]

I'll spend a bit more time later today in trying to figure out what's going on in the VMLM logs, but as far as UEM is concerned, both logons are relatively quick. One takes about 4s, with the majority of time spent on running aspectratio.ps1 and importing Chrome settings; the other takes about 5s, again mostly on the script and Chrome.

It's really strange to see such a big difference between the two VMLM logs. I'll try to get a bit more insight into that, but this might be something to pick up on the Horizon side rather than the UEM side...

[SummaCollege]

Thx UEMdev​ & Pim_van_de_Vis​ for looking into this!

[DEMdev]

Hi SummaCollege,

I've tried to make sense of the VMLM logs, but without much success, I'm afraid...

Given that you're using local profiles, I'm particularly surprised by the hive load time of more than a minute in one of these runs, but the user policy time is also quite strange. Could this be caused by infrastructure issues (AD, DNS, ...), maybe?

[SummaCollege]

Thx UEMdev​ for looking into this, we do appreciate this!

AD, DNS, ... as a potential source of these problems is something that's also one of the things on top of my list. First i wanted to rule out any other potential problems other than AD, DNS, ... mainly because we don't see any other issues throughout a domain that consists of roughly 5000 devices. At least no problems that we know of  .

Does anyone have some tips about relevant logging that i could look at to get me closer to the source of this annoying issue?

Besides that the digging goes on......

[DEMdev]

Hi SummaCollege,

I don't have any concrete tips for troubleshooting these kinds of infrastructure issues. Maybe start with diving into the Group Policy logging (as per https://blogs.technet.microsoft.com/askds/2015/04/17/a-treatise-on-group-policy-troubleshootingnow-w...)?

One thing I'm curious about: if you remove the UEM software but leave the GPO(s) in place, does this change anything in logon performance?