Simple way to trace DPCs and ISRs

Discussion in 'Operating Systems' started by mbk1969, Nov 12, 2018.

  1. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    Everyone uses Latencymon nowadays to troubleshoot DPC latencies. I stumbled across even simpler way provided by Microsoft.

    1. Install "Windows Performance Toolkit" from Windows ADK (for your version of Windows)
    https://docs.microsoft.com/en-us/windows-hardware/get-started/adk-install
    For my Win10 1803 it costs
    [​IMG]

    2. Launch elevated command prompt and execute to start the trace:
    Code:
    cd "C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit"
    xperf -on base+interrupt+dpc
    
    3. Run the game, the video, or whatever you are trying to troubleshoot.

    4. Return to command prompt to stop the trace and to save the trace file:
    Code:
    xperf -d c:\temp\trace.etl
    
    Choose your own path and name for that trace file.

    5. Generate the text report file for DPCs and ISRs:
    Code:
    xperf -i c:\temp\trace.etl -o c:\temp\report.txt -a dpcisr
    
    6. Now you can open that text report file to browse quite detailed info.
    My example for DPCs:
    Code:
    --------------------------
    DPC Info
    --------------------------
    CPU Usage Summing By Module For the Whole Trace
    CPU Usage from 0 us to 45524244 us:
         CPU 0 Usage,      CPU 1 Usage,      CPU 2 Usage,      CPU 3 Usage,      CPU 4 Usage,      CPU 5 Usage,      CPU 6 Usage,      CPU 7 Usage,      CPU 8 Usage,      CPU 9 Usage,      CPU 10 Usage,      CPU 11 Usage,
         usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %, Module
            0   0.00,         0   0.00,        27   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, CLASSPNP.SYS
         3180   0.01,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, HDAudBus.sys
           45   0.00,         0   0.00,         1   0.00,         2   0.00,        31   0.00,         0   0.00,         9   0.00,         2   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, Ndu.sys
            5   0.00,         0   0.00,         5   0.00,         0   0.00,        23   0.00,         0   0.00,         7   0.00,         0   0.00,         8   0.00,         0   0.00,         0   0.00,         0   0.00, Ntfs.sys
          211   0.00,         0   0.00,        23   0.00,         7   0.00,        36   0.00,         0   0.00,        13   0.00,         7   0.00,         0   0.00,        15   0.00,         7   0.00,         8   0.00, USBPORT.SYS
           14   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, WdFilter.sys
         2852   0.01,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, asmtxhci.sys
        27992   0.06,         0   0.00,       108   0.00,         8   0.00,       208   0.00,         0   0.00,        55   0.00,        14   0.00,         8   0.00,         8   0.00,        34   0.00,         9   0.00, dxgkrnl.sys
          247   0.00,         0   0.00,        41   0.00,         0   0.00,        97   0.00,         5   0.00,        32   0.00,        11   0.00,        18   0.00,         3   0.00,        36   0.00,         5   0.00, dxgmms2.sys
            1   0.00,         0   0.00,         5   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, hal.dll
           14   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, kbdhid.sys
          681   0.00,         0   0.00,        43   0.00,        22   0.00,       101   0.00,         0   0.00,        16   0.00,         0   0.00,        19   0.00,        23   0.00,        12   0.00,        13   0.00, ndis.sys
        32259   0.07,       510   0.00,      4375   0.01,      1879   0.00,     10845   0.02,      1776   0.00,      4951   0.01,      2481   0.01,      2466   0.01,      2638   0.01,      7674   0.02,      3018   0.01, ntoskrnl.exe
       167796   0.37,         0   0.00,       147   0.00,        60   0.00,       459   0.00,         7   0.00,        93   0.00,        36   0.00,         7   0.00,        32   0.00,        85   0.00,         4   0.00, nvlddmkm.sys
            0   0.00,         0   0.00,         0   0.00,         0   0.00,         6   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, rdyboost.sys
           82   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, storahci.sys
          939   0.00,        21   0.00,       649   0.00,        82   0.00,       896   0.00,         0   0.00,      1113   0.00,         9   0.00,       428   0.00,       929   0.00,       842   0.00,        22   0.00, storport.sys
           64   0.00,        15   0.00,       302   0.00,       128   0.00,       145   0.00,         0   0.00,       324   0.00,         4   0.00,         0   0.00,       106   0.00,         0   0.00,       298   0.00, tcpip.sys
    
    Total = 17090
    Elapsed Time, >        0 usecs AND <=        1 usecs,    977, or   5.72%
    Elapsed Time, >        1 usecs AND <=        2 usecs,   1067, or   6.24%
    Elapsed Time, >        2 usecs AND <=        4 usecs,   3668, or  21.46%
    Elapsed Time, >        4 usecs AND <=        8 usecs,   4017, or  23.50%
    Elapsed Time, >        8 usecs AND <=       16 usecs,   1486, or   8.70%
    Elapsed Time, >       16 usecs AND <=       32 usecs,   1711, or  10.01%
    Elapsed Time, >       32 usecs AND <=       64 usecs,   3634, or  21.26%
    Elapsed Time, >       64 usecs AND <=      128 usecs,    457, or   2.67%
    Elapsed Time, >      128 usecs AND <=      256 usecs,     73, or   0.43%
    Total,                                                 17090
    
    Total = 5453 for module ntoskrnl.exe
    Elapsed Time, >        0 usecs AND <=        1 usecs,    108, or   1.98%
    Elapsed Time, >        1 usecs AND <=        2 usecs,    313, or   5.74%
    Elapsed Time, >        2 usecs AND <=        4 usecs,   1537, or  28.19%
    Elapsed Time, >        4 usecs AND <=        8 usecs,   1277, or  23.42%
    Elapsed Time, >        8 usecs AND <=       16 usecs,    431, or   7.90%
    Elapsed Time, >       16 usecs AND <=       32 usecs,    834, or  15.29%
    Elapsed Time, >       32 usecs AND <=       64 usecs,    946, or  17.35%
    Elapsed Time, >       64 usecs AND <=      128 usecs,      5, or   0.09%
    Elapsed Time, >      128 usecs AND <=      256 usecs,      2, or   0.04%
    Total,                                                  5453
    
    ...
    

    and for ISRs
    Code:
    --------------------------
    Interrupt Info
    --------------------------
    CPU Usage Summing By Module For the Whole Trace
    CPU Usage from 0 us to 45524244 us:
         CPU 0 Usage,      CPU 1 Usage,      CPU 2 Usage,      CPU 3 Usage,      CPU 4 Usage,      CPU 5 Usage,      CPU 6 Usage,      CPU 7 Usage,      CPU 8 Usage,      CPU 9 Usage,      CPU 10 Usage,      CPU 11 Usage,
         usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %,      usec      %, Module
         4328   0.01,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, HDAudBus.sys
         1747   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, asmtxhci.sys
       235333   0.52,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, dxgkrnl.sys
          767   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, ndis.sys
         2903   0.01,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00,         0   0.00, storport.sys
    
    Total = 6733
    Elapsed Time, >        0 usecs AND <=        1 usecs,    248, or   3.68%
    Elapsed Time, >        1 usecs AND <=        2 usecs,    277, or   4.11%
    Elapsed Time, >        2 usecs AND <=        4 usecs,    470, or   6.98%
    Elapsed Time, >        4 usecs AND <=        8 usecs,    907, or  13.47%
    Elapsed Time, >        8 usecs AND <=       16 usecs,    513, or   7.62%
    Elapsed Time, >       16 usecs AND <=       32 usecs,    965, or  14.33%
    Elapsed Time, >       32 usecs AND <=       64 usecs,   1272, or  18.89%
    Elapsed Time, >       64 usecs AND <=      128 usecs,   2080, or  30.89%
    Elapsed Time, >      128 usecs AND <=      256 usecs,      1, or   0.01%
    Total,                                                  6733
    
    Total = 728 for module HDAudBus.sys
    Elapsed Time, >        0 usecs AND <=        1 usecs,      0, or   0.00%
    Elapsed Time, >        1 usecs AND <=        2 usecs,      0, or   0.00%
    Elapsed Time, >        2 usecs AND <=        4 usecs,      0, or   0.00%
    Elapsed Time, >        4 usecs AND <=        8 usecs,    670, or  92.03%
    Elapsed Time, >        8 usecs AND <=       16 usecs,     53, or   7.28%
    Elapsed Time, >       16 usecs AND <=       32 usecs,      4, or   0.55%
    Elapsed Time, >       32 usecs AND <=       64 usecs,      0, or   0.00%
    Elapsed Time, >       64 usecs AND <=      128 usecs,      1, or   0.14%
    Total,                                                   728
    
    ...
    

    where "us", "usec" and "usecs" stand for "microseconds".
    You can see how many DPCs/ISRs for each module fall to ranges - between 0 and 1 microseconds, between 1 and 2 microseconds, and so forth.
    Also you can see summaries for DPCs and ISRs per CPU.
     
    Last edited: Nov 12, 2018
  2. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    And "Windows Performance Toolkit" comes with GUI tools "Windows Performance Recorder" and "Windows Performance Analyzer" as well. I started to prepare screenshots with these tools but decided to write only about "xperf" usage as a simplest one. But you can open etl-files in "Windows Performance Analyzer" and view raw ETW info in sophisticated and complicated way to feel as very smart person.
     
    Coldblackice likes this.
  3. Astyanax

    Astyanax Ancient Guru

    Messages:
    11,351
    Likes Received:
    4,256
    GPU:
    GTX 1080ti
    DPC and ISR values obtained during system load are invalid.
     
  4. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    Why are you talking about obtaining DPC and ISR during system load?
     

  5. Astyanax

    Astyanax Ancient Guru

    Messages:
    11,351
    Likes Received:
    4,256
    GPU:
    GTX 1080ti
    >3. Run the game, the video, or whatever you are trying to troubleshoot.

    none of the vendors will accept DPC/ISR bug reports when the device is busy.
     
  6. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    Who cares what vendors do? It is just a way to find possible culprit, troubleshoot, and change the vendor if troubleshooting was not successful.
     
  7. limeay

    limeay Active Member

    Messages:
    60
    Likes Received:
    1
    GPU:
    Nvidia GTX 1080 Ti
    I've heard of this but majority use latencymon... I should try this whenever I have enough time and my craptastic internet becomes more stable again. ATT sucking it with DNS probe problems... this I believe is across the U.S
     
  8. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    Latencymon doesn`t offer detailed info on DPCs and ISRs.
     
  9. jenpepu

    jenpepu New Member

    Messages:
    1
    Likes Received:
    0
    GPU:
    RTX 2080 Ti - 11Go
    Never to late to say it, thank.
     
  10. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    Have you used it?
     

  11. Coldblackice

    Coldblackice Member Guru

    Messages:
    127
    Likes Received:
    0
    GPU:
    EVGA 3080 FTW3
    When I try this, I get this error: xperf: error: NT Kernel Logger: Cannot create a file when that file already exists. (0xb7).

    Any idea why? Googling reveals others suggesting this can happen if Process Monitor/Hacker/Explorer is open at the time, however, I definitely have all of them closed.
     
  12. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    Which command gives you that:
    xperf -on base+interrupt+dpc
    or
    xperf -d c:\temp\trace.etl
    ?
     
  13. Guru3Dmember

    Guru3Dmember Member

    Messages:
    49
    Likes Received:
    4
    GPU:
    6Gb
    Is it possible to just observe one module? e.g. ndis.sys?

    Also I've tried running this and some of the commands don't work like:

    $date = date
    start-sleep -s 5
    write-host "started"
    start-sleep -s 30

    This seems to work but I also don't know what to expect here as well.
    xperf -on Latency -stackwalk profile -BufferSize 1024

    Should I run your command? The "xperf -on base+interrupt+dpc"?

    https://github.com/djdallmann/GamingPCSetup/blob/master/CONTENT/SCRIPTS/xperfdpcisr.ps1
     
  14. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    Let`s see what a kernel provider offers - output of "xperf -providers K" command:
    Code:
    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
           COMPACT_CSWITCH: Compact Context Switch
           DISPATCHER     : CPU Scheduler
           DPC            : DPC Events
           IDEAL_PROC     : Ideal processor events
           INTERRUPT      : Interrupt events
           INTERRUPT_STEER: Interrupt Steering events
           WDF_DPC        : WDF DPC events
           WDF_INTERRUPT  : WDF Interrupt events
           SYSCALL        : System calls
           PRIORITY       : Priority change events
           SPINLOCK       : Spinlock Collisions
           KQUEUE         : Kernel Queue Enqueue/Dequeue
           ALPC           : Advanced Local Procedure Call
           PERF_COUNTER   : Process Perf Counters
           DISK_IO        : Disk I/O
           DISK_IO_INIT   : Disk I/O Initiation
           FILE_IO        : File system operation end times and results
           FILE_IO_INIT   : File system operation (create/open/close/read/write)
           HARD_FAULTS    : Hard Page Faults
           FILENAME       : FileName (e.g., FileName create/delete/rundown)
           SPLIT_IO       : Split I/O
           REGISTRY       : Registry tracing
           REG_HIVE       : Registry hive tracing
           DRIVERS        : Driver events
           POWER          : Power management events
           CC             : Cache manager events
           NETWORKTRACE   : Network events (e.g., tcp/udp send/receive)
           VIRT_ALLOC     : Virtual allocation reserve and release
           MEMINFO        : Memory List Info
           ALL_FAULTS     : All page faults including hard, Copy on write, demand zero faults, etc.
           MEMINFO_WS     : Working set Info
           VAMAP          : MapFile info
           FOOTPRINT      : Support footprint analysis
           MEMORY         : Memory tracing
           REFSET         : Support footprint analysis
           HIBERRUNDOWN   : Rundown(s) during hibernate
           CONTMEMGEN     : Contiguous Memory Generation
           POOL           : Pool tracing
           SHOULDYIELD    : Tracing for the cooperative DPC mechanism
           VTL_CHANGE     : VTL1 Entry and Exit
           CPU_CONFIG     : NUMA topology, Processor Group and Processor Index to Number mapping. By default it is always enabled.
           SESSION        : Session rundown/create/delete events.
           IDLE_STATES    : CPU Idle States
           TIMER          : Timer settings and its expiration
           CLOCKINT       : Clock Interrupt Events
           IPI            : Inter-processor Interrupt Events
           OPTICAL_IO     : Optical I/O
           OPTICAL_IO_INIT: Optical I/O Initiation
           FLT_IO_INIT    : Minifilter callback initiation
           FLT_IO         : Minifilter callback completion
           FLT_FASTIO     : Minifilter fastio callback completion
           FLT_IO_FAILURE : Minifilter callback completion with failure
           OB_HANDLE      : Object handle events
           OB_OBJECT      : Object events
           KE_CLOCK       : Clock Configuration events
           PMC_PROFILE    : PMC sampling events
           DPC_QUEUE      : DPC queue events
           CACHE_FLUSH    : Cache flush events
           DEBUG_EVENTS   : Debugger scheduling events
           HV_CALLOUTS    : NT Hypercalls into HyperV Events
    
    Kernel Groups:
           Base           : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+PROFILE+MEMINFO+MEMINFO_WS
           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
           FileIO         : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+FILE_IO+FILE_IO_INIT
           IOTrace        : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+CSWITCH
           ResumeTrace    : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+PROFILE+POWER
           SysProf        : PROC_THREAD+LOADER+PROFILE
           ResidentSet    : PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+MEMORY+MEMINFO+VAMAP+SESSION+VIRT_ALLOC
           ReferenceSet   : PROC_THREAD+LOADER+HARD_FAULTS+MEMORY+FOOTPRINT+VIRT_ALLOC+MEMINFO+VAMAP+SESSION+REFSET+MEMINFO_WS
           Network        : PROC_THREAD+LOADER+NETWORKTRACE
    
    Kernel flags and groups are the strings which can be used with "xperf -on " command - https://docs.microsoft.com/en-us/windows-hardware/test/wpt/start:
    So "base+interrupt+dpc" command option in OP is a combination of kernel flags:
    PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+PROFILE+MEMINFO+MEMINFO_WS + INTERRUPT + DPC

    where "latency" command option is a combination of flags:
    PROC_THREAD+LOADER+DISK_IO+HARD_FAULTS+PROFILE+CSWITCH+INTERRUPT+DPC

    You can see that both command options contain INTERRUPT and DPC flags.

    "-stackwalk" parameter is about the API functions calls - https://docs.microsoft.com/en-us/windows-hardware/test/wpt/stackwalk, so I do not know why it was used there.

    So the command "xperf -on base+interrupt+dpc" gives the same results as "xperf -on latency".
     
    Guru3Dmember likes this.
  15. Guru3Dmember

    Guru3Dmember Member

    Messages:
    49
    Likes Received:
    4
    GPU:
    6Gb

  16. Matrixqw

    Matrixqw New Member

    Messages:
    9
    Likes Received:
    0
    GPU:
    GTX 260 1GB
    I'm trying to check if the Interrupt Affinity Policy Tool has any effect.
    It adds the key DevicePolicy to regedit when I set a specific cpu and changes the policy to 'SpecifiedProcessors'.

    I changed ethernet to cpu 3.
    I'm not sure if I'm reading this right but the ndis.sys (network?) in the 'Interrupt Info' section shows that only cpu 0 has usec.
    Does this mean that the policy does nothing (for network at least) to change cpu interrupts ?
     
  17. mbk1969

    mbk1969 Ancient Guru

    Messages:
    11,135
    Likes Received:
    8,660
    GPU:
    GF RTX 2070 Super
    There are two tables for CPU usage in report - DPCs and ISRs. DPCs usually are spread across multiple CPUs. ISRs are usually isolated on CPU 0.

    It is hard to tell whether Interrupt Affinity Policy Tool deals with ISRs only or with DPCs only or with both. You can experiment with ndis.sys to see whether DPCs are affected by setting in Interrupt Affinity Policy Tool.
     
  18. EdKiefer

    EdKiefer Ancient Guru

    Messages:
    2,697
    Likes Received:
    283
    GPU:
    MSI 970 Gaming 4G
    If you want Interrupts across all cores try the setting in power plan "Interrupt steering settings> Interrupt steering mode = any unparked process.
    I tried this a yr ago and got pretty good spread across cores.

    I only tested the setting, I have it at default value now.

    PS: Use mbk1969 excellent tool PowerSettingExplorer.
     

Share This Page