Answer key for trace; HighCPUPlusOtherIssues.etl

[itoleck]

Scenario:

Python was running a long command to open 2 million record .csv file and write a small file on c:\temp\2mfiles for each row.

Explorer.exe had an open window to the save location c:\temp\2mfiles and was refreshing the file count and list.

Disk access was through Hyper-V VMBus which was causing a bit high kernel CPU usage.

Analysis:

Python

1. Python.exe(10844) and Explorer.exe(9224) processes high CPU usage. There are 3 logical CPU cores available on machine. CPU %Weight in CPU Usage (Sampled) is close to 1 CPU max weight of 33.3% (100 / 3). Explorer.exe 29.73% weight and Python.exe 29.28% weight.

2. Python symbols are available as part of the Windows Python package. Add symbol path to Python install location, i.e. c:\programdata\anaconda3

3. Load symbols

4. Use CPU usage (Precise) graph to view what Python may be doing to utilize CPU. Use column view 'Utilization by Process, Thread, Stack.

5. Open stack for python.exe and find following stacks:
   python39.dll!builtin_print 15.42% weight - Python print function(printing to screen)
   python39.dll!_io_open 8.36% weight - Python file open/create function(opening or creating file)

6. When Python command was run output was being written to stdout/screen. Running without print statement will help CPU usage.

7. Check file usage for python.exe. Add DiskIO graph to analysis view.

8. Select column view 'Service Time by Process, Path Name, Stack'

9. View python.exe (10844) process. Each value in 'Disk Service Time' is within good SSD performance limits. (i.e. 781.900 microseconds). If the storage was slower hardware this could have been an issue.

10. View the stack functions and find that the files were being written. (i.e. python39.dll!buffered_close, partmgr.sys!PartitionWrite, partmgr.sys!PmWrrite)

Explorer

1. Use CPU Usage (Precise) graph to view utilization of threads in Explorer process. Use column view 'Utilization by Process, Thread, Stack'

2. Find threads 6,100 and 2,716. 6,100 is highest CPU usage at 20.68% weight.

3. Open thread 6,100 and view stack, find ntskrnl.exe!KiDpcInterrupt function with 11.75% weight. This is high kernel CPU usage.

4. Open DPC/ISR graph. Use column view 'DPC/ISR Duration by Module, Function'. Sort columns descending by 'Duration (Fragmented) (ms).

5. See vmbus.sys driver has high max duration at 0.302100ms. Any durations > 0.1 is considered high.

Remediation
If process really needed to write 2 million files then the process should not output each line to screen and the Explorer window should not be opened to the location were the files are being written for best performance of application.

[MagicAndre1981]

btw, I made a large topic on superuser with a lot of cases for high CPU usage of the SYSTEM process/kernel. This may be helpful for users.