5 Replies Latest reply on Oct 7, 2020 3:44 PM by Hocshop

    Windows 10 – Challenges with Logon time and Profile import

    lansti Enthusiast

      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

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

        • 1. Re: Windows 10 – Challenges with Logon time and Profile import
          DEMdev Master
          VMware Employees

          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.

          • 2. Re: Windows 10 – Challenges with Logon time and Profile import
            lansti Enthusiast

            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?

            • 3. Re: Windows 10 – Challenges with Logon time and Profile import
              DEMdev Master
              VMware Employees

              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.

              • 4. Re: Windows 10 – Challenges with Logon time and Profile import
                lansti Enthusiast

                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...

                • 5. Re: Windows 10 – Challenges with Logon time and Profile import
                  Hocshop Novice
                  VMware Employees

                  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