We have a Horizon 7.9 environment having floating Linked Clones with FSLogix and DEM. We were testing this so far and now planning to go production. However, when we moved the user GPOs to DEM, we are seeing inconsistent login times. It takes between 15-20 seconds ideally (which is great!), but sometimes goes up to 5 minutes!
I don't see any errors in the log, but I see that there is significant delays between import tasks. Could someone take a look at the logs and comment what could be the issue?
[Edit]: The desktops are set to 'Refresh on Logoff'. When tested without 'Refresh on Logoff', the login time is consistently 15 seconds. I am doing some more testing...
Random-ish logon delays in non-persistent scenarios are typically caused by SMB clients not having had the time to correctly "sign out" from the SMB server before the image was refreshed, causing oplock-related delays when the SMB client on another VM subsequently tries to access configuration files. Please see Re: UEM hanging/delaying randomly. for a workaround.
Having said that, something else might be at play here (as well), as that would not really explain why your 10 async drive mappings take 12 seconds to be processed. That's just a matter of reading 10 tiny files from the config share... Does that takes as long if you do not refresh at logoff? Anyway, let's first try shutting down the workstation service, to see the impact of that.
Thanks DEMdev for taking a look.
I created a GPO to run a .bat script during shutdown which stops workstation, but that did not help unfortunately
Its very intermittent - when Refresh on Logoff is set, it works fine half of the time, and when its ideal (15-20 secs), drive mapping takes less than a second (see below).
2020-06-25 16:04:34.470 [DEBUG] Broadcasting environment variable changes
2020-06-25 16:04:34.485 [INFO ] Scheduled drive mapping for async processing ('Archive Drive.xml')
2020-06-25 16:04:34.493 [INFO ] Scheduled drive mapping for async processing ('Graphics Drive.xml')
2020-06-25 16:04:34.504 [INFO ] Scheduled drive mapping for async processing ('Graphics Library Drive.xml')
2020-06-25 16:04:34.514 [INFO ] Scheduled drive mapping for async processing ('Images Drive.xml')
2020-06-25 16:04:34.523 [INFO ] Scheduled drive mapping for async processing ('Marketing Drive.xml')
2020-06-25 16:04:34.532 [INFO ] Scheduled drive mapping for async processing ('NetApp Drive.xml')
2020-06-25 16:04:34.543 [INFO ] Scheduled drive mapping for async processing ('Office Admin Drive.xml')
2020-06-25 16:04:34.555 [INFO ] Scheduled drive mapping for async processing ('Pop Drive.xml')
2020-06-25 16:04:34.564 [INFO ] Scheduled drive mapping for async processing ('Pop Global Drive.xml')
2020-06-25 16:04:34.575 [INFO ] Scheduled drive mapping for async processing ('Reference Drive.xml')
Also we can see time taken for all the operations are delayed. See folder redirection, for example:
2020-06-25 16:12:28.620 [INFO ] Successfully redirected 'Documents' folder to '\\au-fs3\RedirectedFolders\%username%\Documents' ('User Folder Redirection.xml')
2020-06-25 16:12:38.314 [INFO ] Successfully redirected 'Downloads' folder to '\\au-fs3\RedirectedFolders\%username%\Downloads' ('User Folder Redirection.xml')
2020-06-25 16:12:51.386 [INFO ] Successfully redirected 'Music' folder to '\\au-fs3\RedirectedFolders\%username%\Music' ('User Folder Redirection.xml')
2020-06-25 16:13:05.177 [INFO ] Successfully redirected 'Pictures' folder to '\\au-fs3\RedirectedFolders\%username%\Pictures' ('User Folder Redirection.xml')
2020-06-25 16:13:18.624 [INFO ] Successfully redirected 'Videos' folder to '\\au-fs3\RedirectedFolders\%username%\Videos' ('User Folder Redirection.xml')
Can you reproduce the problem within the session, for instance by continuously refreshing drive mappings (FlexEngine.exe -UEMRefreshDrives) for a test user? If so, a ProcMon trace might shed some light on this. Of course, so would a ProcMon trace captured during a delayed logon, but collecting such a trace is more involved than doing so during a session.
As for slow folder redirection: the DEM agent isn't really doing anything here. We just tell Windows that a particular user profile sub folder should reside at the specified location, and it takes care of that.
Is there anything you can check on the file server side or the network to see what's going on? What type of storage are your config share and that RedirectedFolders share hosted on? Windows, or another vendor's?
I do see a bit of registry imports slowing you down a bit. But most what I see seems to be coming from how fast your File server is delivering the content. Make sure its not coming from say another location on the other side of the world. I've seen that happen before with name spaces.
I have attached the ProcMon output - hope this is what you're looking for.
We are on a file server with PureStorage flash array in the backend, so performance wise, all should be good I guess. However, when I moved all the stuff to the E: drive of the VM where DEM console is running (by creating the file share), we have more predictable login times (12-25 seconds). I'm doing some more tests.
Traces in Native Process Monitor Format (PML) are easier to analyze, but if I interpret this XML data correctly, it seems like the FlexEngine.exe run it covers did not encounter any delays?
Is it possible to reproduce the delays via in-session refreshes, or does it only happen at logon?
Sorry, the log file I attached was from the new file server which I mentioned (where we are seeing more consistent login times of 12-20 seconds). I have attached the log file file from the problem file server in PML format.
I think the the delay is when the user logs in and not when we run FlexEngine.exe from within the session, but I see better login times on the new file server, so could the backend storage be the culprit?
Do we have any dependency (during user login) on the server where UEM console is running (I don't expect so)? The reason to ask is, in the scenario where we don't see the delay, the file server is on the same machine where the UEM console is running (which means the FSLogix VHD, redirected folders, user profiles, DEM config data and UEM console are all in the same place). In the other case, everything except UEM console is in the same place.
We are also talking to the storage vendor to see if there's anything wrong with the storage.
Thank you for the PML. Both FlexEngine.exe instances (the one you launched to perform the drive mapping refresh, and its child process that performs the async mapping) do indeed complete within a few seconds. The only outlier I see is the following:
That means that just opening that config file on the share takes 0.2 seconds, which is relatively slow. For the other config files this takes just 2-7 milliseconds, so that's quite a difference.
The DEM agent does not have any dependency on the DEM console; all it cares about and needs access to are the two shares.
Issues like this can definitely be related to storage, e.g. due to some particularities of a third-party SMB implementation. Hopefully there are some diagnostics on that side that might shed some light on this.