Simple way to trace DPCs and ISRs

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

  1. mbk1969

    mbk1969 Ancient Guru

    Messages:
    9,815
    Likes Received:
    6,754
    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:
    9,815
    Likes Received:
    6,754
    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.
     
  3. Astyanax

    Astyanax Ancient Guru

    Messages:
    7,927
    Likes Received:
    2,652
    GPU:
    GTX 1080ti
    DPC and ISR values obtained during system load are invalid.
     
  4. mbk1969

    mbk1969 Ancient Guru

    Messages:
    9,815
    Likes Received:
    6,754
    GPU:
    GF RTX 2070 Super
    Why are you talking about obtaining DPC and ISR during system load?
     

  5. Astyanax

    Astyanax Ancient Guru

    Messages:
    7,927
    Likes Received:
    2,652
    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:
    9,815
    Likes Received:
    6,754
    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:
    9,815
    Likes Received:
    6,754
    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:
    9,815
    Likes Received:
    6,754
    GPU:
    GF RTX 2070 Super
    Have you used it?
     

Share This Page