Windows 10 Pro - DPC Latency Issues

davros303 · Sep 18, 2019

Hello Sysnative - my DPC latency issues have dogged me since upgrading my audio workstation system from Win 7 Pro to Win 10 Pro along with a complete new hardware build. On the old setup, I had the system tuned for super low latency, less than 100 microseconds and always steady. The new system spikes at 1000 microseconds constantly, and then every 10 to 15 minutes will have a massive spike which causes a short freeze and audio dropout. I've also noticed a few applications running a lot slower in the new environment vs the old. Here's all the details:

System Manufacturer? Custom build
Laptop or Desktop? Desktop
Exact model number (if laptop, check label on bottom) N/A
OS ? (Windows 10, 8.1, 8, 7, Vista) Windows 10 Pro
x86 (32bit) or x64 (64bit)? x64
Service pack? No
What was original installed OS on system? Formerly Win 7 Pro, however upgrade has come with an entirely new hardware rig so this is effectively a fresh install.
Is the OS an OEM version (came pre-installed on system) or full retail version (YOU purchased it from retailer)? retail
Age of system? (hardware) 18 months
Age of OS installation? 4 months
Have you re-installed the OS? No
CPU - AMD Ryzen Threadripper 1950X 16-Core Processor, 3400 Mhz, 16 Core(s), 32 Logical Processor(s)
RAM (brand, EXACT model, what slots are you using?) G.Skill Trident DDR4 F4-3200C16-8GTZSK 2 x 8 gig slots, slot 2 and slot 6 (as recommended in the mobo manual)
Video Card - NVIDIA GeForce GTX 950
MotherBoard - (if NOT a laptop) Asus Rog Strix Gaming X399
Power Supply - brand & wattage (if laptop, skip this one) Corsair CX650M bronze
Is driver verifier enabled or disabled? Not sure
What security software are you using? (Firewall, antivirus, antimalware, antispyware, and so forth) Bitdefender free edition (have tested with antivirus disabled)
Are you using proxy, vpn, ipfilters or similar software? Yes a VPN (though have tested with it disabled)
Are you using Disk Image tools? (like daemon tools, alcohol 52% or 120%, virtual CloneDrive, roxio software) Yes, Virtual Clone Drive
Are you currently under/overclocking? Are there overclocking software installed on your system? I am not overclocking or gaming on this system. There is overclocking software / CPU mgmt installed but not being used.

I have a LatencyMon snapshot captured just after a massive DPC latency spike which resulted in audio dropout (attached), and a dropbox link to a trace file I recorded. I have WPA installed, but aside from seeing what LatencyMon tells me, I don't know how to use it to diagnose which programs and processes are behind certain drivers running hot or spiking. I would be eternally grateful for some help here...

trace01.rar

x BlueRobot · Sep 18, 2019

I've created a new thread for you and changed the thread title from the default title it gives when moving a post into it's own thread. This makes it easier for people to identify a new problem thread and allows us to help you more effectively.

To check if Driver Verifier is running, then please open command prompt and entering the following:

Code:

verifier /query

If Driver Verifier isn't running, you should get a message saying: "No drivers are currently verified".

I'm currently at work at the moment, so won't be able to check the logs for you. Hopefully someone will be able to pick up this thread in the meantime.

davros303 · Sep 18, 2019

Thanks BlueRobot - I ran that string and "No drivers are currently verified" was the return message.

cwsink · Sep 18, 2019

Hi davros303,

I'm not sure why but the LatencyMon report you attached is showing Windows 8 as the operating system. Are you perhaps using an outdated version of LatencyMon?

The trace looks really good except for 3 DPC fragments running for a little over a millisecond and a few almost at a millisecond. Those aren't really long enough to cause noticeable audio/video glitches even if they happened on core 0, which they didn't. They were spread out on quite a few other cores but never core 0 which is the core normally used for audio/video playback. The function called was ExpGetPoolTagInfoTarget for all of those longer running DPCs. I don't often see that DPC function taking long in traces. The only one I can recall is where OP ended up reinstalling Windows on a new SSD after which the latency problems went away. Can you clarify whether or not you did an actual full clean install of Windows 10? Did you upgrade the hardware and try to use the Windows installation that was optimized for the old hardware? Also, did you actually experience latency problems while capturing the trace?

davros303 · Sep 18, 2019

Let me run another trace over one of the big spikes, that trace file was recorded a little while ago and not taken at the same time as the LatencyMon report. You are correct that this install for Win10 was originally on an SSD, and I used Macrium Reflect to lift and shift it onto a brand new NvMe Samsung Evo drive. Cannot explain why LatencyMon is seeing Win8, I'll check the version I've got when I get home and let you know.

For an effective DAW / audio production environment, I'm really targeting baseline latency of 200 μs or less. Even though LatencyMon shows "green" up to 1000, even 1200 μs - in practice this latency is way too high and comprises a lot of the processing headroom I was hoping to achieve by going from a Phenom X6 system to a Threadripper 1950x.

In any case, huge thanks for your eyes on this cwsink!

davros303 · Sep 19, 2019

OK, looks like I was using a very old version of LatencyMon 4.02 - I've just installed 6.71 and baseline latency is much lower. Stats screen is recognising OS as Win 10. Bizarrely I cannot get storport to spike during tonight's session.

x BlueRobot · Sep 19, 2019

What latency statistics is it providing?

Do you know if you were running less applications this time?

davros303 · Sep 21, 2019

OK, storport spiked again during today's session. The LatencyMon report is below, now I'm going to record another trace and post it here

_________________________________________________________________________________________________________
CONCLUSION
_________________________________________________________________________________________________________
Your system appears to be having trouble handling real-time audio and other tasks. You are likely to experience buffer underruns appearing as drop outs, clicks or pops. One or more DPC routines that belong to a driver running in your system appear to be executing for too long. One problem may be related to power management, disable CPU throttling settings in Control Panel and BIOS setup. Check for BIOS updates.
LatencyMon has been analyzing your system for 0:07:46 (h:mm:ss) on all processors.

_________________________________________________________________________________________________________
SYSTEM INFORMATION
_________________________________________________________________________________________________________
Computer name: DESKTOP-JUQID0H
OS version: Windows 10 , 10.0, version 1903, build: 18362 (x64)
Hardware: ASUSTeK COMPUTER INC., ROG STRIX X399-E GAMING
CPU: AuthenticAMD AMD Ryzen Threadripper 1950X 16-Core Processor
Logical processors: 32
Processor groups: 1
RAM: 16258 MB total

_________________________________________________________________________________________________________
CPU SPEED
_________________________________________________________________________________________________________
Reported CPU speed: 3394 MHz

Note: reported execution times may be calculated based on a fixed reported CPU speed. Disable variable speed settings like Intel Speed Step and AMD Cool N Quiet in the BIOS setup for more accurate results.

WARNING: the CPU speed that was measured is only a fraction of the CPU speed reported. Your CPUs may be throttled back due to variable speed settings and thermal issues. It is suggested that you run a utility which reports your actual CPU frequency and temperature.

_________________________________________________________________________________________________________
MEASURED INTERRUPT TO USER PROCESS LATENCIES
_________________________________________________________________________________________________________
The interrupt to process latency reflects the measured interval that a usermode process needed to respond to a hardware request from the moment the interrupt service routine started execution. This includes the scheduling and execution of a DPC routine, the signaling of an event and the waking up of a usermode thread from an idle wait state in response to that event.

Highest measured interrupt to process latency (µs): 100888.80
Average measured interrupt to process latency (µs): 5.309528

Highest measured interrupt to DPC latency (µs): 100877.40
Average measured interrupt to DPC latency (µs): 2.287687

_________________________________________________________________________________________________________
REPORTED ISRs
_________________________________________________________________________________________________________
Interrupt service routines are routines installed by the OS and device drivers that execute in response to a hardware interrupt signal.

Highest ISR routine execution time (µs): 529.294048
Driver with highest ISR routine execution time: Wdf01000.sys - Kernel Mode Driver Framework Runtime, Microsoft Corporation

Highest reported total ISR routine time (%): 0.015054
Driver with highest ISR total time: Wdf01000.sys - Kernel Mode Driver Framework Runtime, Microsoft Corporation

Total time spent in ISRs (%) 0.016584

ISR count (execution time <250 µs): 480497
ISR count (execution time 250-500 µs): 0
ISR count (execution time 500-999 µs): 205
ISR count (execution time 1000-1999 µs): 0
ISR count (execution time 2000-3999 µs): 0
ISR count (execution time >=4000 µs): 0

_________________________________________________________________________________________________________
REPORTED DPCs
_________________________________________________________________________________________________________
DPC routines are part of the interrupt servicing dispatch mechanism and disable the possibility for a process to utilize the CPU while it is interrupted until the DPC has finished execution.

Highest DPC routine execution time (µs): 100892.826164
Driver with highest DPC routine execution time: storport.sys - Microsoft Storage Port Driver, Microsoft Corporation

Highest reported total DPC routine time (%): 0.101085
Driver with highest DPC total execution time: Wdf01000.sys - Kernel Mode Driver Framework Runtime, Microsoft Corporation

Total time spent in DPCs (%) 0.121556

DPC count (execution time <250 µs): 884407
DPC count (execution time 250-500 µs): 0
DPC count (execution time 500-999 µs): 2850
DPC count (execution time 1000-1999 µs): 0
DPC count (execution time 2000-3999 µs): 0
DPC count (execution time >=4000 µs): 0

_________________________________________________________________________________________________________
REPORTED HARD PAGEFAULTS
_________________________________________________________________________________________________________
Hard pagefaults are events that get triggered by making use of virtual memory that is not resident in RAM but backed by a memory mapped file on disk. The process of resolving the hard pagefault requires reading in the memory from disk while the process is interrupted and blocked from execution.

NOTE: some processes were hit by hard pagefaults. If these were programs producing audio, they are likely to interrupt the audio stream resulting in dropouts, clicks and pops. Check the Processes tab to see which programs were hit.

Process with highest pagefault count: msiexec.exe

Total number of hard pagefaults 19320
Hard pagefault count of hardest hit process: 6990
Number of processes hit: 33

_________________________________________________________________________________________________________
PER CPU DATA
_________________________________________________________________________________________________________
CPU 0 Interrupt cycle time (s): 30.168549
CPU 0 ISR highest execution time (µs): 0.0
CPU 0 ISR total execution time (s): 0.0
CPU 0 ISR count: 0
CPU 0 DPC highest execution time (µs): 100892.826164
CPU 0 DPC total execution time (s): 1.228672
CPU 0 DPC count: 370091
_________________________________________________________________________________________________________
CPU 1 Interrupt cycle time (s): 24.721034
CPU 1 ISR highest execution time (µs): 0.0
CPU 1 ISR total execution time (s): 0.0
CPU 1 ISR count: 0
CPU 1 DPC highest execution time (µs): 12.742487
CPU 1 DPC total execution time (s): 0.000278
CPU 1 DPC count: 63
_________________________________________________________________________________________________________
CPU 2 Interrupt cycle time (s): 11.496605
CPU 2 ISR highest execution time (µs): 0.0
CPU 2 ISR total execution time (s): 0.0
CPU 2 ISR count: 0
CPU 2 DPC highest execution time (µs): 397.371243
CPU 2 DPC total execution time (s): 0.015622
CPU 2 DPC count: 3217
_________________________________________________________________________________________________________
CPU 3 Interrupt cycle time (s): 18.436720
CPU 3 ISR highest execution time (µs): 0.0
CPU 3 ISR total execution time (s): 0.0
CPU 3 ISR count: 0
CPU 3 DPC highest execution time (µs): 17.260460
CPU 3 DPC total execution time (s): 0.000958
CPU 3 DPC count: 232
_________________________________________________________________________________________________________
CPU 4 Interrupt cycle time (s): 10.607399
CPU 4 ISR highest execution time (µs): 0.0
CPU 4 ISR total execution time (s): 0.0
CPU 4 ISR count: 0
CPU 4 DPC highest execution time (µs): 312.741897
CPU 4 DPC total execution time (s): 0.010291
CPU 4 DPC count: 2302
_________________________________________________________________________________________________________
CPU 5 Interrupt cycle time (s): 17.069488
CPU 5 ISR highest execution time (µs): 0.0
CPU 5 ISR total execution time (s): 0.0
CPU 5 ISR count: 0
CPU 5 DPC highest execution time (µs): 24.002357
CPU 5 DPC total execution time (s): 0.000343
CPU 5 DPC count: 64
_________________________________________________________________________________________________________
CPU 6 Interrupt cycle time (s): 10.334575
CPU 6 ISR highest execution time (µs): 0.0
CPU 6 ISR total execution time (s): 0.0
CPU 6 ISR count: 0
CPU 6 DPC highest execution time (µs): 460.352387
CPU 6 DPC total execution time (s): 0.034361
CPU 6 DPC count: 6408
_________________________________________________________________________________________________________
CPU 7 Interrupt cycle time (s): 15.952531
CPU 7 ISR highest execution time (µs): 0.0
CPU 7 ISR total execution time (s): 0.0
CPU 7 ISR count: 0
CPU 7 DPC highest execution time (µs): 37.315852
CPU 7 DPC total execution time (s): 0.000208
CPU 7 DPC count: 29
_________________________________________________________________________________________________________
CPU 8 Interrupt cycle time (s): 13.715242
CPU 8 ISR highest execution time (µs): 0.0
CPU 8 ISR total execution time (s): 0.0
CPU 8 ISR count: 0
CPU 8 DPC highest execution time (µs): 364.693577
CPU 8 DPC total execution time (s): 0.007511
CPU 8 DPC count: 1388
_________________________________________________________________________________________________________
CPU 9 Interrupt cycle time (s): 13.673804
CPU 9 ISR highest execution time (µs): 0.0
CPU 9 ISR total execution time (s): 0.0
CPU 9 ISR count: 0
CPU 9 DPC highest execution time (µs): 193.391279
CPU 9 DPC total execution time (s): 0.000750
CPU 9 DPC count: 106
_________________________________________________________________________________________________________
CPU 10 Interrupt cycle time (s): 14.230566
CPU 10 ISR highest execution time (µs): 0.0
CPU 10 ISR total execution time (s): 0.0
CPU 10 ISR count: 0
CPU 10 DPC highest execution time (µs): 485.476724
CPU 10 DPC total execution time (s): 0.053103
CPU 10 DPC count: 6355
_________________________________________________________________________________________________________
CPU 11 Interrupt cycle time (s): 14.441703
CPU 11 ISR highest execution time (µs): 0.0
CPU 11 ISR total execution time (s): 0.0
CPU 11 ISR count: 0
CPU 11 DPC highest execution time (µs): 60.887448
CPU 11 DPC total execution time (s): 0.000718
CPU 11 DPC count: 85
_________________________________________________________________________________________________________
CPU 12 Interrupt cycle time (s): 14.292068
CPU 12 ISR highest execution time (µs): 0.0
CPU 12 ISR total execution time (s): 0.0
CPU 12 ISR count: 0
CPU 12 DPC highest execution time (µs): 431.070713
CPU 12 DPC total execution time (s): 0.015468
CPU 12 DPC count: 2492
_________________________________________________________________________________________________________
CPU 13 Interrupt cycle time (s): 14.053151
CPU 13 ISR highest execution time (µs): 0.0
CPU 13 ISR total execution time (s): 0.0
CPU 13 ISR count: 0
CPU 13 DPC highest execution time (µs): 243.429582
CPU 13 DPC total execution time (s): 0.000575
CPU 13 DPC count: 75
_________________________________________________________________________________________________________
CPU 14 Interrupt cycle time (s): 13.934411
CPU 14 ISR highest execution time (µs): 0.0
CPU 14 ISR total execution time (s): 0.0
CPU 14 ISR count: 0
CPU 14 DPC highest execution time (µs): 457.106659
CPU 14 DPC total execution time (s): 0.07960
CPU 14 DPC count: 9516
_________________________________________________________________________________________________________
CPU 15 Interrupt cycle time (s): 13.782894
CPU 15 ISR highest execution time (µs): 0.0
CPU 15 ISR total execution time (s): 0.0
CPU 15 ISR count: 0
CPU 15 DPC highest execution time (µs): 58.763701
CPU 15 DPC total execution time (s): 0.000456
CPU 15 DPC count: 49
_________________________________________________________________________________________________________
CPU 16 Interrupt cycle time (s): 9.572110
CPU 16 ISR highest execution time (µs): 0.0
CPU 16 ISR total execution time (s): 0.0
CPU 16 ISR count: 0
CPU 16 DPC highest execution time (µs): 293.558044
CPU 16 DPC total execution time (s): 0.032254
CPU 16 DPC count: 8527
_________________________________________________________________________________________________________
CPU 17 Interrupt cycle time (s): 9.021504
CPU 17 ISR highest execution time (µs): 0.0
CPU 17 ISR total execution time (s): 0.0
CPU 17 ISR count: 0
CPU 17 DPC highest execution time (µs): 14.826164
CPU 17 DPC total execution time (s): 0.000454
CPU 17 DPC count: 151
_________________________________________________________________________________________________________
CPU 18 Interrupt cycle time (s): 8.933250
CPU 18 ISR highest execution time (µs): 0.0
CPU 18 ISR total execution time (s): 0.0
CPU 18 ISR count: 0
CPU 18 DPC highest execution time (µs): 389.847967
CPU 18 DPC total execution time (s): 0.015908
CPU 18 DPC count: 3308
_________________________________________________________________________________________________________
CPU 19 Interrupt cycle time (s): 8.758429
CPU 19 ISR highest execution time (µs): 0.0
CPU 19 ISR total execution time (s): 0.0
CPU 19 ISR count: 0
CPU 19 DPC highest execution time (µs): 75.553329
CPU 19 DPC total execution time (s): 0.000699
CPU 19 DPC count: 121
_________________________________________________________________________________________________________
CPU 20 Interrupt cycle time (s): 12.809438
CPU 20 ISR highest execution time (µs): 0.0
CPU 20 ISR total execution time (s): 0.0
CPU 20 ISR count: 0
CPU 20 DPC highest execution time (µs): 520.378315
CPU 20 DPC total execution time (s): 0.063186
CPU 20 DPC count: 5581
_________________________________________________________________________________________________________
CPU 21 Interrupt cycle time (s): 11.928096
CPU 21 ISR highest execution time (µs): 0.0
CPU 21 ISR total execution time (s): 0.0
CPU 21 ISR count: 0
CPU 21 DPC highest execution time (µs): 357.310548
CPU 21 DPC total execution time (s): 0.003916
CPU 21 DPC count: 227
_________________________________________________________________________________________________________
CPU 22 Interrupt cycle time (s): 9.399285
CPU 22 ISR highest execution time (µs): 0.0
CPU 22 ISR total execution time (s): 0.0
CPU 22 ISR count: 0
CPU 22 DPC highest execution time (µs): 303.896288
CPU 22 DPC total execution time (s): 0.047487
CPU 22 DPC count: 10259
_________________________________________________________________________________________________________
CPU 23 Interrupt cycle time (s): 9.585675
CPU 23 ISR highest execution time (µs): 0.0
CPU 23 ISR total execution time (s): 0.0
CPU 23 ISR count: 0
CPU 23 DPC highest execution time (µs): 240.885091
CPU 23 DPC total execution time (s): 0.015105
CPU 23 DPC count: 3716
_________________________________________________________________________________________________________
CPU 24 Interrupt cycle time (s): 9.579070
CPU 24 ISR highest execution time (µs): 0.0
CPU 24 ISR total execution time (s): 0.0
CPU 24 ISR count: 0
CPU 24 DPC highest execution time (µs): 281.987625
CPU 24 DPC total execution time (s): 0.007604
CPU 24 DPC count: 1579
_________________________________________________________________________________________________________
CPU 25 Interrupt cycle time (s): 10.010152
CPU 25 ISR highest execution time (µs): 5.249263
CPU 25 ISR total execution time (s): 0.000331
CPU 25 ISR count: 277
CPU 25 DPC highest execution time (µs): 230.396582
CPU 25 DPC total execution time (s): 0.010701
CPU 25 DPC count: 338
_________________________________________________________________________________________________________
CPU 26 Interrupt cycle time (s): 9.996050
CPU 26 ISR highest execution time (µs): 0.0
CPU 26 ISR total execution time (s): 0.0
CPU 26 ISR count: 0
CPU 26 DPC highest execution time (µs): 358.332351
CPU 26 DPC total execution time (s): 0.010592
CPU 26 DPC count: 1669
_________________________________________________________________________________________________________
CPU 27 Interrupt cycle time (s): 13.982836
CPU 27 ISR highest execution time (µs): 326.155569
CPU 27 ISR total execution time (s): 0.228314
CPU 27 ISR count: 9092
CPU 27 DPC highest execution time (µs): 556.602239
CPU 27 DPC total execution time (s): 0.282886
CPU 27 DPC count: 17118
_________________________________________________________________________________________________________
CPU 28 Interrupt cycle time (s): 12.872607
CPU 28 ISR highest execution time (µs): 178.444903
CPU 28 ISR total execution time (s): 0.003877
CPU 28 ISR count: 3349
CPU 28 DPC highest execution time (µs): 524.114909
CPU 28 DPC total execution time (s): 0.075504
CPU 28 DPC count: 4213
_________________________________________________________________________________________________________
CPU 29 Interrupt cycle time (s): 11.754790
CPU 29 ISR highest execution time (µs): 0.0
CPU 29 ISR total execution time (s): 0.0
CPU 29 ISR count: 0
CPU 29 DPC highest execution time (µs): 194.663524
CPU 29 DPC total execution time (s): 0.026791
CPU 29 DPC count: 8079
_________________________________________________________________________________________________________
CPU 30 Interrupt cycle time (s): 18.212881
CPU 30 ISR highest execution time (µs): 0.0
CPU 30 ISR total execution time (s): 0.0
CPU 30 ISR count: 0
CPU 30 DPC highest execution time (µs): 232.890984
CPU 30 DPC total execution time (s): 0.008415
CPU 30 DPC count: 839
_________________________________________________________________________________________________________
CPU 31 Interrupt cycle time (s): 49.792958
CPU 31 ISR highest execution time (µs): 529.294048
CPU 31 ISR total execution time (s): 2.240720
CPU 31 ISR count: 467984
CPU 31 DPC highest execution time (µs): 722.905716
CPU 31 DPC total execution time (s): 16.077195
CPU 31 DPC count: 419062
_________________________________________________________________________________________________________

davros303 · Sep 21, 2019

Here's a brand new trace file with another big storport spike

DESKTOP-JUQID0H.09-21-2019.15-20-33.rar

When I look at this file in WPA, under the Generic Events graph, I can see "Power: Device Notify" and then "System (4)" exactly correlates with the timing of the big storport spike. Cannot tell whether this is related to any programs / processes, but scrolling down the time scale, each event line is bouncing between different CPUs.

cwsink · Sep 22, 2019

I know you tried disabling Bitdefender but please try completely uninstalling it and just using Windows Defender for security; at least while troubleshooting. Drivers from the program would still be loading and part of the disk I/O stack whether it was enabled or not.

Everything looks good until the end of the trace where I see quite a few long running storport DPCs. The DPC routine being called is RaidpAdapterTimerDpcRoutine which is running for as long as 101+ milliseconds without interruption on core 0. DPCs take over the thread running on whatever core they are assigned to and have a higher priority than user processes. Once a DPC takes over only higher priority DPCs or interrupts can preempt what it's doing. I don't see anything actually preempting the long running DPCs - they are simply taking that long to run for some reason. There have been threads in the recent past where Bitdefender was causing storport problems. I don't recall if we ever tried disabling Bitdefender in those threads but I doubt it. I normally ask people to uninstall any 3rd party antivirus products they are using while troubleshooting.

Please test the system after addressing the above and see if the problems continue.

davros303 · Sep 25, 2019

OK, completely uninstalled Bitdefender and also disabled ethernet and no good. Instead of storport spiking, now it's ntoskrnl jumping into the red. Here's the report from latencymon

_________________________________________________________________________________________________________
CONCLUSION
_________________________________________________________________________________________________________
Your system appears to be having trouble handling real-time audio and other tasks. You are likely to experience buffer underruns appearing as drop outs, clicks or pops. One or more DPC routines that belong to a driver running in your system appear to be executing for too long. One problem may be related to power management, disable CPU throttling settings in Control Panel and BIOS setup. Check for BIOS updates.
LatencyMon has been analyzing your system for 0:02:42 (h:mm:ss) on all processors.

_________________________________________________________________________________________________________
SYSTEM INFORMATION
_________________________________________________________________________________________________________
Computer name: DESKTOP-JUQID0H
OS version: Windows 10 , 10.0, version 1903, build: 18362 (x64)
Hardware: ASUSTeK COMPUTER INC., ROG STRIX X399-E GAMING
CPU: AuthenticAMD AMD Ryzen Threadripper 1950X 16-Core Processor
Logical processors: 32
Processor groups: 1
RAM: 16258 MB total

_________________________________________________________________________________________________________
CPU SPEED
_________________________________________________________________________________________________________
Reported CPU speed: 3394 MHz

Note: reported execution times may be calculated based on a fixed reported CPU speed. Disable variable speed settings like Intel Speed Step and AMD Cool N Quiet in the BIOS setup for more accurate results.

WARNING: the CPU speed that was measured is only a fraction of the CPU speed reported. Your CPUs may be throttled back due to variable speed settings and thermal issues. It is suggested that you run a utility which reports your actual CPU frequency and temperature.

_________________________________________________________________________________________________________
MEASURED INTERRUPT TO USER PROCESS LATENCIES
_________________________________________________________________________________________________________
The interrupt to process latency reflects the measured interval that a usermode process needed to respond to a hardware request from the moment the interrupt service routine started execution. This includes the scheduling and execution of a DPC routine, the signaling of an event and the waking up of a usermode thread from an idle wait state in response to that event.

Highest measured interrupt to process latency (µs): 2277.80
Average measured interrupt to process latency (µs): 5.575969

Highest measured interrupt to DPC latency (µs): 2275.0
Average measured interrupt to DPC latency (µs): 2.572754

_________________________________________________________________________________________________________
REPORTED ISRs
_________________________________________________________________________________________________________
Interrupt service routines are routines installed by the OS and device drivers that execute in response to a hardware interrupt signal.

Highest ISR routine execution time (µs): 364.523276
Driver with highest ISR routine execution time: Wdf01000.sys - Kernel Mode Driver Framework Runtime, Microsoft Corporation

Highest reported total ISR routine time (%): 0.016398
Driver with highest ISR total time: Wdf01000.sys - Kernel Mode Driver Framework Runtime, Microsoft Corporation

Total time spent in ISRs (%) 0.016767

ISR count (execution time <250 µs): 191384
ISR count (execution time 250-500 µs): 0
ISR count (execution time 500-999 µs): 19
ISR count (execution time 1000-1999 µs): 0
ISR count (execution time 2000-3999 µs): 0
ISR count (execution time >=4000 µs): 0

_________________________________________________________________________________________________________
REPORTED DPCs
_________________________________________________________________________________________________________
DPC routines are part of the interrupt servicing dispatch mechanism and disable the possibility for a process to utilize the CPU while it is interrupted until the DPC has finished execution.

Highest DPC routine execution time (µs): 2536.315852
Driver with highest DPC routine execution time: ntoskrnl.exe - NT Kernel & System, Microsoft Corporation

Highest reported total DPC routine time (%): 0.103866
Driver with highest DPC total execution time: Wdf01000.sys - Kernel Mode Driver Framework Runtime, Microsoft Corporation

Total time spent in DPCs (%) 0.109734

DPC count (execution time <250 µs): 119799
DPC count (execution time 250-500 µs): 0
DPC count (execution time 500-999 µs): 508
DPC count (execution time 1000-1999 µs): 0
DPC count (execution time 2000-3999 µs): 1
DPC count (execution time >=4000 µs): 0

_________________________________________________________________________________________________________
REPORTED HARD PAGEFAULTS
_________________________________________________________________________________________________________
Hard pagefaults are events that get triggered by making use of virtual memory that is not resident in RAM but backed by a memory mapped file on disk. The process of resolving the hard pagefault requires reading in the memory from disk while the process is interrupted and blocked from execution.

NOTE: some processes were hit by hard pagefaults. If these were programs producing audio, they are likely to interrupt the audio stream resulting in dropouts, clicks and pops. Check the Processes tab to see which programs were hit.

Process with highest pagefault count: svchost.exe

Total number of hard pagefaults 1158
Hard pagefault count of hardest hit process: 284
Number of processes hit: 14

_________________________________________________________________________________________________________
PER CPU DATA
_________________________________________________________________________________________________________
CPU 0 Interrupt cycle time (s): 2.628308
CPU 0 ISR highest execution time (µs): 0.0
CPU 0 ISR total execution time (s): 0.0
CPU 0 ISR count: 0
CPU 0 DPC highest execution time (µs): 2536.315852
CPU 0 DPC total execution time (s): 0.141480
CPU 0 DPC count: 5944
_________________________________________________________________________________________________________
CPU 1 Interrupt cycle time (s): 2.219795
CPU 1 ISR highest execution time (µs): 0.0
CPU 1 ISR total execution time (s): 0.0
CPU 1 ISR count: 0
CPU 1 DPC highest execution time (µs): 0.0
CPU 1 DPC total execution time (s): 0.0
CPU 1 DPC count: 0
_________________________________________________________________________________________________________
CPU 2 Interrupt cycle time (s): 0.635148
CPU 2 ISR highest execution time (µs): 0.0
CPU 2 ISR total execution time (s): 0.0
CPU 2 ISR count: 0
CPU 2 DPC highest execution time (µs): 363.210961
CPU 2 DPC total execution time (s): 0.002401
CPU 2 DPC count: 177
_________________________________________________________________________________________________________
CPU 3 Interrupt cycle time (s): 1.276254
CPU 3 ISR highest execution time (µs): 0.0
CPU 3 ISR total execution time (s): 0.0
CPU 3 ISR count: 0
CPU 3 DPC highest execution time (µs): 7.102534
CPU 3 DPC total execution time (s): 0.000095
CPU 3 DPC count: 30
_________________________________________________________________________________________________________
CPU 4 Interrupt cycle time (s): 0.798371
CPU 4 ISR highest execution time (µs): 0.0
CPU 4 ISR total execution time (s): 0.0
CPU 4 ISR count: 0
CPU 4 DPC highest execution time (µs): 329.781968
CPU 4 DPC total execution time (s): 0.004521
CPU 4 DPC count: 392
_________________________________________________________________________________________________________
CPU 5 Interrupt cycle time (s): 1.300130
CPU 5 ISR highest execution time (µs): 0.0
CPU 5 ISR total execution time (s): 0.0
CPU 5 ISR count: 0
CPU 5 DPC highest execution time (µs): 359.694755
CPU 5 DPC total execution time (s): 0.000410
CPU 5 DPC count: 10
_________________________________________________________________________________________________________
CPU 6 Interrupt cycle time (s): 0.646958
CPU 6 ISR highest execution time (µs): 0.0
CPU 6 ISR total execution time (s): 0.0
CPU 6 ISR count: 0
CPU 6 DPC highest execution time (µs): 44.648792
CPU 6 DPC total execution time (s): 0.000248
CPU 6 DPC count: 57
_________________________________________________________________________________________________________
CPU 7 Interrupt cycle time (s): 1.123813
CPU 7 ISR highest execution time (µs): 0.0
CPU 7 ISR total execution time (s): 0.0
CPU 7 ISR count: 0
CPU 7 DPC highest execution time (µs): 7.152622
CPU 7 DPC total execution time (s): 0.000007
CPU 7 DPC count: 1
_________________________________________________________________________________________________________
CPU 8 Interrupt cycle time (s): 0.865305
CPU 8 ISR highest execution time (µs): 0.0
CPU 8 ISR total execution time (s): 0.0
CPU 8 ISR count: 0
CPU 8 DPC highest execution time (µs): 2.053624
CPU 8 DPC total execution time (s): 0.000002
CPU 8 DPC count: 1
_________________________________________________________________________________________________________
CPU 9 Interrupt cycle time (s): 0.861280
CPU 9 ISR highest execution time (µs): 0.0
CPU 9 ISR total execution time (s): 0.0
CPU 9 ISR count: 0
CPU 9 DPC highest execution time (µs): 315.136123
CPU 9 DPC total execution time (s): 0.000823
CPU 9 DPC count: 81
_________________________________________________________________________________________________________
CPU 10 Interrupt cycle time (s): 0.878253
CPU 10 ISR highest execution time (µs): 0.0
CPU 10 ISR total execution time (s): 0.0
CPU 10 ISR count: 0
CPU 10 DPC highest execution time (µs): 172.654685
CPU 10 DPC total execution time (s): 0.001085
CPU 10 DPC count: 293
_________________________________________________________________________________________________________
CPU 11 Interrupt cycle time (s): 0.862644
CPU 11 ISR highest execution time (µs): 0.0
CPU 11 ISR total execution time (s): 0.0
CPU 11 ISR count: 0
CPU 11 DPC highest execution time (µs): 333.278138
CPU 11 DPC total execution time (s): 0.000987
CPU 11 DPC count: 56
_________________________________________________________________________________________________________
CPU 12 Interrupt cycle time (s): 0.860869
CPU 12 ISR highest execution time (µs): 0.0
CPU 12 ISR total execution time (s): 0.0
CPU 12 ISR count: 0
CPU 12 DPC highest execution time (µs): 13.283441
CPU 12 DPC total execution time (s): 0.000150
CPU 12 DPC count: 45
_________________________________________________________________________________________________________
CPU 13 Interrupt cycle time (s): 0.847059
CPU 13 ISR highest execution time (µs): 0.0
CPU 13 ISR total execution time (s): 0.0
CPU 13 ISR count: 0
CPU 13 DPC highest execution time (µs): 247.106070
CPU 13 DPC total execution time (s): 0.000290
CPU 13 DPC count: 9
_________________________________________________________________________________________________________
CPU 14 Interrupt cycle time (s): 0.849138
CPU 14 ISR highest execution time (µs): 0.0
CPU 14 ISR total execution time (s): 0.0
CPU 14 ISR count: 0
CPU 14 DPC highest execution time (µs): 10.077784
CPU 14 DPC total execution time (s): 0.000049
CPU 14 DPC count: 9
_________________________________________________________________________________________________________
CPU 15 Interrupt cycle time (s): 0.858738
CPU 15 ISR highest execution time (µs): 0.0
CPU 15 ISR total execution time (s): 0.0
CPU 15 ISR count: 0
CPU 15 DPC highest execution time (µs): 4.367708
CPU 15 DPC total execution time (s): 0.000011
CPU 15 DPC count: 4
_________________________________________________________________________________________________________
CPU 16 Interrupt cycle time (s): 0.393912
CPU 16 ISR highest execution time (µs): 0.0
CPU 16 ISR total execution time (s): 0.0
CPU 16 ISR count: 0
CPU 16 DPC highest execution time (µs): 6.411314
CPU 16 DPC total execution time (s): 0.000006
CPU 16 DPC count: 1
_________________________________________________________________________________________________________
CPU 17 Interrupt cycle time (s): 0.390170
CPU 17 ISR highest execution time (µs): 0.0
CPU 17 ISR total execution time (s): 0.0
CPU 17 ISR count: 0
CPU 17 DPC highest execution time (µs): 7.633471
CPU 17 DPC total execution time (s): 0.000032
CPU 17 DPC count: 7
_________________________________________________________________________________________________________
CPU 18 Interrupt cycle time (s): 0.420893
CPU 18 ISR highest execution time (µs): 0.0
CPU 18 ISR total execution time (s): 0.0
CPU 18 ISR count: 0
CPU 18 DPC highest execution time (µs): 15.256924
CPU 18 DPC total execution time (s): 0.000338
CPU 18 DPC count: 78
_________________________________________________________________________________________________________
CPU 19 Interrupt cycle time (s): 0.421828
CPU 19 ISR highest execution time (µs): 0.0
CPU 19 ISR total execution time (s): 0.0
CPU 19 ISR count: 0
CPU 19 DPC highest execution time (µs): 226.970536
CPU 19 DPC total execution time (s): 0.001063
CPU 19 DPC count: 218
_________________________________________________________________________________________________________
CPU 20 Interrupt cycle time (s): 0.378948
CPU 20 ISR highest execution time (µs): 0.0
CPU 20 ISR total execution time (s): 0.0
CPU 20 ISR count: 0
CPU 20 DPC highest execution time (µs): 388.615793
CPU 20 DPC total execution time (s): 0.002948
CPU 20 DPC count: 95
_________________________________________________________________________________________________________
CPU 21 Interrupt cycle time (s): 0.380143
CPU 21 ISR highest execution time (µs): 0.0
CPU 21 ISR total execution time (s): 0.0
CPU 21 ISR count: 0
CPU 21 DPC highest execution time (µs): 0.0
CPU 21 DPC total execution time (s): 0.0
CPU 21 DPC count: 0
_________________________________________________________________________________________________________
CPU 22 Interrupt cycle time (s): 0.36570
CPU 22 ISR highest execution time (µs): 0.0
CPU 22 ISR total execution time (s): 0.0
CPU 22 ISR count: 0
CPU 22 DPC highest execution time (µs): 11.269888
CPU 22 DPC total execution time (s): 0.000135
CPU 22 DPC count: 40
_________________________________________________________________________________________________________
CPU 23 Interrupt cycle time (s): 0.358131
CPU 23 ISR highest execution time (µs): 0.0
CPU 23 ISR total execution time (s): 0.0
CPU 23 ISR count: 0
CPU 23 DPC highest execution time (µs): 1.061874
CPU 23 DPC total execution time (s): 0.000001
CPU 23 DPC count: 1
_________________________________________________________________________________________________________
CPU 24 Interrupt cycle time (s): 0.527882
CPU 24 ISR highest execution time (µs): 0.0
CPU 24 ISR total execution time (s): 0.0
CPU 24 ISR count: 0
CPU 24 DPC highest execution time (µs): 36.995286
CPU 24 DPC total execution time (s): 0.000247
CPU 24 DPC count: 62
_________________________________________________________________________________________________________
CPU 25 Interrupt cycle time (s): 0.576867
CPU 25 ISR highest execution time (µs): 3.195639
CPU 25 ISR total execution time (s): 0.000563
CPU 25 ISR count: 505
CPU 25 DPC highest execution time (µs): 405.525633
CPU 25 DPC total execution time (s): 0.039085
CPU 25 DPC count: 938
_________________________________________________________________________________________________________
CPU 26 Interrupt cycle time (s): 0.511394
CPU 26 ISR highest execution time (µs): 0.0
CPU 26 ISR total execution time (s): 0.0
CPU 26 ISR count: 0
CPU 26 DPC highest execution time (µs): 543.378904
CPU 26 DPC total execution time (s): 0.015789
CPU 26 DPC count: 544
_________________________________________________________________________________________________________
CPU 27 Interrupt cycle time (s): 1.319810
CPU 27 ISR highest execution time (µs): 245.082499
CPU 27 ISR total execution time (s): 0.019142
CPU 27 ISR count: 571
CPU 27 DPC highest execution time (µs): 173.095463
CPU 27 DPC total execution time (s): 0.017533
CPU 27 DPC count: 1132
_________________________________________________________________________________________________________
CPU 28 Interrupt cycle time (s): 1.021486
CPU 28 ISR highest execution time (µs): 3.045374
CPU 28 ISR total execution time (s): 0.000784
CPU 28 ISR count: 750
CPU 28 DPC highest execution time (µs): 310.217443
CPU 28 DPC total execution time (s): 0.015756
CPU 28 DPC count: 821
_________________________________________________________________________________________________________
CPU 29 Interrupt cycle time (s): 0.674496
CPU 29 ISR highest execution time (µs): 0.0
CPU 29 ISR total execution time (s): 0.0
CPU 29 ISR count: 0
CPU 29 DPC highest execution time (µs): 161.454920
CPU 29 DPC total execution time (s): 0.000197
CPU 29 DPC count: 4
_________________________________________________________________________________________________________
CPU 30 Interrupt cycle time (s): 1.494605
CPU 30 ISR highest execution time (µs): 0.0
CPU 30 ISR total execution time (s): 0.0
CPU 30 ISR count: 0
CPU 30 DPC highest execution time (µs): 23.331173
CPU 30 DPC total execution time (s): 0.000159
CPU 30 DPC count: 53
_________________________________________________________________________________________________________
CPU 31 Interrupt cycle time (s): 11.016972
CPU 31 ISR highest execution time (µs): 364.523276
CPU 31 ISR total execution time (s): 0.849404
CPU 31 ISR count: 189577
CPU 31 DPC highest execution time (µs): 455.664113
CPU 31 DPC total execution time (s): 5.447155
CPU 31 DPC count: 109205
_________________________________________________________________________________________________________

cwsink · Sep 25, 2019

We’d need to look at a trace that captured such an occurrence rather than LatencyMon results to see what was called. Ntoskrnl.exe is the Windows kernel and there are many different DPC related functions it could be calling. The previous trace has such a ntoskrnl.exe function getting called which took a similar amount of time but I don’t know if that’s what you’re still experiencing. The routine being called is “ExpTimeRefreshDpcRoutine” and it took 2.5+ milliseconds in the previous trace. Hopefully it's a different function being called as I haven't been able to find documentation for ExpTimeRefreshDpcRoutine.

x BlueRobot · Sep 25, 2019

cwsink said:
Hopefully it's a different function being called as I haven't been able to find documentation for ExpTimeRefreshDpcRoutine.

I'm not sure what exactly it does, but it is likely something to do with timer objects. However, I did read one article mentioning that it potentially updates the system clock.

cwsink · Sep 25, 2019

x BlueRobot said:
I'm not sure what exactly it does, but it is likely something to do with timer objects. However, I did read one article mentioning that it potentially updates the system clock.

I'm not sure, either. A trace of my own system shows that routine being called infrequently and taking far less time to run than it did on davros303's computer. I went looking through past memory.dmp files of my system and !timer doesn't show any entries with the name ExpTimeRefreshDpcRoutine.

I can't find anything I'd consider definitive about it.

Search

Search

Windows 10 Pro - DPC Latency Issues

davros303

Member

Attachments

x BlueRobot

Administrator

davros303

Member

cwsink

Sysnative Staff, BSOD Kernel Dump Expert

davros303

Member

davros303

Member

x BlueRobot

Administrator

davros303

Member

davros303

Member

cwsink

Sysnative Staff, BSOD Kernel Dump Expert

davros303

Member

cwsink

Sysnative Staff, BSOD Kernel Dump Expert

x BlueRobot

Administrator

cwsink

Sysnative Staff, BSOD Kernel Dump Expert