search

itoleck / WindowsPerformance

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

Answer key for trace; HighCPUPlusOtherIssues.etl #1

Open itoleck opened 2 years ago

itoleck commented 2 years ago

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.

Alt text

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

Alt text

Alt text

  1. Load symbols

Alt text

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

Alt text

  1. 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)

Alt text

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

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

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

  4. 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.

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

Alt text

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.

Alt text

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

Alt text

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

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

Alt text

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 commented 2 years ago

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.