Defrag Tools #118 - PerfView Part 6

Sign in to queue

Description

In this episode of Defrag Tools, Vance Morrison joins Andrew Richards and Chad Beeder to discuss his performance analysis tool, PerfView. In part 6 of this series, we show how easy it is to add ETW events to your applications, and how these events can be seen in PerfView.

Resources:
Download PerfView from Microsoft Download Center
PerfView Tutorial on Channel 9

 

Embed

Download

Download this episode

The Discussion

  • User profile image
    androidi

    In Windows 7, stopping the tracing in many if not all ETW based tools caused HDD's to spin up. Is this still the case with Win 10?

    I used to like process monitor back when it didn't use ETW. Now it's a tool of last resort as it's so heavy - huge activity when you start it and then spins up the disks when you end it.

    I'd find out myself* but the Start Menu in 10 previews so far is not back to 7's usability so at this point I don't see much reason to upgrade because it's not much of an upgrade if you take a hit in usability of the most used Windows feature. Another concern is the "free edition" - well lets just hope there's a "good value" edition as well, just with less legal copy and without the features intended to make the free edition somehow profitable.

     

    * I have 10 in VM but the spin up problem does not occur in VM and you need a bunch of 3.5" hdd's to really notice it.

  • User profile image
    windev

    @androidi: Email me (defragtools@microsoft.com) -- I haven't seen this issue at all -- we should look in to it.

  • User profile image
    PerfectPhase

    We're in the processes of ripping out most of our logging that is based on Log4Net and implementing ETW with EventSource.

    The bit we're having difficulty getting our head round is how to route logging from shared components.   For example with have a bunch of NT services (ServiceA, ServiceB etc) that  that have a lot of common dependency's such as AssemblyA, AssemblyB etc.

    Back in the old Log4Net days we'd pass a common ILogger around and route to a log file for each service via configuration.  That way an error logged by AssemblyA running in ServiceB would be logged to ServiceB's log file.

    With ETW as the target of events is controlled by the attribute on the logging class, the runtime aggregation is a lot harder.

    We currently bouncing back and forth with each component logging to its own event source, aggregating the data after the fact, or implementing some DI trickery to route all the events from all the components to a single event source.  While the former is easier for the developers/IT staff to diagnose a problem has it's happing, the latter seems to be easier after the fact. 

    Our biggest stumbling block seems to be when we look at an event source in Event Viewer for an error a component logged, we don't know the process name, only it's ID and it seems impossible to build custom views in event viewer based of process name?

    Any advice on handling these types of systems?

  • User profile image
    Onurg

    @PerfectPhase: My conclusions are the same. Note that ETW and SLAB allows you to put filters based on process names (as long as you are on windows 8.1 or Server 2012 R2). However this is not sufficient either as there are many cases where process names are identical as in IIS processes.

    A bigger problem with ETW is that you have to know these EventSource name in advance if you are doing xml configuration. So you have 10 dlls each using 3 EventSources, boom suddenly you will have to maintain 30 names. Memorize them, deploy them...

     

    Considering above limitations we decided to stick with log4net as ETW while technically a superior and more advanced solution, it doesn't fit into standard enterprise application logging

  • User profile image
    treynash

    @PerfectPhase:@Onurg:

    This sounds like a job for WPA included in the Windows Performance Toolkit.  If you want to sort/pivot by process name/PID/thread, etc., then you need to make sure the information is in your trace to begin with.  You could add arguments to your events but that can be tedious and inefficient.  It would be easier to couple your events with events generated by the kernel provider.

    If you do so and you use WPA to view your events, you can drag the Generic Events graph into an analysis tab and use the tables to pivot things around nicely.  That way, you will get the fidelity you are after whereby you can filter by process name, PID, threadID, etc.

    You can even use the tables to pivot on arguments to your custom ETW events created by your EventSource derivatives.

    Vance wrote a related blog post here: https://blogs.msdn.com/b/vancem/archive/2013/08/10/wpr-wpa-support-for-viewing-system-diagnostics-tracing-eventsource.aspx

    These tools do have a learning curve, but once you get the hang of them, their power is virtually boundless.

    For example, if you know the GUID of your provider, you could start the trace as follows:
    xperf -on PROC_THREAD+LOADER -start MySession -on EF456B24-2DD3-4E9B-B619-18F96123EBC7:0xffffffffffffffff:0xff

    You would then stop the trace as follows:
    xperf -stop MySession -stop -d mytrace.etl

    You would then load mytrace.etl into WPA.exe and go to town.  The xperf command to start the trace starts two providers.  Yours and the kernel provider.  For the kernel provider, it is only asking for loader events (for symbols - if needed) and proc/thread events (so you can determine which thread was active when your event fired).  Be careful with those kernel flags!  If you enable too many, you'll create a fire hose of data.  The stop xperf command above stops both providers and merges the results into one ETL file.  There are many more options for xperf which allow you to control buffering, etc.

    Finally, if your start command looked like the following (note the 'stack' addition):
    xperf -on PROC_THREAD+LOADER -start MySession -on EF456B24-2DD3-4E9B-B619-18F96123EBC7:0xffffffffffffffff:0xff:'stack'

    Then you would also be able to see the call stacks at the point of your event firing. This is when PROC_THREAD information becomes essential.

    As a final point, if you have two ETL traces from two different providers captured at the same time, you can merge them into one ETL file using xperf -merge.

  • User profile image
    Magic​Andre1981

     treynash wrote

     

     

    Finally, if your start command looked like the following (note the 'stack' addition):
    xperf -on PROC_THREAD+LOADER -start MySession -on EF456B24-2DD3-4E9B-B619-18F96123EBC7:0xffffffffffffffff:0xff:'stack'

    using stack with custom eventsource Providers doesn't work when you only use the GUID. WPA Fails to load the manifest data and only displays Crimson:{GUID}.  

  • User profile image
    Vancem

    @androidi: ETW is not heavy weight necessarily, but if you ask it to do a lot it will use the hard drive a lot.    In particular if you want stack traces, it does do what is called 'merging' which involves finding all the DLLs that were in the trace and getting the PDB signatures (so you can find the PDBS) from the DLLs.   This does take 10s of sec and uses the hard drive.    However if you collect just a little, then it is very light.   This is independent of OS version. 

    @PerfectPhase: Your situation is complicated by the fact that you seem to wish your output to go to the windows event log (using channel attribute).   This mechanism is 'old style' where a eventSource 'knows' where it is logging (a particular place (channel) in the windows event log).   As you can see for complex situations, it is not as flexible as you would wish.   Your situation however is complex enough that it does not make sense to discuss it in the comments.  If you still care you can contact me at vancem@Microsoft.com and I can describe other options you have.  

    @Onurg: I don't properly understand your complaint, but something I did not talk about in the video is that EventSource can go to in-proc event listeners.   Thus if you REALLY like the way log4Net works, you can frankly pipe all the data from your eventSource to whatever logging mechanism you would like to use.   The advantage of this is that you can go to BOTH log4Net AND ETW (and frankly anywhere else), and code that does the logging does NOT KNOW what logging mechanism is used (thus you get dependency injection for 'free').    

    @MagicAndre1981: For what it is worth, the fact that stacks interfere with evnetSource decoding is a known bug in the WPA stack.   They are working on a fix.   You can use PerfView to work-around the problem in the short term.   They should have a fix reasonably soon.  

  • User profile image
    Magic​Andre1981

    the WPA.exe (10.0.9933.0 (fbl_awesome1501.150127-1606)) from the ADK for Win10 TP, still has the CRIMSON GUID issue for Eventsource stackwalking :'(

Add Your 2 Cents