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”

http://blogs.technet.com/b/askpfeplat/archive/2014/02/03/becoming-an-xperf-xpert-part-7-slow-profile-load-and-our-very-first-stack-walk.aspx

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.