How to get the cause of high CPU usage by DPC / Interrupt

[MagicAndre1981]

run the xperf commands and upload the generated .ETL file.

[doveman]

I've had to restore my gaming PC from a True Image backup and am having problems with latency again. Previously I'd got it down to around 19us, with spikes around 100-200us.

Now it's not going lower than around 82us, spending most of the time around 150-300ms but with very high spikes as shown in these screenshots. The first two were taken before installing the AMD Chipset drivers.

These next two were taken after installing the AMD Chipset drivers. At first, it seemed better and stayed below about 300us but as soon as I opened my browser, with several tabs saved, it spiked to 500us and then LatencyMon stopped (I didn't notice at first). After I restarted it, I saw these very high spikes, which are lower than the spikes in the previous screenshots but still very high.

etl uploaded to https://docs.google.com/file/d/0B1fDI89phEESclpuWXNvZGpSYVk/edit?usp=sharing

[MagicAndre1981]

the .etl file shows 1 spike caused by the NDIS.sys:

Total = 130696 for module ndis.sys
Elapsed Time, >      256 usecs AND <=      512 usecs,     56, or   0.04%
Elapsed Time, >      512 usecs AND <=     1024 usecs,      1, or   0.00%
Total,                                                130696

Also disable all effects in the sound options, becasue the AudioEng.exe causes some CPU usage (CAudioProcessor::ProcessEachAPO)

Edited July 10, 2013 by MagicAndre1981

[MagicAndre1981]

my last post is gone.

The latest trace shows HDD issues ("Depth queue at Init" is over 100) which explains the storport.sys issues you see.

[doveman]

my last post is gone.

The latest trace shows HDD issues ("Depth queue at Init" is over 100) which explains the storport.sys issues you see.

Hmm, seems to be an epidemic. My post has disappeared too.

Anyway, as I'm not sure which message you're replying to, can you confirm you're referring to DPC_Interrupt_3.zip?

I'm still at a loss to understand why this storport.sys (which apparently is used for SCSI devices) is even being used on my system. In Device Manager, the AMD SATA Controller lists amd_sata.sys and amd_xata.sys, whilst the actual HDDs list disk.sys and partmgr.sys and I don't have any other storage devices connected.

[MagicAndre1981]

I think the storport.sys is used by the AHCI driver.

[doveman]

I think the storport.sys is used by the AHCI driver.

You might be right but I'm not seeing it come up on my other system which is also running in AHCI mode. On that, I haven't installed the AMD Chipset driver yet, so the controller is listed as "Standard AHCI 1.0 Serial ATA Controller" rather than "AMD SATA" (on the system the trace is from, there's also a "Standard AHCI 1.0 Serial ATA Controller" listed, with nothing attached, so I presume there must be another controller on the MSI board that's not part of the AMD 990 chipset.)

In that case, the controller lists atapi.sys, ataport.sys, msahci.sys, pciidex.sys and the HDD lists disk.sys and partmgr.sys as on the other system.

[doveman]

I've now installed the ATI Chipset drivers and upgraded the Realtek audio drivers to 6923 on my other system and I am seeing storport.sys mentioned in LatencyMon, so it seems that comes as part of the AMD drivers.

Latency was OK until I launched Iron and about 20s later it hit 3000us+, so again it was probably the HDD activity (51us ISR, 607us DPC currently). If I restart LatencyMon, the latency hovers between 80-200us with the odd spike to 569us, although it just hit 1222us. Launching Plex and it hit 4029us.

I'll make a trace on this system, launching Iron and then Plex to see what it shows.

EDIT: OK, with this trace I first launched IE, which opens with only one tab, as I saw previously in LatencyMon that caused a spike of 1700us. Then I launched Iron and left it to settle for one minute, then I launched Plex and refreshed a couple of the libraries, which didn't take long. https://docs.google.com/file/d/0B1fDI89phEEScVdxTVotODN3M00/edit?usp=sharing

I thought I'd see if I could understand the trace myself but when I double-click on the etl, WPA opens but then says it's stopped working with the following details

Problem signature:
  Problem Event Name:	APPCRASH
  Application Name:	wpa.exe
  Application Version:	6.2.9200.16384
  Application Timestamp:	501077b4
  Fault Module Name:	clr.dll
  Fault Module Version:	4.0.30319.1008
  Fault Module Timestamp:	517a18ff
  Exception Code:	c0000005
  Exception Offset:	000000000000d08d
  OS Version:	6.1.7601.2.1.0.256.1
  Locale ID:	2057
  Additional Information 1:	3749
  Additional Information 2:	3749574877fa1c2583d7663bfe3c5c14
  Additional Information 3:	b4dc
  Additional Information 4:	b4dcc7f0b08f3f363dd8378be51c7b0b

Read our privacy statement online:
  http://go.microsoft.com/fwlink/?linkid=104288&clcid=0x0409

If the online privacy statement is not available, please read our privacy statement offline:
  C:\Windows\system32\en-US\erofflps.txt

EDIT: Hmm, this seems interesting. As a test, I tried putting Windows Power Options in High Perfomance rather than balanced, which runs the CPU at full speed permanently and also disables "Link State Power Management".

In this mode, I didn't see any spikes when launching IE, nor when running Plex. I still got a spike of around 2700us shortly after launching Iron though and another around 1600us when I was switching between tabs and scrolling through pages.

I've uploaded the trace, repeating the same sequence of tasks as before, here https://docs.google.com/file/d/0B1fDI89phEESSU52VlVKQ0J3cW8/edit?usp=sharing

EDIT2: I also updated the NIC, USB and SATA3 drivers and moved the HDD to the SATA3 port. Rebooting, it's still in High Performance mode and latency stayed under 250us at idle, no spike with IE, a spike to 2500us running Plex. With Iron however, I just got a spike of 4000us followed by one of 19536us! storport.sys is nowhere to be seen now the HDD is not connected to the AMD chipset SATA2 ports and instead ataport.sys is referenced again. Highest ISR of 32us for ataport.sys and DPC 130us for ntoskrnl but those figures are no higher than they were before the spikes happened so they don't seem very useful.

I'll make another trace. Here it is https://docs.google.com/file/d/0B1fDI89phEESU0NIWHkyZXBYMzA/edit?usp=sharing

Edited July 11, 2013 by doveman

[MagicAndre1981]

the DPC_Interrupt_S2c shows DPC usage from USBport.sys

and you still have disk issues. Your HDD is flushing the data all the time (open the etl with xperfview.exe, make a rightclick on the disk graph and select "Detail graph", here you see a lot of red lines). The depth queue is better but still 30 which is still bad.

[doveman]

Thanks. I guess it could be that I'd put the HDD on the SATA3 port that reduced the queue, or it might be High Performance mode or it might just be that it's a different system/HDD I guess. Could you compare with DPC_Interrupt_S2 for me please, which was using SATA2 in Balanced Mode?

The screen went blank when I ran HwInfo and when I next rebooted (after a hard reset) the Sidebar gadgets didn't appear and the mouse was stuck on busy and I couldn't do anything, so had to hard reset again, so I moved the HDD back to the SATA2 port. Mind you, both these problems happened before when it was on the SATA2 port and I thought I'd fixed them by uninstalling some software but anyway, at least it's booting again now.

I'll try disabling the Hauppage Nova-T 500 TV Tuner card as that creates two VIA USB buses. I'm also using a wireless mouse and dongle and a separate wireless keyboard and receiver, so I don't know if those would cause latency problems.

[doveman]

Seems I removed the Nova-T card by mistake (thought I'd removed the Nebula card) but that makes it easier to test without it

Here's another scan, doing the same tasks as before, without that card installed. I also disabled the HwInfo persistent driver in case that was causing problems: https://docs.google.com/file/d/0B1fDI89phEESM3NrMGFKSzdXX2c/edit?usp=sharing

Monitoring the hard pagefaults I found:

On first run, the process with the highest number of pagefaults is svchost at 190 (and rising) after about a minute. This isn't associated with high latency though, which is hovering below 75us with the odd spike to 200us and the highest around 400us.

I noticed that HwInfoMonitor (a sidebar gadget) was showing about 10 pagefaults, so closed that and restarted LatencyMon and then it only showed a count of 3 pagefaults after 3 minutes, one on svchost.exe and one on explorer.exe. I'm not sure where the third one is hiding! Then I launched Iron, and got a latency spike of 12325us (and several below 1000us) and the pagefault count rises to 240 by the time all the tabs have loaded, but processes only shows 50 on Iron.exe, 3 on another instance of Iron.exe, 8 on TrustedInstaller.exe, 2 on svchost.exe, 1 on explorer.exe and 1 on another instance of iron.exe. The total count and the first instance of iron.exe are slowing rising, now on 264 and 66 respectively. Iron seems to open an instance of iron.exe for each tab, judging by Task Manager, so I'm not sure if this indicates that most of the pagefaults are associated with one particular tab.

Then I closed Iron and re-enabled HwInfoMonitor and although it's still showing some pagefaults on that (6 after 1.5mins) I'm not seeing any of svchost.exe now.

I did manage to open the trace with xperfview and opened "Detal Graph" from Disk I/O and Disk Utilisation (seems to open the same view) but I can't see where it shows the Disk Queue.

Edited July 12, 2013 by doveman

[MagicAndre1981]

the DPC2 shows 1 spike causes by the storport.sys. The 2b shows 1 USBport.sy spike.

Do you connect the SUb devices to the ASMedia XHCI Controller or Via USB2?

to get the Depth queue you have to make a rightclik inside the "detail graph" and select "Summary table" again. It is a bit confusing.

[doveman]

Nothing's connected to the Asmedia USB3 controller, just the Mouse dongle and Keyboard dongle connected to the top two USB2 ports on the rear of the board.

Did you have a look at the DPC_S2d trace with the Nova-T card removed? I'd be interested to know if that shows less/no USB spikes.

[MagicAndre1981]

the 2d is fine. Only 1 storport.sys spike, but not critical (under 1ms):

Total = 5102 for module storport.sysElapsed Time, >      128 usecs AND <=      256 usecs,     75, or   1.47%Elapsed Time, >      256 usecs AND <=      512 usecs,      1, or   0.02%Total,                                                  5102

[doveman]

the 2d is fine. Only 1 storport.sys spike, but not critical (under 1ms):

Thanks. I'm really at a loss to know what to do. The latency spikes would appear to be related to HDD writing and nothing to do with pagefaults. Running Windows defrag and analysing my partitions, svchost generates a ton of pagefaults (like 30000) but no latency spikes. If I Analyse in CCleaner, no latency spikes but when I run the Wipe, they appear.

Iron seems to generate a spike (3500us) just as it's finished opening all the saved tabs, so perhaps it does some writing at that point. Then again, if I open a new tab and browse to a new page, that obviously writes to the temporary files and doesn't generate a spike. Opera Portable also generates a spike of around 1100us just as it finishes loading. Sometimes IE, which only opens with one tab, does and other times it doesn't generate a spike, whether I'm in Balanced or High Performance mode. I get the odd spike to 600-700us with various apps but that's below the threshold to trigger LatencyMon's warning, so they probably don't matter.

Even in High Performance mode, opening MediaPortal generates several spikes from 1500us to 3908us. On the second launch, it hit 20874us and then 9000us. Even if I restart LatencyMon after MediaPortal has loaded, it spikes to around 2000us several times. It may be updating the media database in the background, which could involve writing new thumbnails, metadata, etc.

Then again I can update/install software without triggering any spikes.

Generally storport.sys is appearing from both ISR and DPC although sometimes ISR gets replaced by tcpip.sys or ndis.sys

EDIT: Strangely, if I run DPC Latency Checker with Iron open, the highest spike is 168us over several minutes. If I close that and start LatencyMon however, I get a spike of 758us within 10s. I don't know if DPC-LC is just sampling at a lower frequency than LatencyMon and missing the spikes. With MediaPortal, the highest spike DPC-LC shows is 138us.

Edited July 15, 2013 by doveman