none
System Interrupts CPU (high DPC and Interrupt usage)

    Question

  • Hi, just this evening i was playing a game and my audio started stuttering and my FPS dropped, i checked Task manager real quick and saw very high CPU usage coming from "System interrupts". After some quick searching i now understand that this is usually a driver related issue, and an awesome tool called dpc latency checker can find the culprit. Unfortunately it does not yet work on windows 8, as many people with a similar issue eagerly wait to find a solution.

    I tried doing it manually following some various forum guides, but ultimately got stuck and could not find the problem. If anyone could help me isolate the issue i would greatly appreciate it.

    It is worth noting a couple days ago i stopped using my Marvell Sata controller drivers, and reverted to the standard ones (needed to update my SSD drivers to fix another windows 8 error DPC_Watchdog_Violation). Since then i have had no more BSOD's and everything was running smooth, even while playing games yesterday and today, but it wasn't until seemingly random tonight i got the issue.

    I am using a custom built desktop so no OEM info there, but please let me know any other information that i should include, or diagnositc logs i can produce.

    Thanks


    Friday, January 04, 2013 4:42 AM

All replies

  • Hi,

    make a xperf trace or Run LatencyMon [1] to diagnostic the DPC issues. Please upload the xperf etl file to your SkyDrive [2] and post a link here if LatencyMon doesn't help you to find the causing driver.

    I'll take a look at it.

    André

    [1] http://www.msfn.org/board/index.php?showtopic=140263
    [2] http://social.technet.microsoft.com/Forums/en-US/w7itproui/thread/4fc10639-02db-4665-993a-08d865088d65

    "A programmer is just a tool which converts caffeine into code"

    Friday, January 04, 2013 5:38 AM
    Answerer
  • Thanks for the response, i was under the impression that LatencyMod also gave false/incorrect values on windows 8.

    I went ahead and ran LatencyMod for a minuet, and attached a logfile, and a few screenshots from the program.
    I also ran xperf trace for about 30 seconds, and attacked those etl files as well.

    Everything is in my Skydrive, my Upload speed is very slow so a couple of the big files might not show up yet, but hopefully by the time you see it they will be.

    http://sdrv.ms/XrPhQ8

    Three should be a total of 8 files. Thanks again.

    EDIT: I gave up, just uploaded them on my phone, much faster. I wasn't sure exactly which files were important so i attached the kernel.etl, as well as the DPC_interupt.etl, a log of the xperf trace, and screenshots of latencyMOD + log.

    Friday, January 04, 2013 6:21 PM
  • the trace you captured shows normal CPU usgae caused by 4 programs (vina_3.1_windows_intelx86.exe, vina_3.1_windows_intelx86.exe, pdsat_3.02_windows_intelx86.exe and camb_2.16_windows_intelx86.exe). Next you have Steam running which causes some CPU usgae.

    The only DPC spikes come from ndis.sys:

    Total = 1124 for module ndis.sys
    Elapsed Time, >      512 usecs AND <=     1024 usecs,      5, or   0.44%
    Total,                                                  1124

    Update the driver for your Realtek PCIe GBE Family Controller and look if this helps because you use the inbox driver from July (Rt630x64.sys", "8.003.0730.2012")

    http://www.realtek.com.tw/downloads/downloadsView.aspx?Langid=1&PNid=13&PFid=5&Level=5&Conn=4&DownTypeID=3&GetDown=false


    "A programmer is just a tool which converts caffeine into code"

    Saturday, January 05, 2013 7:27 AM
    Answerer
  • Thanks, i updated to the driver listed above, restarted and ran latencymon again. I'll post the quick logfile here, if you need more info i will.

    It seems to only happen slightly every few seconds, just using a few percent or even less cpu usage. Thats how it was before though, just the one time it spiked really high and lagged my system and audio. 

    Should i have 0 system interrupts, or is a little okay, because i am not sure the issue is gone even if it is better. However it seemed to be sporadic to begin with.

    _________________________________________________________________________________________________________
    CONCLUSION
    _________________________________________________________________________________________________________
    Your system appears to be suitable for handling real-time audio and other tasks without dropouts. 
    LatencyMon has been analyzing your system for  0:00:30  (h:mm:ss) on all processors in the system.
    
    
    _________________________________________________________________________________________________________
    SYSTEM INFORMATION
    _________________________________________________________________________________________________________
    Computer name:                                        NATHAN-DESKTOP
    OS version:                                           Windows 8 , 6.2, build: 9200 (x64)
    CPU:                                                  AuthenticAMD AMD Phenom(tm) II X4 955 Processor
    Logical processors:                                   4
    Processor groups:                                     1
    RAM:                                                  16383 MB total
    
    
    _________________________________________________________________________________________________________
    CPU SPEED
    _________________________________________________________________________________________________________
    Reported CPU speed:                                   3800.0 MHz
    Measured CPU speed:                                   4636.0 MHz (approx.)
    
    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.
    
    
    _________________________________________________________________________________________________________
    MEASURED KERNEL TIMER LATENCIES
    _________________________________________________________________________________________________________
    Highest measured kernel timer latency (µs):           1008.228699
    
    
    _________________________________________________________________________________________________________
    MEASURED SMIs AND CPU STALLS
    _________________________________________________________________________________________________________
    Highest measured SMI, IPI or CPU stall (µs)           20.044447
    
    
    _________________________________________________________________________________________________________
    REPORTED DPCs
    _________________________________________________________________________________________________________
    Highest DPC routine execution time (µs):              146.484737
    Driver with highest DPC routine execution time:       ndis.sys - NDIS 6.30 driver, Microsoft Corporation
    
    Highest reported total DPC routine time (%):          0.192897
    Driver with highest DPC total execution time:         rspLLL64.sys - Resplendence Latency Monitoring and Auxiliary Kernel Library, Resplendence Software Projects Sp.
    
    Total time spent in DPCs (%)                          0.518336
    
    DPC count (execution time <250 µs):                   41526
    DPC count (execution time 250-500 µs):                0
    DPC count (execution time 500-999 µs):                0
    DPC count (execution time 1000-1999 µs):              0
    DPC count (execution time 2000-3999 µs):              0
    DPC count (execution time >=4000 µs):                 0
    
    
    _________________________________________________________________________________________________________
     REPORTED ISRs
    _________________________________________________________________________________________________________
    Highest ISR routine execution time (µs):              313.150526
    Driver with highest ISR routine execution time:       ataport.SYS - ATAPI Driver Extension, Microsoft Corporation
    
    Highest reported total ISR routine time (%):          0.110007
    Driver with highest ISR total time:                   dxgkrnl.sys - DirectX Graphics Kernel, Microsoft Corporation
    
    Total time spent in ISRs (%)                          0.235192
    
    ISR count (execution time <250 µs):                   38818
    ISR count (execution time 250-500 µs):                0
    ISR count (execution time 500-999 µs):                4
    ISR count (execution time 1000-1999 µs):              0
    ISR count (execution time 2000-3999 µs):              0
    ISR count (execution time >=4000 µs):                 0
    
    
    _________________________________________________________________________________________________________
     REPORTED HARD PAGEFAULTS
    _________________________________________________________________________________________________________
    Process with highest pagefault count:                 none
    
    Total number of hard pagefaults                       111
    Hard pagefault count of hardest hit process:          73
    Highest hard pagefault resolution time (µs):          1915.754211
    Total time spent in hard pagefaults (%):              0.036757
    Number of processes hit:                              0
    
    
    _________________________________________________________________________________________________________
     PER CPU DATA
    _________________________________________________________________________________________________________
    CPU 0 Interrupt cycle time (s):                       0.971076
    CPU 0 ISR highest execution time (µs):                51.0150
    CPU 0 ISR total execution time (s):                   0.001785
    CPU 0 ISR count:                                      178
    CPU 0 DPC highest execution time (µs):                146.484737
    CPU 0 DPC total execution time (s):                   0.285418
    CPU 0 DPC count:                                      17622
    _________________________________________________________________________________________________________
    CPU 1 Interrupt cycle time (s):                       0.153965
    CPU 1 ISR highest execution time (µs):                58.944737
    CPU 1 ISR total execution time (s):                   0.007126
    CPU 1 ISR count:                                      755
    CPU 1 DPC highest execution time (µs):                93.525526
    CPU 1 DPC total execution time (s):                   0.011231
    CPU 1 DPC count:                                      798
    _________________________________________________________________________________________________________
    CPU 2 Interrupt cycle time (s):                       0.203732
    CPU 2 ISR highest execution time (µs):                71.614474
    CPU 2 ISR total execution time (s):                   0.033704
    CPU 2 ISR count:                                      3670
    CPU 2 DPC highest execution time (µs):                113.036579
    CPU 2 DPC total execution time (s):                   0.037069
    CPU 2 DPC count:                                      2390
    _________________________________________________________________________________________________________
    CPU 3 Interrupt cycle time (s):                       0.787475
    CPU 3 ISR highest execution time (µs):                313.150526
    CPU 3 ISR total execution time (s):                   0.243858
    CPU 3 ISR count:                                      34219
    CPU 3 DPC highest execution time (µs):                133.480
    CPU 3 DPC total execution time (s):                   0.297635
    CPU 3 DPC count:                                      20716
    _________________________________________________________________________________________________________
    

    Saturday, January 05, 2013 10:06 PM
  • this shows me that you have 4 spikes which may cause the audio issue.

    ISR count (execution time 500-999 µs):                4

    run this command all the time in background (DON'T RUN PROCEXP OR LATENCYMON at the same time!) :

    xperf -on latency -stackwalk profile -buffersize 1024 -MaxFile 256 -FileMode Circular && timeout -1 && xperf -d DPC_Interrupt.etl

    and when you get the laggs, go back to the cmd and press a key to stop logging. Now share the new ETL file.


    "A programmer is just a tool which converts caffeine into code"

    Sunday, January 06, 2013 7:10 AM
    Answerer
  • Thanks, i have been ruining it, haven't experienced the lags or audio bugs yet, but they are extremely rare.

    I can attach it anyways though if you want, as far as I've seen System Interrupts usually takes 0.*-1.* Percentage of CPU, except when the audio bug appears obviously.

    Monday, January 07, 2013 11:01 PM
  • You can run this command in background all the time. The filesize is limited to 256MB. When you gte the audio bug again, go to CMD and stop the logging.

    "A programmer is just a tool which converts caffeine into code"

    Tuesday, January 08, 2013 5:56 AM
    Answerer
  • Still having issues. Took a new log. Can anyone be of assistance? Thanks

    _________________________________________________________________________________________________________
    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 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:21:17  (h:mm:ss) on all processors.
    
    
    _________________________________________________________________________________________________________
    SYSTEM INFORMATION
    _________________________________________________________________________________________________________
    Computer name:                                        NATHAN-DESKTOP
    OS version:                                           Windows 8 , 6.2, build: 9200 (x64)
    Hardware:                                             MS-7599, MSI, 870A-G55 (MS-7599)
    CPU:                                                  AuthenticAMD AMD Phenom(tm) II X4 955 Processor
    Logical processors:                                   4
    Processor groups:                                     1
    RAM:                                                  16383 MB total
    
    
    _________________________________________________________________________________________________________
    CPU SPEED
    _________________________________________________________________________________________________________
    Reported CPU speed:                                   3800.0 MHz
    Measured CPU speed:                                   5208.0 MHz (approx.)
    
    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.
    
    
    _________________________________________________________________________________________________________
    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):   2018.133590
    Average measured interrupt to process latency (µs):   6.174089
    
    Highest measured interrupt to DPC latency (µs):       233.688919
    Average measured interrupt to DPC latency (µs):       2.558643
    
    
    _________________________________________________________________________________________________________
    MEASURED SMI, IPI AND CPU STALLS
    _________________________________________________________________________________________________________
    The SMI, IPI and CPU stalls value represents the highest measured interval that a CPU did not respond while having its maskable interrupts disabled.
    
    Highest measured SMI or CPU stall (µs)                21.022225
    
    
    _________________________________________________________________________________________________________
     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):              515.8150
    Driver with highest ISR routine execution time:       ataport.SYS - ATAPI Driver Extension, Microsoft Corporation
    
    Highest reported total ISR routine time (%):          0.367935
    Driver with highest ISR total time:                   dxgkrnl.sys - DirectX Graphics Kernel, Microsoft Corporation
    
    Total time spent in ISRs (%)                          0.800443
    
    ISR count (execution time <250 µs):                   5592955
    ISR count (execution time 250-500 µs):                0
    ISR count (execution time 500-999 µs):                80
    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):              467.414474
    Driver with highest DPC routine execution time:       ntoskrnl.exe - NT Kernel & System, Microsoft Corporation
    
    Highest reported total DPC routine time (%):          0.222693
    Driver with highest DPC total execution time:         nvlddmkm.sys - NVIDIA Windows Kernel Mode Driver, Version 320.18 , NVIDIA Corporation
    
    Total time spent in DPCs (%)                          1.164309
    
    DPC count (execution time <250 µs):                   8103299
    DPC count (execution time 250-500 µs):                0
    DPC count (execution time 500-999 µs):                1
    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:                 msmpeng.exe
    
    Total number of hard pagefaults                       48109
    Hard pagefault count of hardest hit process:          21397
    Highest hard pagefault resolution time (µs):          995246.443684
    Total time spent in hard pagefaults (%):              1.834249
    Number of processes hit:                              40
    
    
    _________________________________________________________________________________________________________
     PER CPU DATA
    _________________________________________________________________________________________________________
    CPU 0 Interrupt cycle time (s):                       39.527573
    CPU 0 ISR highest execution time (µs):                69.790789
    CPU 0 ISR total execution time (s):                   0.081838
    CPU 0 ISR count:                                      9267
    CPU 0 DPC highest execution time (µs):                467.414474
    CPU 0 DPC total execution time (s):                   20.479948
    CPU 0 DPC count:                                      4573143
    _________________________________________________________________________________________________________
    CPU 1 Interrupt cycle time (s):                       9.098229
    CPU 1 ISR highest execution time (µs):                515.8150
    CPU 1 ISR total execution time (s):                   0.535598
    CPU 1 ISR count:                                      63510
    CPU 1 DPC highest execution time (µs):                168.656579
    CPU 1 DPC total execution time (s):                   1.525866
    CPU 1 DPC count:                                      124085
    _________________________________________________________________________________________________________
    CPU 2 Interrupt cycle time (s):                       17.890030
    CPU 2 ISR highest execution time (µs):                324.482632
    CPU 2 ISR total execution time (s):                   4.512601
    CPU 2 ISR count:                                      624114
    CPU 2 DPC highest execution time (µs):                147.947368
    CPU 2 DPC total execution time (s):                   6.780893
    CPU 2 DPC count:                                      531805
    _________________________________________________________________________________________________________
    CPU 3 Interrupt cycle time (s):                       75.340101
    CPU 3 ISR highest execution time (µs):                444.206842
    CPU 3 ISR total execution time (s):                   35.777806
    CPU 3 ISR count:                                      4896144
    CPU 3 DPC highest execution time (µs):                154.079737
    CPU 3 DPC total execution time (s):                   30.717075
    CPU 3 DPC count:                                      2874267
    _________________________________________________________________________________________________________
    

    Thursday, June 13, 2013 12:45 AM
  • upload the latest ETL file.

    "A programmer is just a tool which converts caffeine into code"

    Thursday, June 13, 2013 4:53 AM
    Answerer