First published on TechNet on Jul 02, 2012
Login scripts once implemented in an environment tend to never really get removed. They are always there, running. The fact that many of these login script functionality, such as mapping drives, could be moved to Group Policy Preferences (http://blogs.technet.com/b/askds/archive/2009/01/07/using-group-policy-preferences-to-map-drives-bas... ). The real question is do you know how long your login scripts take to complete? What about that one script that was supposed to run one time and never again? Are you sure it is running on every login? We will dive in and find out.
In our previous posts (https://techcommunity.microsoft.com/t5/core-infrastructure-and-security/slow-boot-slow-logon-sbsl-a-... we’ve talked about how to take an xbootmgr trace. Open up the trace and scroll down until you see “Process Lifetimes”
We are going to want to right click in this area and choose “select view”. This will then highlight the entire view. Right click again and select “process summary table” where a new window will open that gives us a detailed view of every process that started during the trace. Since we are investigating login scripts know that they tend to take a few forms, bat files and vbscripts are often the most popular.
First, we will want to get our columns in order. I recommend the order of Process, Process ID, Parent Process ID, Duration, Start Time, End Time, Hosted Services, Command Line. These can be added or removed from the Columns Menu. Now take a look and see if we have any cmd.exe processes launching during this time frame. In this case we do:
Here we can see that cmd.exe process ID 2,164 is taking 30 seconds to complete. We also see that it kicks off 3 other child processes, 2,236, 2,352, and 2,268. Those run very quickly but we are able to tell this is where they came from, as they all share the same Parent Process ID, 2,164. Understanding this parent child process relationship will help us to continue to drill down. For now if we scroll to the right to look under Command Line to see what is being called:
This is appears to be launching from a group policy since we are in the directory \sysvol\domain name\Policies\GUID\Machine\Scripts\Startup\ and we are calling the script called startup.cmd. Here is the part where I tell the admin that they now have a 30 second login script. Their responses range from “there is no way” to “not possible” and even “inconceivable!” especially if they were Vizzini from Princess Bride. As Inigo Montoya would say, “I do not think that word means what you think it means.” Well we could stop right here and say this startup.cmd script is the problem, but what if this script is large and does lots of things? We need to get more specific to see what else this script is kicking off to get to the root delay. We do this by dragging the Parent Process ID column all the way to the left so that it is now what we are sorting by. Then, we target the process ID we are interested in, 2,164.
This script is busy, they always are. The one that seems to be our bottleneck is a Cscript.exe with the process ID of 2,316 is taking 28 seconds to complete. If we scroll to the right we will see the command being launched.
The top arrow is our original script; the second arrow is process 2,316. It is calling another script, startup.vbs. It also appears to be coming from the same group policy which is confusing, in general, but that is a different issue altogether. As we push on, let’s go investigate what child process are being kicked off from process 2,316.
This process is another cscript with the process ID of 2,364 that is taking 26 seconds to complete. We scroll to the right to see what is being kicked off.
I know what you are thinking, this just keeps on going, doesn’t it? I promise there is a light at the end of the tunnel. We see that we are mapping to a DFS share to launch another VBScript called SDT.VBS. Let’s see what child process come from the process 2,364.
Finally not another script! We can see that this process, 2,728 spawned from SDT.vbs 2,364 is doing an install of some sort. It is also taking 18 seconds complete. The line directly above it (33) is its parent and is taking 26 seconds as we can see above. I don’t have a network trace to confirm this but I’m suspecting it is taking roughly 12 seconds to map the drive to launch the SDT.VBS script. Let’s scroll over to see what all this trouble was for:
There you have it! Vcredist.msi installer is taking a large part of our login script time. Chances are that this doesn’t need to be installed EVERY SINGLE TIME. We were able to remove this from our login script and reduce our boot time substantially, about 30 seconds. Continuing to dig through the parent processes allowed us to identify the actual root cause of the delay.
Hello. My name is Mark Morowczynski. You kill my boot time. Login Script….prepare to die.