Becoming an Xperf Xpert Part 8: Long Service Load, Never Jump to Conclusions
Hi everyone Randolph (Randy) Reyes with another SBSL blog post. In this particular engagement we were able to be more proactive, our job was to check and verified a Windows 7 image prior of mass deployment all around the world.
When arriving onsite we notice that 1,000 Windows 7 machines were already deployed and 7,000 are schedule in 3 weeks.
So let’s get to it.
The Before
PreSMSS |
SMSSInit |
WinlogonInit |
ExplorerInit |
Post Boot |
3.037 |
8.067 |
144.139 |
17.896 |
74.000 |
Boot to Post Boot Activity ended: 247 Seconds and 539 Milliseconds = 4 Minutes and 7 Seconds
Looking at this number definitely our boot time is not with in good values using traditional hard-drive (non-SSD).
What’s consider good value?
Here is an article previously posted with those values. “Becoming an Xperf Xpert Part 7: Slow Profile Load and Our Very First Stack Walk”
The major delay in the boot trace can be identified in the Winlogon Phase. Many operations occur in parallel during WinLogonInit. On many systems, this subphase is CPU bound and has large I/O demands. Services like PnP and Power, network subsystem, Computer and User Group Policy processing, CAD (CTRL+ALT+DEL) screen and credentials delay. Good citizenship from the services that start in this phase is critical for optimized boot times.
After adding the graph for Boot Phases and also Generic Event we can see that most of the Winlogon Initiation Phase time is been consume by the Subscriber Profiles under the Microsoft-Windows-Winlogon provider. In the picture below we can see when the Subscriber Profile started at 30.772 and ended at 154.169 of the trace.
Before jumping into any conclusion of why Profiles are taking too long to load, I decided to look all the different Graph’s that Windows Performance Toolkit provide to us.
The graph that caught my eye is Services. So let’s add the Services to the analysis view.
Choosing to highlight the start and stop time of Profiles we can see a service call SVCHost32.exe starting before Profiles. Looks like Profiles initiation is been extended by the Service SVCHost32.exe.
Services = Services can declare dependencies or use load order groups to ensure that they start in a specific order. Windows processes load order groups in serial order. Service initialization delays in an early load order group block subsequent load order groups and can possibly block the boot process.
Long delays during any service initialization can increase the time that the boot transition requires. If you can do so, set services to demand start or trigger start. Demand-start and trigger-start services start after the boot process is complete and therefore reduce overall boot time.
Important reminder services “300 or less milliseconds should take to initialize”
After adding the graph for Boot Phases and also Services “Display Graph and Table” we can see that the service SVCHost.32.exe started at 28.350 and ended 125.809 in the trace.
Wow that’s a long time for a service to initialize, it should only take around 300 Milliseconds. If we add the Service Initiation time and Container Initiation Time we get 97.458 (1 Minute and 37 Seconds)
I know what you are thinking, this is a critical service for the company and no matter what we need to leave it alone. :) Here is a conversation I had.
Randy: Why is this service taking this long? Do you know what software is using this service?
Customer: Yes, this is an internal application that needs to be in every system in the environment
Randy: What is this software supposed to do? Is the software needed when user is booting or do we use it after the user logs in?
Customer: (Thinking) Honestly not sure I will need to ask the programmers.
15 Minutes later…..
Customer: The software scans user data that is copied to the file servers and the version installed in the image is including a new update. The system didn’t take this long before this update was deployed.
Randy: Sounds like this service is not necessary to start at boot time and also we need to check if the update is the cause of this long delay in the service.
At this point for testing purposes we open the Services Microsoft Management Console, searched for the service SVCHost.exe and changed the Startup Type from Automatic to (Automatic Delayed Start)
The Fixes
Step 1 = Startup Type from Automatic to (Automatic Delayed Start)
The After
Boot to Post Boot Activity end: 68 Seconds and 004 Milliseconds = 1 Minutes and 8 Seconds
(Note: In this particular engagement we still have other areas that will improve boot time in this particular systems but those will be posted in another blog post.)
At the end of this engagement I was really happy! Not only because we shorted the boot time in the systems, but also because I got an e-mail from the company programmer two days later.
Programmer: Thank you so much for the work you did. After your visit and the recommendations in the SVCHost.exe service, we detected a bug in the application. At this moment the bug is fixed and service is no longer affecting boot time our systems.
Before
1,000 Computers x 4 minutes and 4 seconds= 4,000 minutes every working day
Potential full environment
7,000 Computer x 4 minutes and 4 seconds = 28,000 minutes every working day
After
1,000 Computer x 1 minute and 8 seconds = 1,000 minutes every working day
Recommended Articles
Troubleshooting Windows Performance Issues Using the Windows Performance Recorder
Here is another blog from a good friend and fellow blogger Mark Morowczynski that also talk about another Services Delay if you missed it.
Becoming an Xperf Xpert Part 4: What Did the WDIService Host Ever Do To You?
https://blogs.technet.com/b/askpfeplat/archive/2012/09/24/becoming-an-xperf-xpert-part-4-what-did-the-wdiservice-host-ever-do-to-you.aspx
Also want to send a special thank you to, Yong Rhee, Mark Morowczynski and Antonio Vasconcelos.
Randy “How much boot time can you save today?” Reyes