itoleck / WindowsPerformance

Various Windows Performance files, scripts, settings and documents
MIT License
30 stars 9 forks source link

Answer key for trace; Create_100files.etl #3

Open itoleck opened 2 years ago

itoleck commented 2 years ago

Scenario:

100 files were being created from process cmd.exe (2024) with the command 'fsutil file createnew c:\temp\files\A###.tmp'. There was 1 CPU available. Process MsMpEng.exe (2372) was utilizing just over half of the CPU at 58.89% weight. Overall CPU usage was high at 90.92% weight.

There is slow disk access, but overall disk utilization looks low and average Disk Service Time(Latency) is low at 5.759ms. At this point it looks like the issue may just be not enough CPU.

Storage Mini-Filter Delays are very high. There is a mini-filter installed (ChadsBadFilter.sys) that is 10x slower (23.756ms avg) than the next highest driver (Wdfilter.sys) (2.255ms).

Analysis:

CPU Usage

  1. Start with the CPU Usage (Sampled) graph and use the 'Utilization By Process' filter. There is no need for adding stack information because the trace does not contain stack information.

  2. Sort by % weight column and view process MsMpEng.exe (2372), Anti-Virus, utilizing over half of the 1 CPU at 58.89 % weight.

Create_100files-1

  1. Change view to 'Utilization By CPU' to view the overall CPU utilization during the trace at 90.92 % weight. This is nearly all of the CPU.

Create_100files-2

Disk Usage

  1. Add the Disk Usage graph to the analysis view and select the following columns.

Disk | Priority | IO Type | Process | IO Init Stack |GOLDBAR| Disk Service Time(us) Avg | Size | Count |BLUEBAR| Disk Service Time(us) Sum


  1. Sort by Disk Service Time(us) Avg descending. Notice that the overall average latency is low at 5.759ms.

Create_100files-3

  1. Sometimes slow storage performance does not show in the DiskIO chart. Mini-filter drivers are drivers that load in the storage stack to perform functions on I/O Request Packets. To check for delays in the storage mini-filters, add the Graph Explorer->Storage->Mini-Filter Delays graph to the analysis view and change the columns to the following.

Mini-Filter Driver | ProcessID | File Name |GOLDBAR| Duration (us) Sum | Duration (us) Max | Duration (us) Avg | Count |BLUEBAR| Start (s) | End (s)


  1. Sort by Duration (us) Avg descending and notice that the ChadsBadFilter.sys driver is causing an average 23.756ms delay for each IO. This is comparable to a hard disk :fire:, but if the underlying storage was a slow hard disk, the DiskIO graph would have showed higher overall latency instead of 5.759ms average.

Create_100files-4

Other mini-filter drivers to watch for include anti-virus and data loss protection software.

Remediation:

Add CPU core/s and remove/debug the ChadsBadFilter.sys storage mini-filter driver.