Monday, 24 March 2014

Using Process Monitor to investigate logon times and analyse applications

Two of the things I am most often asked when talking to AppSense customers and partners are:
  • How do I determine what my logon times are?
  • How do I determine what I need to personalise for an application?
This blog post will describe how I use Process Monitor, a free tool included as part of Microsoft's SysInternals Suite, to help with both of these tasks:
Logon Times

All jokes aside, I usually ask the customer to do a little bit of preparation work then stand next to an end user, make a not of the time and then use the stopwatch on their phone to time from when the user presses return after typing their password to the point where the desktop is usable. Sure, this isn't the most accurate way of measuring logon time but it does give me a good indication on where to look in the log files, etc that I get the to configure as part of the preparation work. 

In the example I am going to run through the user started logging on shortly after 12:46 PM and I know the desktop was usable at around 12:48 PM. 

I spoke earlier about some preparation work. Here is what I ask:

The first thing I do is ask the customer to identify a user who repeatedly experiences poor logon times so that we have a benchmark. I ask them to add an application to the users Startup folder or Run registry key. These locations are both run towards the back end of the logon process after group policy, logon scripts, etc have been run. I then time the logon process using my very simple stopwatch method from the point where the user pressed return to the point where the application starts up before we start playing within anything to get a rough baseline time.  

The next thing I do is enable Process Monitor in session 0 so that I can capture everything that goes on during logon. I like to use session 0 instead of having an Administrator logged on to the machine purely because the Administrators session will add a number of additional executables to the machine which will all be consuming additional resources. In order to configure this take a look at Mark Russinovich's blog post describing the case of the slow logons here

With Process Monitor configured I ask the customer to log on with the user, timing the process. The only difference here is that I ask the customer to gather the users Session ID from Task Manager because this will help me narrow down the Process Explorer log. In this example the users session was session 2. As soon as the approximate logon time is known and the session id is known you can log the user off, log back on as the administrator and stop Process Monitor from capturing logs. Ensure you save the log file to an accessible location before closing Process Monitor within session 0. 

Once this is done copy the log file to a network location so that you can analyse the log file away from the end users desk. At this point you're done at the end users desk.

Now open the log file using Process Monitor. First thing to do is configure a filter within the process monitor log. In my example I had logging enabled for about 4 minutes and had a total of 3 million entries in the log... by applying the session filter I immediately cut out 2 million entries.  

In order to do this click the Filter button within Process Explorer:

Within the Process Monitor Filter dialogue select the session drop down, next ensure the relation option is set to "is" and then type the session number into the value. Lastly, ensure the action is set to "Include" and then click the Add button:

Once the filter is in place I can tell that my users log on process started at 12:46:01 PM. 

Instead of applying additional filters or scrolling through the log to find where the process I added to the Startup folder or RunOnce key started, I've found the easiest method for finding this within the log is to click on the process tree icon, seen below:

Immediately I can tell that the application I added to my Startup folder started at 12:47:43 PM. So that means my total logon process was 1 minute and 42 seconds. 

Scrolling through the Process Tree it becomes clear where I need to look. EMUser.exe started at 12:46.17, a mere 16 seconds into the full logon process but this process has a number of child processes that appear to run for some time. 

In this example there are a few processes I am interested in:

WScript.exe - I know this is the engine that executes any custom VB Script actions configured within AppSense Environment Manager so the fact that there are 5 could raise some questions. On this occasion all of them were quick to complete with the longest one running for 6 seconds. This script was also started after logon had completed because this is trigged by my "post logon" trigger which I described in another blog post.

EmPsHost.exe - I know that this is the engine that executes any custom PowerShell scripts configured with AppSense Environment Manager. Interestingly there are two actions that appear to be identical actions running in parallel and each of these runs for 10 seconds. 

EmLoggedOnUser.exe - This is the process that is responsible for performing network drive and network printer mappings within Environment Manager Policy. This confirms that the "logon" portion of Environment Manager policy was still running until 12:47:21 PM. 

EMUser.exe - This is the AppSense User Virtualization service that will execute all the logon actions within a users session. All native actions won't be seen as individual processes within the process tree. The fact that EMUser started 16 seconds into logon and EmLoggedOnUser only exited over a minute later indicates that the delay is almost certainly within this process. 

Everything else appears to be normal within the logon process so the next step would be enabling Environment Manager debug logging and analysing those to look for errors, delays, etc. I will not be covering this topic within this blog post. 

Note: In this particular example I have engineered the delay by moving my virtual machine used to create the log file off my SSD and have duplicated actions within my Environment Manager configuration to deliberately delay the logon process. I've done this by including two powershell actions that use WMI to lookup my users SID and then set an environment variable which is the 10 second delay. I've also duplicated an action to set an environment variable using VBscript to try and show how to use process monitor to narrow your search down. In addition, I had a drive mapping action to a server that I had deliberately taken offline. 

Application Personalization

This topic in itself can typically take a half day workshop to describe end-to-end. At a high level one of the tools I often use to identify registry keys and folders to be personalised with an application is using Process Monitor.

For best results I always recommend using Process Monitor alongside other tools like AppSense Configuration Assistance, Template Creator (AppSense Exchange tool) and Data Collection mode (enabled within the User Personalization section of the Environment Manager console).

First off, configure Process Monitor with a filter for the application you are looking to monitor. In this example, Lync.exe. 

Begin capturing and then either as the administrator, packager or user launch the application you have configured the filter for. Process Monitor will immediately start displaying entries within the results pane.

You'll notice that there is still a lot more information within this filter that we don't necessarily need. In order to simplify the process I typically add two more filters to the Process Monitor Filter dialogue. These filters are:
  • Operation is RegSetInfoKey
  • Operation is CreateFile
We know from a Personalization perspective we virtualise on write so by keeping all of the registry reads, file reads, etc within the display we are only dramatically increasing the amount of time to build a configuration.

At this point we have a streamlined output, as seen below:

At this point a bit of common sense must prevail. You can't simply include everything shown in the output to the user personalization console because you'll end up with a massive number of entries which are not required. In addition, a number of the registry keys that are written to aren't really relevant to the standard operation of the application. 

In the image above you can see there are a number of instances where Lync.exe has written information to HKCU\Software\Microsoft\Windows\CurrentVersion\Internet Settings. Almost every modern application will write (or at least try and write) to these keys. There are totally irrelevant to the personalization of the Lync client. 

However looking further down that same image you will notice another key, HKCU\Software\Microsoft\Office\15.0\Lync. This is definitely a key we want to investigate. At this point I usually just open up a registry editor, browse to the key and take a look at the contents:

Straight away you will notice that you are onto the right track. Values like ServerSipUri are entries that the user won't want to enter every time. 

At this point I typically recommend building a configuration for the application and capturing that registry key. Then logon and test the application in the same way a user would, e.g. launch the application, logon, initiate a call, initiate an IM, accept a call, accept an IM, change some preferences.  Then logoff, ensure your local user profile is deleted either by implementing a temporary profile approach, a mandatory profile or by logging on as an administrator and deleting the local profile. 

Log on again and verify the application works as expected. If it doesn't you need to repeat the previous steps using Process Monitor. If it does I would highly recommend logging out again and looking at the application within Personalization Analysis. Ensure the application isn't excessively large, doesn't have any resiliency keys, etc. I know Lync has resiliency keys similar to Office 2007, 2010 and 2013 and so these must also be excluded to avoid unnecessary database bloat and performance degradation. 

Unfortunately application personalization is a trial and error process much like sequencing an application using App-V. There isn't necessarily a configuration that will meet all requirements and more often than not the configuration will need an element of tweaking. 

I hope this post helps someone.