The system takes an actual long time to shutdown; >75 seconds.
Analysis:
Shutdown traces are quite a bit different then boot up and logon performance traces. In a shutdown sceario you want processes and drivers to stop and unload as fast as possible. There are a few issues that may stop this from happening, like A GPO logoff or shutdown script, clearing the pagefile on shutdown, slow service shutdown, open applications and others.
There are WPA.exe profiles for shutdown analysis in the WPA Profiles folder.
Overall CPU and Disk Usage
First thing after opening the trace to look for is a high level of resource usage in the left side graphs. Look at the CPU usage and disk usage graphs to quickly verify if the resources were heavily in use during the trace period. In this case, the CPU usage graph spikes pretty high so it warrants more investigation.
Add the CPU Usage (Sampled) graph to the analysis view. See the highest consumers of CPU in weight during the trace period. There were 6 processes > 1% CPU usage in weight. There is only 1 CPU available in the machine. This can be verified by opening the Menu->Trace->'System Configuration'->General tab. The TiWorker.exe (3540) process was the highest user of CPU during the trace period. Let's see if we can investigate what the process was doing during the trace period. This trace includes the stackwalk events, which can be verified by going to Menu->Trace->'System Configuration'->'Trace Statistics' tab.
Since we are looking at CPU usage and not looking for processes that are waiting for CPU at this point you can use the same CPU Usage (Sampled) graph to view the stack of each process. Before continuing, load the symbols by going to Menu->Trace->'Load Symbols'. Your symbols should be set to at least the public Microsoft symbol server. (SRV*https://msdl.microsoft.com/download/symbols). You can configure your symbols by going to Menu->Trace->'Configure Symbol Paths'. A screenshot of my paths are below.
After symbols are loaded you can open the stack for the highest CPU consumer, process TiWorker.exe (3540). Open each of the highest CPU weight rows under the process and look for public functions that will give clues to the processing of the threads in the process.
You should see the many functions are in the module CbsCore.dll. You can look at the details of that dll file in the Images graph or look in the details of the machine's file or search online but you will find that this dll supports servicing in Windows; which is Windows updates and features. You will also see that there were some hard page faults as well, so you should be able to see that in the Memory->Hard Faults graph.
You can see a correlation between the hard page faults and disk usage in the graphs.
So it looks like there was some update servicing when this shutdown occurred.
Continuing Investigation
You may stop the analysis at this point and put the blame on just the Windows servicing but since the CPU and disk was not 100% utilized during the whole trace period there can be other factors at play as well.
Always look at the Services graph and Processes graph when investigating shutdown WPA traces.
Open the Service graph and sort/group by 'Ended At(s)' descending, then End Thread ID, then Service Init Time (s). You will see that there are 3 services that took longer than 1 second to stop. WinDefend, wuauserv and MSSQLSERVER. Also notice that these 3 services did not try to shutdown until after the Tiworker.exe and cleanmgr.exe processes were done processing. In this case, it looks like these services could not being shutdown until the servicing was complete.
To view the process that were shutting down in the trace, use the Process graph and sort by Start Time9s) descending. View what processes started from the end of the shutdown towards the beginning. You should see LogonUI.exe as one of the last processes, this is normal. The LogonUI.exe process shows what the machine is doing in text after the desktop is shutdown.
The other processes give clues to what was occurring at the time as well. There are a few wlrmdr.exe process, some shutdown.exe processes and a MicrosoftEdgeUpdate.exe (5044) process.
The Windows servicing was kicked off by cleanmgr.exe using the following command; C:\Windows\system32\cleanmgr.exe /autoclean /d C:
This caused the TiWorker process to read a bunch of Cbs files on the drive. Microsoft Edge browser was also serviced at this time.
The main cause of the long shutdown though was the command issued to wait to reboot; shutdown /r /t 60 /d p:0:0
It just happened that while the system was waiting to shutdown for 60 seconds the Windows serving stack kicked in.
Remediation:
Do not give a command to shutdown in 60 seconds if you do not want to wait, or force the shutdown/reboot. Forcing shutdown or reboot should have not allowed the system to service Windows while shutting down.
You really should let Windows do it's updates though, when needed, so some of this could not be helped.
Scenario:
The system takes an actual long time to shutdown; >75 seconds.
Analysis:
Shutdown traces are quite a bit different then boot up and logon performance traces. In a shutdown sceario you want processes and drivers to stop and unload as fast as possible. There are a few issues that may stop this from happening, like A GPO logoff or shutdown script, clearing the pagefile on shutdown, slow service shutdown, open applications and others.
There are WPA.exe profiles for shutdown analysis in the WPA Profiles folder.
Overall CPU and Disk Usage
First thing after opening the trace to look for is a high level of resource usage in the left side graphs. Look at the CPU usage and disk usage graphs to quickly verify if the resources were heavily in use during the trace period. In this case, the CPU usage graph spikes pretty high so it warrants more investigation.
Add the CPU Usage (Sampled) graph to the analysis view. See the highest consumers of CPU in weight during the trace period. There were 6 processes > 1% CPU usage in weight. There is only 1 CPU available in the machine. This can be verified by opening the Menu->Trace->'System Configuration'->General tab. The TiWorker.exe (3540) process was the highest user of CPU during the trace period. Let's see if we can investigate what the process was doing during the trace period. This trace includes the stackwalk events, which can be verified by going to Menu->Trace->'System Configuration'->'Trace Statistics' tab.
Since we are looking at CPU usage and not looking for processes that are waiting for CPU at this point you can use the same CPU Usage (Sampled) graph to view the stack of each process. Before continuing, load the symbols by going to Menu->Trace->'Load Symbols'. Your symbols should be set to at least the public Microsoft symbol server. (SRV*https://msdl.microsoft.com/download/symbols). You can configure your symbols by going to Menu->Trace->'Configure Symbol Paths'. A screenshot of my paths are below.
After symbols are loaded you can open the stack for the highest CPU consumer, process TiWorker.exe (3540). Open each of the highest CPU weight rows under the process and look for public functions that will give clues to the processing of the threads in the process.
You should see the many functions are in the module CbsCore.dll. You can look at the details of that dll file in the Images graph or look in the details of the machine's file or search online but you will find that this dll supports servicing in Windows; which is Windows updates and features. You will also see that there were some hard page faults as well, so you should be able to see that in the Memory->Hard Faults graph.
You can see a correlation between the hard page faults and disk usage in the graphs.
So it looks like there was some update servicing when this shutdown occurred.
Continuing Investigation
You may stop the analysis at this point and put the blame on just the Windows servicing but since the CPU and disk was not 100% utilized during the whole trace period there can be other factors at play as well.
Always look at the Services graph and Processes graph when investigating shutdown WPA traces.
Open the Service graph and sort/group by 'Ended At(s)' descending, then End Thread ID, then Service Init Time (s). You will see that there are 3 services that took longer than 1 second to stop. WinDefend, wuauserv and MSSQLSERVER. Also notice that these 3 services did not try to shutdown until after the Tiworker.exe and cleanmgr.exe processes were done processing. In this case, it looks like these services could not being shutdown until the servicing was complete.
To view the process that were shutting down in the trace, use the Process graph and sort by Start Time9s) descending. View what processes started from the end of the shutdown towards the beginning. You should see LogonUI.exe as one of the last processes, this is normal. The LogonUI.exe process shows what the machine is doing in text after the desktop is shutdown.
The other processes give clues to what was occurring at the time as well. There are a few wlrmdr.exe process, some shutdown.exe processes and a MicrosoftEdgeUpdate.exe (5044) process.
The Windows servicing was kicked off by cleanmgr.exe using the following command; C:\Windows\system32\cleanmgr.exe /autoclean /d C:
This caused the TiWorker process to read a bunch of Cbs files on the drive. Microsoft Edge browser was also serviced at this time.
The main cause of the long shutdown though was the command issued to wait to reboot; shutdown /r /t 60 /d p:0:0
It just happened that while the system was waiting to shutdown for 60 seconds the Windows serving stack kicked in.
Remediation:
Do not give a command to shutdown in 60 seconds if you do not want to wait, or force the shutdown/reboot. Forcing shutdown or reboot should have not allowed the system to service Windows while shutting down.
You really should let Windows do it's updates though, when needed, so some of this could not be helped.