How do I get to the root cause of high Deferred Procedure Calls?

Question

I've got a Dual core processor, and one of the two is constantly at 100%. Looking in ProcessExplorer shows me that it's Deferred Procedure Calls. Reading around the net seems to give me tons of different answers.

Is it possible to set out a couple of steps to trying to narrow down what the problem might be in my case?

Update 1: FWIW, the problem persists even in Safe Mode.

Update 2: I unplugged everything I could from the back of the PC, and that bought me 40% more free processor. I also downloaded the RATTV3 tool, but for some reason on my machine it's not giving me a driver-by-driver breakdown. There's a good description of both DPCLatencyChecker and RATTV3 here.

Update 3:, LatencyMon (see my answer below) tells me it's nvstor32.sys - which is NVidia's SATA driver - with times of about 5300 µs.

Update 4: The plot thickens, while pondering whether to try booting of a recovery disk (to see if it's really drivers, and not a hardware problem), I noticed that the DVD/CD player wasn't working (i.e. Not even opening the door when I press the button). Given that the machine just got back from having the motherboard replaced, I figured maybe they'd forgotten to plug it in. I opened the box, everything seemed ok, but I unplugged and plugged it back in again. On reboot, everything was fine - no more DPC (highest now 300µs)!

Update 5: On following day, problem back, CD player not working again, even the cursor in the password textbox is blinking in slow motion... Tried unplugging everything I could think of, and on second reboot, worked again (as at Update2). Next time I'm going to try unplugging the CD player completely...

Update 6: Just noticed System event log has nvstor32.sys giving an error saying Parity error detected in \Device\RaidPort0, then a warning about sending a reinitialisation. Now just have to work out which one RaidPort0 is... (note, I've got no RAID set-up, it's just a bog standard Acer). Oh, and my Avast setup apparently got killed when I did a System Rollback (or whatever it's called), because it won't start (RPC error), won't uninstall (setiface error has occurred).

Update 7: Finally got time to reboot with DVD unplugged. No more DPC problems! (lots of page faults though, but that's for later). Next step: work out if it's the cable, or the DVD player.

Update 8: Borrowed a SATA cable, booted with it, no problems. CD/DVD player works, no DPC problems with nvstor32.sys, no processors blocked. Happy end... almost: I've still got problems with Avast, apparent DPC problems with storport.sys at start up (maybe normal for USB?), and lots of hard page faults. But those will be the subject of other questions.

Postscript: I recently started having the same problem, and using the same method, managed to track it down to a USB stick (the one I was using for ReadyBoost) being shot.

Answer 1

Here is the story of how I found the cause of my high DPC latency.

---

My system was experiencing clicks and pops during sound playback. I knew this meant that something in kernel mode was hogging the CPU. My first thought was to poke around Process Explorer, and see if anything looked out of place. The only thing that caught my attention was an excessive amount of time spent performing Deferred Procedure Calls (DPCs):

I knew that DPCs are code being run inside a driver; the challenge was to figure out which driver. I turned to DPC Latency Checker, which showed me just how bad the latency was:

DPC Latency Checker suggests going through devices in Device Manager, and disabling non-essential hardware one-by-one (e.g. network card, sound card), hoping to isolate the buggy driver. (If you disable a device, and the DPC latency suddenly drops: you've found your culprit!)

Unfortunately, after disabling everything I possibly could (while still being able to use the computer — don't disable your hard drive, video card, mouse, or USB hub the mouse is plugged into!), the latency was still high. Next I turned to the the Windows Performance Toolkit (part of the Windows SDK), and an excellent blog post by Peter Weiland, "Measuring DPC Time". After installing the Windows Performance Toolkit:

I opened an elevated command prompt and ran:

>xperf -on Latency

Note: The Latency group is a predefined set of events that can be traced from the Kernel Group provider:

>xperf -providers kg
   Base           : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+PROFILE+MEMINFO
   Diag           : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+DPC+INTERRUPT+CSWITCH+PERF_COUNTER+COMPACT_CSWITCH
   DiagEasy       : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+DPC+INTERRUPT+CSWITCH+PERF_COUNTER
   Latency        : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+DPC+INTERRUPT+CSWITCH+PROFILE
   ...

In this case Latency corresponds to the Kernel Flags:

• PROC_THREAD Process and Thread create/delete
• LOADER Kernel and user mode Image Load/Unload events
• PROFILE CPU Sample profile
• CSWITCH Context Switch
• DPC DPC Events
• INTERRUPT Interrupt events
• DISK_IO Disk I/O
• HARD_FAULTS Hard Page Faults

After letting that run for a minute, I stopped the trace, and had it save to a file:

C:\Users\Ian\Desktop\xperf -d thingy1.etl

And then I viewed the results of the trace with the command:

C:\Users\Ian\Desktop\xperf thingy1.etl

This loads the graphical Windows Performance Analyzer. Right clicking on the DPC CPU Usage graph, I selected Summary Table. This shows a breakdown of time spent in DPCs by driver:

Right away I can see one driver (tsvp.sys) taking an average of 2.8ms per DPC execution, which is an order of magnitude slower than any other driver:

Googling tsvp.sys gave me the answer: CommView, which I had recently installed.

The question now is how to disable this driver. Using AutoRuns, I can see that it's installed as a driver service:

Using Device Manager, I can disable the service that hosts this driver. First you have to Show hidden devices, then expand the Non-Plug and Play Drivers node:

Finally I could stop the driver service, and I changed it's startup mode from System (meaning the driver is an essential part of Windows, and Windows cannot boot without it), to Demand (meaning I can start the driver when I want to):

Stopping the driver service immediately fixed my DPC latency:

I may or may not completely uninstall CommView, but for now I've solved the Case of the High DPC Latency.

---

Update: Starting with Windows 8 you can no longer see Non-Plug and Play Drivers in Device Manager:

Note Starting with Windows 8 and Windows Server 2012, the Plug-and-Play Manager no longer creates device represetnations for non-PnP (legacy) devices. Thus there are no such devices to view in the Device Manager. To include hidden devices in Device Manager display, click View and select Show Hidden Devices.

Microsoft took away the feature and replace it with nothing. Good job.

In typical nerd rage, some unhelpful answers:

• Device manager never showed non pnp drivers
• Why do you need this?

Fortunately, NirSoft has created a replacement. ServiWin lets you see, stop, and start all services (even the ones Microsoft decided administrators should be allowed to see):

Answer 2

PROGRESS REPORT

The best tool I've found so far is LatencyMon, which basically does everything that the preceding two tools do, without making you think. The download page asks you to register via email - but nothing happened for me when I did that - but you can scroll to the bottom of the page to download anyway.

Answer 3

In my case I used LatencyMon (from Benjol's answer) and found that the driver freezing life, the universe, and everything was (also) storport.sys which is a Microsoft driver for "high performance buses". That confirmed my suspicious that the problem was IO related.

I also went ahead and looked at my Windows 7 Event Viewer, folder Windows Logs -> Application, and found several batches of errors from Volume Shadow Copy (VSS) happening every 30 min to 2 hours. They're details were like this:

Volume Shadow Copy Service error: Error calling a routine on the Shadow Copy Provider {b5946137-7b9f-4925-af80-51abd60b20d5}. Routine returned E_INVALIDARG. Routine details GetSnapshot({00000000-0000-0000-0000-000000000000},000000000023C850). 

Operation:
   Get Shadow Copy Properties

Context:
   Execution Context: Coordinator

I then began investigating what the heck is VSS and what it is used for. I went over several - pages - about - VSS troubleshooting. Going through all of those I had one big suspect: my backup software CrashPlan.

Following that lead, I quickly found a page relating it with VSS errors. By following the instructions there to disable backup of open files, which uses VSS, the freezes, high Kernel CPU usage, etc were completely extinct. And don't get me wrong: CrashPlan is great! Just this feature wasn't working on my machine.

BTW, this page right here was THE ONE that gave me the initial lead that helped me finding the root cause of my problems. Thanks so much @Benjol and all others that answered previously! I hope my answer will also help others...

Answer 4

There's probably a device driver that's keeping your system busy. One way to analyze this is to run DPC latency checker. Then disable one driver at a time and see if the DPC load goes down. (Process explorer also works.)

You can disable device drivers in Computer Management -> Device Manager.

Answer 5

I feel I should add my answer here because this issue is difficult to solve and not always down to bad drivers or IRQ conflicts.

I had high RPC latency that were causing pops/crackles in my pro-sumer USB soundcard. The tools described in the accepted answer were not helpful in identifying a particular driver that was causing an issue. The latency was occurring across a number of processes: HAL, USBPORT.SYS and the Windows kernel. Digging deeper into these processes did not reveal an obvious culprit.

It turned out in my case that the issue was lower-level and specific to GigaByte motherboards with certain chipsets and BIOS revisions. The solution was to disable Intel SpeedStep and all other motherboard specific features that adjusted CPU speed and voltage on the fly. Once these options were turned off my RPC latency was immediately fixed.

Answer 6

I started seeing this error after resolving an IRQ error with my nVidia 10/100/1000 Ethernet controller that appeared when upgrading my graphics card to the GeForce GTX 550 Ti.

It seems after the upgrade to the new GeForce drivers 295.73 and then resolving the interrupt conflict, I had removed, damaged or uninstalled existing nForce SATA/RAID controller drivers. I don't use RAID, the error still persisted, and locked up Vista Ultimate 64-bit from time to time.

After trying all the troubleshooting suggestions I found on the web, a simple solution presented itself...I upgraded to nForce SATA/RAID controller 15.58, but left other nForce drivers alone.

That fixed it for me, and I now have resolved all my driver conflicts. Hope it helps you, too.