Windows 10 – Challenges with Logon time and Profile import

[lansti]

I know that there are a number of posts about long login times here in the community.
But it so happens that I still have big challenges with dissatisfied users, as our login times are over 1 minute for a user.
I understand that I have some challenges with DEM's profile import, where some of the applications contain a little too much, and these are templates I have taken from VmWare's website. So I would think that this is the best practice to use them as they are. But of course I have also added several exclusions and inclusions to get what the users need.

Our company is located in 2 cities, and then has 2 sites, but the DEM server is located in site 1. The users have the DEM Profile area in their site, and the VDIs are also located in their respective sites.

I see in the logs the following logon time for 2 users, each belonging to its own site:

Site 1:

****************** Session Summary (User: domain\user1, Session: 1) *****************
Logon Time: 89.59 seconds
Logon Start To Hive Loaded Time: 0.00 seconds
Logon Start To Classes Hive Loaded Time: 9.62 seconds
Profile Sync Time: 8.32 seconds
Windows Folder Redirection Apply Time: 0.00 seconds
Shell Load Time: 9.76 seconds
Total Logon Script Time: 0.00 seconds
User Policy Apply Time: 69 seconds
Machine Policy Apply Time: 0 seconds
Group Policy Software Install Time: 0.09 seconds
Free Disk Space Available To User: 42 GB
**********************************************************************************

Site 2:

****************** Session Summary (User: domain\user2, Session: 1) *****************
Logon Time: 71.26 seconds
Logon Start To Hive Loaded Time: 0.00 seconds
Logon Start To Classes Hive Loaded Time: 27.65 seconds
Profile Sync Time: 26.38 seconds
Windows Folder Redirection Apply Time: 0.00 seconds
Shell Load Time: 5.51 seconds
Total Logon Script Time: 0.00 seconds
User Policy Apply Time: 34 seconds
Machine Policy Apply Time: 0 seconds
Group Policy Software Install Time: 0.23 seconds
Free Disk Space Available To User: 41 GB
**********************************************************************************

The pool both log on to is based on the same Golden image, which has been cloned from site 1 to site 2

When I go through the logs I see the following for user 1:
T10:33:32.160 TRACE (0dd4-075c) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 4016, ActivityID: {39C1E896-768C-4BC9-937B-9B23DCC4762D}, Account: , Session: 1

T10:34:39.075 TRACE (0dd4-075c) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5016, ActivityID: {39C1E896-768C-4BC9-937B-9B23DCC4762D}, Account: , Session: 1

For user 2, the time is a little lower:
T08:40:44.871 TRACE (1080-0728) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 4016, ActivityID: {6A47075B-EBDB-476E-B436-38D8CC1AFE5C}, Account: , Session: 1

T08:41:17.403 TRACE (1080-1aa4) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 4016, ActivityID: {6A47075B-EBDB-476E-B436-38D8CC1AFE5C}, Account: , Session: 1

What is going on here?
Does the machine spend more than 1 minute on a GPO, or is it DEM that uses this time?

When the profile import starts, I can see the following:

T10:33:20.504 INFO (0dd4-075c) [LogonMonitor::Logon] LOGON: User: domain\user1, Session: 1
T10:33:21.397 TRACE (0dd4-075c) [LogonMonitor::ProcessLogonEvent] Event Id: 1, Session: 1
T10:33:21.397 TRACE (0dd4-075c) [LogonMonitor::ProcessLogonEvent] Profile Started. Session: 1
T10:33:21.397 TRACE (0dd4-0364) [LogonMonitor::ProcessLogonEvent] Event Id: 6, Session: 1
T10:33:21.397 TRACE (0dd4-0364) [LogonMonitor::ProcessLogonEvent] Profile Sync Started. Session: 1
T10:33:29.968 TRACE (0dd4-0364) [LogonMonitor::ProcessLogonEvent] Event Id: 7, Session: 1
T10:33:29.968 TRACE (0dd4-0364) [LogonMonitor::ProcessLogonEvent] Profile Sync Finished. Session: 1
T10:33:29.968 TRACE (0dd4-075c) [LogonMonitor::ProcessLogonEvent] Event Id: 5, Session: 1
T10:33:31.032 TRACE (0dd4-075c) [LogonMonitor::ProcessLogonEvent] Event Id: 5, Session: 1

T08:40:14.892 INFO (1080-0dc0) [LogonMonitor::Logon] LOGON: User: domain\user2, Session: 1
T08:40:15.775 TRACE (1080-0dc0) [LogonMonitor::ProcessLogonEvent] Event Id: 1, Session: 1
T08:40:15.775 TRACE (1080-0dc0) [LogonMonitor::ProcessLogonEvent] Profile Started. Session: 1
T08:40:15.775 TRACE (1080-0728) [LogonMonitor::ProcessLogonEvent] Event Id: 6, Session: 1
T08:40:15.775 TRACE (1080-0728) [LogonMonitor::ProcessLogonEvent] Profile Sync Started. Session: 1
T08:40:42.650 TRACE (1080-0728) [LogonMonitor::ProcessLogonEvent] Event Id: 7, Session: 1
T08:40:42.650 TRACE (1080-0728) [LogonMonitor::ProcessLogonEvent] Profile Sync Finished. Session: 1
T08:40:42.650 TRACE (1080-0dc0) [LogonMonitor::ProcessLogonEvent] Event Id: 5, Session: 1
T08:40:42.650 TRACE (1080-0dc0) [LogonMonitor::ProcessLogonEvent] Event Id: 5, Session: 1

What is going on here?
User 2 has a much smaller profile to be imported than user 1, but DEM is located in the site of user 1. The profile areas are located in the user's site, respectively.
How can we monitor this job more deeply so that we can pin point what takes so long?
Are there any tools that allow me to easily see which application import takes the longest time?

***************SYSTEM***************

Windows 10: 10.0.18362.1016
RAM: 10GB
Instant Clone – Non presistant desktops
DEM: 9.10.0.921
Horizon: 7.10.1
4 CS in each site
1 Vcenter in each site (for Office clients)
About 90-140 sessions per site

*************************************

[DEMdev]

Hi lansti,

Are there any tools that allow me to easily see which application import takes the longest time?

While VMLM logs might provide some high-level insight into overall logon processing time, nothing beats DEM logs (at log level DEBUG) to pinpoint where the DEM agent is spending time.

Does the machine spend more than 1 minute on a GPO, or is it DEM that uses this time?

If DEM is configured to run as a Group Policy client-side extension at logon, it runs while user Group Policy is being applied, so the time it takes to perform its logon activities is indeed counted as such.

[lansti]

Hi DEMdev​, Group Policy client-side extension at logon is enabled, and we have the debug level enabled.

When I now logs in again, I can see that the vmlm.log has much more information, where I can pinpoint where the issues are located.

A section of the vmlm log:

2020-09-08T10:13:52.416 TRACE (0c44-122c) [MailslotServer::ProcessMessage] Begin event: Product: DEM Agent, Component: FlexEngine, Event: Logon, Event Type: EVENT_BEGIN, Process Id: 1800, Timestamp: 2020-09-08T10:13:52.416, Session: 1

2020-09-08T10:13:52.422 TRACE (0c44-122c) [MailslotServer::ProcessMessage] Begin event: Product: DEM Agent, Component: FlexEngine, Event: Pre-import, Event Type: EVENT_BEGIN, Process Id: 1800, Timestamp: 2020-09-08T10:13:52.422, Session: 1

2020-09-08T10:13:57.014 TRACE (0c44-122c) [MailslotServer::ProcessMessage] End event: Product: DEM Agent, Component: FlexEngine, Event: Pre-import, Event Type: EVENT_END, Process Id: 1800, Timestamp: 2020-09-08T10:13:57.014, Session: 1

2020-09-08T10:13:57.014 TRACE (0c44-122c) [MailslotServer::ProcessMessage] Begin event: Product: DEM Agent, Component: FlexEngine, Event: Import, Event Type: EVENT_BEGIN, Process Id: 1800, Timestamp: 2020-09-08T10:13:57.014, Session: 1

2020-09-08T10:14:45.242 TRACE (0c44-122c) [MailslotServer::ProcessMessage] End event: Product: DEM Agent, Component: FlexEngine, Event: Import, Event Type: EVENT_END, Process Id: 1800, Timestamp: 2020-09-08T10:14:45.242, Session: 1

2020-09-08T10:14:45.242 TRACE (0c44-122c) [MailslotServer::ProcessMessage] Begin event: Product: DEM Agent, Component: FlexEngine, Event: Post-import, Event Type: EVENT_BEGIN, Process Id: 1800, Timestamp: 2020-09-08T10:14:45.242, Session: 1

2020-09-08T10:14:53.436 TRACE (0c44-122c) [MailslotServer::ProcessMessage] End event: Product: DEM Agent, Component: FlexEngine, Event: Post-import, Event Type: EVENT_END, Process Id: 1800, Timestamp: 2020-09-08T10:14:53.436, Session: 1

2020-09-08T10:14:53.699 TRACE (0c44-122c) [MailslotServer::ProcessMessage] Begin event: Product: DEM Agent, Component: FlexEngine, Event: Async, Event Type: EVENT_BEGIN, Process Id: 6440, Timestamp: 2020-09-08T10:14:53.698, Session: 1

2020-09-08T10:14:53.913 TRACE (0c44-122c) [MailslotServer::ProcessMessage] End event: Product: DEM Agent, Component: FlexEngine, Event: Logon, Event Type: EVENT_END, Process Id: 1800, Timestamp: 2020-09-08T10:14:53.913, Session: 1

A section of the users vmlm log

2020-09-08T10:13:51.777 TRACE (0c44-1330) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 4016, ActivityID: {CB98865A-6F8D-443D-99C0-4A8CBFD6932F}, Account: , Session: 1

2020-09-08T10:14:54.936 TRACE (0c44-1234) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 4016, ActivityID: {CB98865A-6F8D-443D-99C0-4A8CBFD6932F}, Account: , Session: 1

2020-09-08T10:14:54.936 TRACE (0c44-1330) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5016, ActivityID: {CB98865A-6F8D-443D-99C0-4A8CBFD6932F}, Account: , Session: 1

2020-09-08T10:14:54.938 TRACE (0c44-1234) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5016, ActivityID: {CB98865A-6F8D-443D-99C0-4A8CBFD6932F}, Account: , Session: 1

2020-09-08T10:14:54.938 TRACE (0c44-1234) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5016, ActivityID: {CB98865A-6F8D-443D-99C0-4A8CBFD6932F}, Account: , Session: 1

...

Is it possible to identify what is imported here?

[DEMdev]

Hi lansti,

All the VMLM log can tell us is that DEM's logon processing took a minute (10:13:52.416 - 10:14:53.913), with about 48s spent on importing profile archives. You will need to refer to the DEM agent logs for more details.

[lansti]

Hi DEMdev​, so if I understand this log correct:

2020-09-08 10:13:52.624 [DEBUG] Conditions: Check for path 'c:\users\testuser' = false

2020-09-08 10:13:52.624 [INFO ] Skipping folder redirection due to conditions ('Folder Redirection testuser - Site1.xml')

2020-09-08 10:13:53.497 [INFO ] Successfully redirected 'Desktop' folder to '\\server.domain\home$\%username%\Desktop' ('Folder Redirection SITE2.xml')

It takes 1 minute to redirect "desktop" folder?

The log is written to when the job is done?

EDIT: Forget this post, i missed minutes/seconds.. my bad...

[Hocshop]

Hi,

I don´t know if you ever found the solution to this problem but I saw in an environment recently lots of problems with log-on time.

When I investigated further in the debug-level logs, I found that it was taking a very long time to map some network printers.

In particular printers that were connected by USB locally to a user´s computer then shared on the network from there.

Go through the debug-level logs from the beginning of the logon process and look at the time stamps, looking for any jumps in time frames.

Another thing I saw that chewed up a lot of time for DEM was the application of the Google Chrome profiles.

Chrome by default stores a really huge amount of info in a user´s profile.

If you already sorted this out, well done.

Regards

[aflopez]

@Hocshop I'm running into this issue now with Chrome. How were you able to navigate around that?

[DEBUG] ImportRegistry::Import: Calling '"C:\Windows\REGEDIT.EXE" /S "UserProfile"' (RPAL: l=0 (D/P), r=0)
[DEBUG] Read 16985 entries from profile archive (size: 420873327; compressed: 188606534; took 369210 ms; largest file: 12866871 bytes; slowest import took 1705 ms; registry took 199 ms)

[Hocshop]

Hi aflopez,

For the long import times of Chrome (this is because Chrome stores such a lot of info in the user´s profile) I had to customize the import/export settings in DEM.

What helped me the most was the following (it reduced the zip files from nearly 300MB down to between 15-20MB:

I hope that helps you?

Regards

# Flex config file generated with VMware Dynamic Environment Manager Application Profiler version 9.9

[IncludeRegistryTrees]

HKCU\Software\Google\Chrome

HKCU\Software\MozillaPlugins

[IncludeFolderTrees]

<LocalAppData>\Google\Chrome\User Data

[ExcludeFolderTrees]

<LocalAppData>\Google\Chrome\User Data\Default\Cache

<LocalAppData>\Google\Chrome\User Data\Default\Code Cache

<LocalAppData>\Google\Chrome\User Data\Default\Application Cache

<LocalAppData>\Google\Chrome\User Data\Default\Storage

<LocalAppData>\Google\Chrome\User Data\Default\Local Storage

<LocalAppData>\Google\Chrome\User Data\Default\Media Cache

<LocalAppData>\Google\Chrome\User Data\Default\Session Storage

<LocalAppData>\Google\Chrome\User Data\Default\GPUCache

<LocalAppData>\Google\Chrome\User Data\Default\Web Applications

<LocalAppData>\Google\Chrome\User Data\Default\Sync Data

<LocalAppData>\Google\Chrome\User Data\Default\Sync Data Backup

<LocalAppData>\Google\Chrome\User Data\Default\Pepper Data\Shockwave Flash\CacheWriteableAdobeRoot

<LocalAppData>\Google\Chrome\User Data\Default\IndexedDB

<LocalAppData>\Google\Chrome\User Data\Profile 1\Cache

<LocalAppData>\Google\Chrome\User Data\Profile 1\Code Cache

<LocalAppData>\Google\Chrome\User Data\Profile 1\Application Cache

<LocalAppData>\Google\Chrome\User Data\Profile 1\Storage

<LocalAppData>\Google\Chrome\User Data\Profile 1\Local Storage

<LocalAppData>\Google\Chrome\User Data\Profile 1\Media Cache

<LocalAppData>\Google\Chrome\User Data\Profile 1\Session Storage

<LocalAppData>\Google\Chrome\User Data\Profile 1\GPUCache

<LocalAppData>\Google\Chrome\User Data\Profile 1\Web Applications

<LocalAppData>\Google\Chrome\User Data\Profile 1\Sync Data

<LocalAppData>\Google\Chrome\User Data\Profile 1\Sync Data Backup

<LocalAppData>\Google\Chrome\User Data\Profile 1\Pepper Data\Shockwave Flash\CacheWriteableAdobeRoot

<LocalAppData>\Google\Chrome\User Data\Profile 1\IndexedDB

<LocalAppData>\Google\Chrome\User Data\Profile 2\Cache

<LocalAppData>\Google\Chrome\User Data\Profile 2\Code Cache

<LocalAppData>\Google\Chrome\User Data\Profile 2\Application Cache

<LocalAppData>\Google\Chrome\User Data\Profile 2\Storage

<LocalAppData>\Google\Chrome\User Data\Profile 2\Local Storage

<LocalAppData>\Google\Chrome\User Data\Profile 2\Media Cache

<LocalAppData>\Google\Chrome\User Data\Profile 2\Session Storage

<LocalAppData>\Google\Chrome\User Data\Profile 2\GPUCache

<LocalAppData>\Google\Chrome\User Data\Profile 2\Web Applications

<LocalAppData>\Google\Chrome\User Data\Profile 2\Sync Data

<LocalAppData>\Google\Chrome\User Data\Profile 2\Sync Data Backup

<LocalAppData>\Google\Chrome\User Data\Profile 2\Pepper Data\Shockwave Flash\CacheWriteableAdobeRoot

<LocalAppData>\Google\Chrome\User Data\Profile 2\IndexedDB

<LocalAppData>\Google\Chrome\User Data\Browser Metrics

<LocalAppData>\Google\Chrome\User Data\SwReporter

<LocalAppData>\Google\Chrome\User Data\WidevineCDM

<LocalAppData>\Google\Chrome\User Data\EVWhitelist

<LocalAppData>\Google\Chrome\User Data\pnacl

<LocalAppData>\Google\Chrome\User Data\recovery

<LocalAppData>\Google\Chrome\User Data\SwiftShader

<LocalAppData>\Google\Chrome\User Data\SwReporter

<LocalAppData>\Google\Chrome\User Data\ShaderCache

<LocalAppData>\Google\Chrome\User Data\PepperFlash

[ExcludeFiles]

<LocalAppData>\Google\Chrome\User Data\Default\ChromeDWriteFontCache

<LocalAppData>\Google\Chrome\User Data\Profile 1\ChromeDWriteFontCache

<LocalAppData>\Google\Chrome\User Data\Profile 2\ChromeDWriteFontCache

<LocalAppData>\Google\Chrome\User Data\Safe Browsing Bloom

<LocalAppData>\Google\Chrome\User Data\Safe Browsing Bloom Prefix Set

<LocalAppData>\Google\Chrome\User Data\Safe Browsing Download

<LocalAppData>\Google\Chrome\User Data\Safe Browsing UwS List

<LocalAppData>\Google\Chrome\User Data\Safe Browsing UwS List Prefix Set

<LocalAppData>\Google\Chrome\User Data\ev_hashes_whitelist.bin

*.tmp