IMPORTANT ANNOUNCEMENT FOR OUR READERS!
AskPFEPlat is in the process of a transformation to the new Core Infrastructure and Security TechCommunity, and will be moving by the end of March 2019 to our new home at https://aka.ms/CISTechComm (hosted at https://techcommunity.microsoft.com). Please bear with us while we are still under construction!
We will continue bringing you the same great content, from the same great contributors, on our new platform. Until then, you can access our new content on either https://aka.ms/askpfeplat as you do today, or at our new site https://aka.ms/CISTechComm. Please feel free to update your bookmarks accordingly!
Why are we doing this? Simple really; we are looking to expand our team internally in order to provide you even more great content, as well as take on a more proactive role in the future with our readers (more to come on that later)! Since our team encompasses many more roles than Premier Field Engineers these days, we felt it was also time we reflected that initial expansion.
If you have never visited the TechCommunity site, it can be found at https://techcommunity.microsoft.com. On the TechCommunity site, you will find numerous technical communities across many topics, which include discussion areas, along with blog content.
NOTE: In addition to the AskPFEPlat-to-Core Infrastructure and Security transformation, Premier Field Engineers from all technology areas will be working together to expand the TechCommunity site even further, joining together in the technology agnostic Premier Field Engineering TechCommunity (along with Core Infrastructure and Security), which can be found at https://aka.ms/PFETechComm!
As always, thank you for continuing to read the Core Infrastructure and Security (AskPFEPlat) blog, and we look forward to providing you more great content well into the future!
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-based-on-group-membership.aspx ). 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 (http://blogs.technet.com/b/askpfeplat/archive/2012/06/09/slow-boot-slow-logon-sbsl-a-tool-called-xperf-and-links-you-need-to-read.aspx ) 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.