none
Detailed execution profiling of custom kernel mode driver RRS feed

  • Question

  • Hi all.  We have a custom wdm USB audio driver that I'd like to profile.  I'm most interested in the URB completion processing code which runs at IRQL_DISPATCH.  I run an app that uses the driver, but I don't seem to be able to isolate the driver's usage statistics.  I understand that calls to / from the driver may be from several different processes including the system process.  Is there a way to group all of the activity for just my driver (module) ?

    Friday, September 19, 2014 1:23 PM

All replies

  • The WPT will allow performance profiling of a driver, look at the documnentation for XPERF.  You can use kernrate if this is an older driver and pre-Win8 version of Windows.   They should both show activity in your driver.


    Don Burn Windows Filesystem and Driver Consulting Website: http://www.windrvr.com

    Friday, September 19, 2014 1:40 PM
  • Hi Don and thanks.  I'm currently testing on Win8.1 but can switch to WIn7.  The driver is an Avstream driver but its built with WDK8.1 / vs2013r3.  There seems to be "one weird trick" required to get xperf running on > Vista, no? 

    Friday, September 19, 2014 1:52 PM
  • Xperf should run fine.  I will admit I am biased towards the older kernrate, because I have used it for years, and I prefer text files I can store and compare to GUI's. 

    If Xperf is not running what is the failure mode?


    Don Burn Windows Filesystem and Driver Consulting Website: http://www.windrvr.com

    Friday, September 19, 2014 1:57 PM
  • Ok.  Xperf is working on the WIn7 machine.  I'm primarily interested in uncovering hotspots in our existing driver and comparing the performance in those hot paths with previous versions of the driver.  Any advice or examples you could point me towards would be greatly appreciated!

    -Wade

    Friday, September 19, 2014 2:35 PM
  • The most important thing you can do is to saturate your driver, i.e. send data to it as fast as possible to load significantly.  One of the challenges of drivers is they may appear to be performing slowly, but when you run XPERF you find the driver is only taking a small percentage of the CPU time.

    If your driver is saturated then also look at the calls to the various locking routines, if you see a significant percentage of CPU time in something like a spinlock then you have a good indicator your locking model needs to be reworked.


    Don Burn Windows Filesystem and Driver Consulting Website: http://www.windrvr.com

    Friday, September 19, 2014 2:46 PM
  • Hi Don.  Thanks for the info.  Makes perfect sense.  I guess I was asking more about what info to gather in the trace itself, i.e what the xperf command line.  I guess the hard part is figuring out how to order the data in WPA and which columns / groups etc give the best insight.  I guess because the driver's activity is spread across many threads it makes it more difficult to see exactly whats happening in JUST the driver.

    And to make matters worse, I assume since the driver is a miniport, ks.sys is actually the driver Im interested in, when it calls into my miniport code that is.  That is to say that I don't even see a "module" entry in the trace for my driver,; only for ks.sys which has calls into my miniport.

    Anyway, I guess this is as answered as it'll get.

    Thanks again1 

    Friday, September 19, 2014 3:14 PM
  • Again prefacing with I am not a major XPERF user, I would think you would see your module.  KS.sys and your module should both be profiled.  By chance are you looking at some of the tracing based data, which is only for the Microsoft modules?  This might explain why your module is not present, but for the general performance profiling it certainly should be present.


    Don Burn Windows Filesystem and Driver Consulting Website: http://www.windrvr.com

    Friday, September 19, 2014 3:28 PM
  • Hi Don.  It is confirmed.  My driver xxx.sys is NOT in the list of modules, but I know its loaded and active.

    i used:

    xperf -on latency -stackwalk profile

    Friday, September 19, 2014 4:33 PM
  • In WPA? What list of loaded modules? Do you mean the list of providers?

     -Brian


    Azius Developer Training www.azius.com Windows device driver, internals, security, & forensics training and consulting. Blog at www.azius.com/blog

    Sunday, September 21, 2014 4:15 AM
  • Hi Brian. What I mean is that my .sys file (module) is not visible alongside the other modules like usbport.sys, ks.sys etc. I can however see some calls into it in the call stacks of a thread using ks.sys. In wpa I've tried CPU usage (precise) and CPU usage (sampled) wth no appreciable difference. Does the fact that it's an avstream miniport matter do you suppose?
    Sunday, September 21, 2014 3:07 PM
  • No, the fact that it is avstream is irrelevant. The reason it isn't showing up much is either the sample time was too short, or your driver just wasn't doing much. You should be exercising your driver heavily while capturing the trace.

     -Brian


    Azius Developer Training www.azius.com Windows device driver, internals, security, & forensics training and consulting. Blog at www.azius.com/blog

    Sunday, September 21, 2014 7:32 PM
  • Hi Brian.  That's what I thought.  As for loading the driver, it was streaming audio, dealing with URB completions, KS_IOCTLs, etc so I don't believe that's the issue as it was about as busy as it ever gets.  Streaming was started right after the performance trace was started, allowed to run for about 10 seconds, then stooped before the performance trace was stopped.  i.e. xperf -d.

    We have a user-mode .dll that ASIO-aware audio apps use to communicate with our avstream  driver.  It is listed along with all the other modules (except our avstream.sys ;(   ) and most of the calls into ks.sys and eventually into our driver originate there.  I see a few calls into our driver from the system process, specifically the URB completions.

    I can post exported trace info or the trace if that helps.

    Tuesday, September 23, 2014 1:01 PM
  • You should read up on how WPR/WPA works, and watch some of the videos. Clearly, you are getting data about your driver. If you're not getting the data that you want, you need to either lengthen or modify your test, or capture more appropriate data. You should also instrument your driver with ETW events.

    This is a little dated, but worth checking out: http://blogs.msdn.com/b/pigscanfly/archive/2009/08/06/stack-walking-in-xperf.aspx

    Here is another useful link on looking at stack traces. It too is a little dated, but it should help: http://blogs.technet.com/b/askpfeplat/archive/2014/02/03/becoming-an-xperf-xpert-part-7-slow-profile-load-and-our-very-first-stack-walk.aspx

     -Brian


    Azius Developer Training www.azius.com Windows device driver, internals, security, & forensics training and consulting. Blog at www.azius.com/blog



    • Edited by Brian Catlin Wednesday, September 24, 2014 1:29 AM Add another link
    Tuesday, September 23, 2014 10:18 PM