SvcPerf's User's Guide

SvcPerf is tool for viewing or processing ETL's or live Windows ETW Sessions. SvcPerf is based of Tx for processing of events.

Quick Start

MainWindowScreenShot

Loading ETL Files

SvcPerf can load multiple ETL files. These can be viewed together. Time and clock skews are not handled and will require custom queries. The files can be loaded in the following ways.

  1. The File - Open dialog.
    • You can select the required ETL files. This will cause the currently loaded session to be unloaded.
  2. Start SvcPerf.exe with a command line to the file or directory you want to load the ETL’s from. [See Command Line Reference]

Note: SvcPerf is currently based of Tx and has a file count limit of 64.

Manifest

SvcPerf uses Manifests - an XML file-that defines all events that providers write along with their layout information. This will be used to format the events and type resolution for the events during query execution.

Loading a Manifest

Manifests can be loaded in the following ways.

  1. Using the Add Manifest under the Manifest Menu in the Main window.
  2. From the command line using the /m qualifier as follows [See Command Line Reference]
    • SvcPerf.exe /m:<Manifest1> /m:<Manifest2>

Event Statistics

Event type occurence statistics can be viewed by loading the ETLs and the corresponding manifest. This would give an overall distribution of events and a breakdown for levels as well.

EventStatsWindowScreenShot

Filtering Events

SvcPerf support dynamic filters. They are filters on the different fields of the raw ETW events. The below table gives a list of some filters that can be used. There are some special filters activity filter [See Activity Filtering] which will internally create a Guid type. You also have a RootActivityId filter which can be used for activity traversal.

Filter Mode Shortcut   Description
Source CTLR+SHIFT+F Filters are applied to the incoming event source. On files the underlying source stream would be filtered using the provided lamda expression.
View CTRL+ALT+F The source stream of events can be held in memory and filters applied on top of these. As these are processed in memory they are generally a quick filters. The same expression can be used to filter events at the source stream or in the currently loaded set.
Search CTRL+F This mode is case-insensitive text search on events loaded in the grid in the symbol/id/message fields.

Expression filters

In "SOURCE" of "VIEW" filter mode expression which evaluate to boolean as per System.Linq.Dynamic can be created. The column headers can be used as Property and a set of primitive type expressions are supported. Here are some examples

Filter Text or Action Description
Level<=3 Shows all errors and warnings in the logs by entering this as the filter.
Ctrl+Shift+E
in ID/PID/TID/Activity/Related Activity
Exclusion filters will add a exclusion expression
  • PID !=<VALUE>
Ctrl+Shift+C
in the activity or related activity cell
Adds a filter condition for the Activity. This filter shows events that have the activity present in the ActivityId field or the RelatedActivityId field as per the query. The guids don't need any curly braces or quotes and will be parsed. 
  • ActivityId=<GUID>
  • RelactedActivityId=<GUID>
Ctrl+Shift+C 
in PID or TID or ID or Symbol cell
Adds the appropriate filters for the events. The supported Filters are EventId(Id) ProcessId(PID) ThreadId(TID)
  • Id=<EventId>
  • Pid=<ProcessId>
  • Tid=<ThreadId>
F5 or Press Enter in the Filter text box Refreshes the grid and applies the filter specified.
Message.Contains("Exception") Messsage fields can be used as a string type and queried using standard string library functions.
<lambda> The filter supports Dynamic expressoins which is evaluated to a expression returning boolean.
  • Message.Contains("Transfer") && !Message.Contains("session")
  • Level <= 3 or Message.Contains("Exception")

Activity Filtering

The ActivityId field or the RelatedActivityId field can be used to filter the logs to the specific activity. The guids should not be enclosed in {} or "".

  • Multiple ActivityIds can be specified in the filter clause. Any event matching the activities will be a successful match.
    • ActivityId=GUID1 or ActivityId=GUID2
  • Activity Trees can be obtained by using the "RootActivityId" filter. This can be used to find all activites that originiated from the specified root and might have transfered to another activity.
    • RootActivityId=GUID1
ActivityFilteringScreenShot

Queries

These are basically "LINQ-to-ETW". It works both past history (.etl ) and live sessions. The subtle nuance in this analogy is that the LINQ queries are expressed in the temporal LINQ dialect of Tx. Playback is used to bind the file or session to the query and Dump() extension methods can be used to view realtime events from an Observable or IEnumerable. To do a full pass in the query use playback.BufferOutput(query) and playback.Run() which will populate the result into an enumerable.

Request Duration and Drilldown Window

This is used to identify slow requests from a large number of requests. A instance of a request can be thought of being made up of a start and stop event correlated using some technique like a field like ActivityId or threadId etc. The requests can then be grouped into buckets to get a distribution. The duration window can be used to do drill down analysis by dumping a DurationItem type.We first join on the fields that correlate the request like ActivityId

Free queries

SvcPerf can be used to execute free form queries that finally use the Dump() extension to output the result as tabular or graphical forms like histograms or performance counter like views or even generate causality diagrams.

Distribution

Events that can be correlated on keys like activity or related activity etc. can be used to derive performance metrics. One way would be to specify a Start Event and an End Event that corresponds to an activity. SvcPerf generates the query automatically by joining on the Activity. This would then use Tx to execute the query.

durationWindowScreenShot

Example Distribution Query

The following query joins on a Start Event (SessionAccepted) and an End Event(SessionRelease) on the activity to produce a distribution of events in 100 millisecond buckets over a tumbling window of 600 seconds. You can modify this query to join on the appropriate fields or change the buckets to the required distribution.

var startEvents = GetEtwStream<Microsoft.Etw.Microsoft_Workflow.SessionAccepted>();
var endEvents = GetEtwStream<Microsoft.Etw.Microsoft_Workflow.SessionReleased>();

var requests = from start in startEvents
                from end in endEvents.Where(e => start.Header.ActivityId == e.Header.ActivityId).Take(1)
                select new
                {                    
                    ActivityId = start.Header.ActivityId,
                    Duration = end.Header.Timestamp - start.Header.Timestamp
                };


var stats = from request in requests
            group request by new
            {
                Milliseconds = Math.Ceiling(request.Duration.TotalMilliseconds / 100) * 100,                
            }
            into g
            from Count in g.Count()
            select new
            {
                Milliseconds = g.Key.Milliseconds,
                Count = Count
            };

// Composition is also possible with LINQ-To-Objects.
// Here we want to wait for the streaming computation to end, and then sort the result

var durationItems = from s in playback.BufferedOutput(stats)
                    orderby s.Milliseconds
                    select new DurationItem
                    {
                        Count = s.Count,
                        Duration = s.Milliseconds
                    };
playback.Run(); // this does the sequence-compute, and fills up the above collection

durationItems.Dump();

Drill Down into Activity

Once the interesting bucket has been identified, the next thing to do would be to drill down into the bucket to find the activities. The following query shows how SvcPerf would get the activities that were in the 100 millisecond bucket.

  • Next find the activity in the main window using the ActivityId filter.
    • ActivityId=<GUID>

            

// QueryGenerated From Drill down. 
// To modify, copy this over and exectue in a new query window.
 
var startEvents = GetEtwStream<Microsoft.Etw.Microsoft_Workflow.SessionAccepted>();
var endEvents = GetEtwStream<Microsoft.Etw.Microsoft_Workflow.SessionReleased>();

var requests = from start in startEvents
                from end in endEvents.Where(e => start.Header.ActivityId == e.Header.ActivityId).Take(1)
                select new
                {                    
                    ActivityId = start.Header.ActivityId,
                    Duration = end.Header.Timestamp - start.Header.Timestamp
                };

var stats = from request in requests
                where (Math.Ceiling(request.Duration.TotalMilliseconds / 100) * 100) == 1100               
                select new { Activity = request.ActivityId };

var idQuery = from e in playback.BufferOutput(stats)
                select new { Id = e.Activity };
playback.Run(); // this does the sequence-compute, and fills up the above collection
idQuery.Dump();

        

Synthetic Performance Counters

You can create a synthetic performance counter out of correlated events. For example you can generate the average number of requests per second or average latency per second that you generally would get from a performance counter. The advantage is that you can generate distributions and do a detailed drill down into the requests where you see a performance degradation and also control the interval of the counter when doing this kind of post processing.

  • For a perf counter like chart use 2 special properties ValueX and ValueY.
PerfCounter

Simple Performance counters

You can generate simple counters to find out occurance statistics over time. A window can be used to select the sample time of the events.

var startEvents = playback.GetObservable<{StartEvent}>();
TimeSpan sampleTime = TimeSpan.FromSeconds({SampleTime});

var requests = from start in startEvents
    select start;

int index = 0;
var statistics = from window in requests.Window(sampleTime, playback.Scheduler)
from Count in window.Count()
select new 
    {
        ValueX = index++,
        ValueY = Count,
    };

statistics.Dump();

Request Duration Performance Counters

Here is an example where a counter is generated on the average request duration. The request duration is obtained by joining start and stop events and can be used to compute times across components or machines depending on the join.

var startEvents = playback.GetObservable<SessionAccepted>();
var endEvents = playback.GetObservable<SessionReleased>();
TimeSpan waitTime = TimeSpan.FromMinutes(1);
TimeSpan sampleTime = TimeSpan.FromSeconds(30);

var requests = from start in startEvents
                from end in endEvents
                    .Where(e => start.Header.ActivityId == e.Header.ActivityId)
                    .Take(waitTime, playback.Scheduler) // <-- Playback virtual time!
                    .Take(1)
                select new
                {
                    Duration = end.Header.Timestamp - start.Header.Timestamp
                };

int index = 0;
var statistics = from window in requests.Window(sampleTime, playback.Scheduler)
                        from a in window.Aggregate(new { Count = 0, Total = 0.0 },
					(acc, e) => new 
					{ 
						Count = acc.Count + 1, 
						Total = acc.Total + e.Duration.TotalSeconds 
					})
			let avg = a.Count > 0? a.Total/a.Count: 0
                        select new 
		{
			ValueY = avg , 
			ValueX = index++
		};

statistics.Dump();

Density Distribution and Histograms

If you want to see request distribution you can get the request time by corellating a start and stop and output only the duration values. You can use the raw values in a tabular format or let SvcPerf generate a simple distribution chart.

  • For generating a density distribution chart expose only one value through a special property - ValueY.
Histogram

Diagrams

You can generate sequence diagrams in SvcPerf to understand causality chains. SvcPerf's diagram generation object model can be used to draw out these from an ETL.

var d = new SequenceDiagram();
d.Title = "Hello Diagram";
var a1 = new SequenceItem("Hello");
var a2 = new SequenceItem("Diagram");
d.Add(a1);
d.Add(a2);

d.Connect(a1, a2,"Hi");
d.Connect(a2, a2,"Listen");
d.Connect(a2, a1,"Hi There");
d.Connect(a1, null,"");
d.Dump(); 
    
Diagram

Causality Activity Diagrams

The diagram generation model can be used to generate some causality activity diagrams which helps analyze activity flow.

CausalityActivityWalking

Here is an example to walk down an activity tree at a depth of 5 activities and max event count of 100. This traverses the event along the ETW's activity/relatedActivityId header values and draws out the activiti diagram.

//--------------------------------------------------------------------------------
// SequenceItem SequenceDiagram[string name]   - Indexer to sequence steps         
// public void Connect(SequenceItem from, SequenceItem to, string message = null)
//--------------------------------------------------------------------------------            

var q = playback.GetObservable<SystemEvent>();
Guid root = Guid.Parse("00000100-0000-0000-643d-42fb30bbcb01");
int activityDepth = 5;
int maxEvents = 100;

var  guids = new System.Collections.Generic.HashSet<Guid>();
guids.Add(root);
Func<Guid,Guid,bool> isValid = (activity, related) =>
            {
               if(guids.Count < activityDepth)
		{
                if (guids.Contains(activity))
                {
                    if (related != Guid.Empty)
                    {
			    guids.Add(related);			
                    }
                    return true;
                 }
		 }	
                return false;
            };

var t= from e in q where isValid(e.Header.ActivityId, e.Header.RelatedActivityId)
                 select new
        {
            Id = e.Header.EventId,
	     ActivityId = e.Header.ActivityId, 
	     RelatedActivityId = e.Header.RelatedActivityId
        };

var buffer = (from e in playback.BufferOutput(t) select e);
playback.Run();
var events = buffer.ToList();

SequenceDiagram diagram = new SequenceDiagram();
diagram.Title = "Http Activity";
var eventNames = (from s in playback.KnownTypes
                    let attr = (ManifestEventAttribute)s.GetCustomAttributes(false)
                                    .Where((e) => e is ManifestEventAttribute).FirstOrDefault()
                    where attr != null
                    select new
                    {
                        Id = attr.EventId,
                        //Opcode = attr.Opcode,
                        Name = s.Name
                    }).ToDictionary((e) => e.Id, (e) => e.Name);

int index = 1;

//var activities = (from e in events select e.ActivityId).Distinct().ToDictionary((e) => e, (e) => "Activity" + (index++));
var activities = (from e in guids select e).Distinct().ToDictionary((e) => e, (e) => "Activity" + (index++));
foreach(var values in activities.Values)
{
	var seq = new SequenceItem(values);
	diagram.Add(seq);
}

SequenceItem source = null;
SequenceItem to = null;

int count = 0;
foreach (var item in events)
{
    	if(count > maxEvents)
	{
		break;
	}
	string eventName = eventNames[item.Id];
	string name = activities[item.ActivityId];
    	source = diagram[name];
	if(item.RelatedActivityId != Guid.Empty)
	{
		diagram.Connect(source, 
				diagram[activities[item.RelatedActivityId]],
				eventName);
	}
	else
	{
		diagram.Connect(source,source,eventName);
        // To generate point events without connectors 
        // use null targets as shown below.
		//diagram.Connect(source,null,eventName);
	}
	count++;
}
diagram.Dump();

Realtime Sessions

Realtime event viewing can be used to see live events from a realtime session. You can use logman or xperf to create a realtime session. Realtime sessions can also be used in the query window as well if SvcPerf has be started in live session mode. Here is the command using logman to start a realtime session to capture WCF events for all keywords at verbose level.

logman.exe create trace WCFSession -rt -nb 2 2 -bs 1024 -p "Microsoft-Windows-Application Server-Applications" 0xffffffffffffffff -ets

Use SvcPerf to view the events by launching it with a /session parameter

SvcPerf.exe /session WCFSession /m  [manifestPath]

Make sure to stop the session once you are done.

logman.exe stop WCFSession -ets
Note:  Session operations require elevation and also if the session is not running SvcPerf may crash.

Here is an example of a TCP live session

LiveSession

Command Line Reference

The SvcPerf application has a number of commands associated with it, each with
its own set of parameters and qualifiers.  They are listed below.  Options that
are common to all commands are listed at the end.

-------------------------------------------------------------------------------
Usage: SvcPerf [InputFile ...]

  Will show the SvcPerf Viewer.

  Parameters:
    [InputFile ...]   Specify the input ETL file to view.

  Qualifiers:
    [-filter:STRING]  filter string that can be applied on the trace.

-------------------------------------------------------------------------------
Usage: SvcPerf -dump InputFile ...

  Dump events

  Parameters:
    InputFile ...     Specify the input ETL file to view.

-------------------------------------------------------------------------------
Usage: SvcPerf -session sessions [InputFile ...]

  Dump events

  Parameters:
    sessions          Specify session name to view.
    [InputFile ...]   Specify the input ETL file to view.

  Qualifiers:
    [-filter:STRING]  filter string that can be applied on the trace.
-------------------------------------------------------------------------------
Qualifiers global to all commands:

    [-verbose]        Output verbose logs.
    [-m:STRING,...]   Manifest files.
    [-q:STRING,...]   Linq query files.
        

ETW FAQ

http://social.msdn.microsoft.com/Forums/en-US/etw/thread/a1aa1350-41a0-4490-9ae3-9b4520aeb9d4

Contact

http://svcperf.codeplex.com/discussions

Last edited Jan 18, 2013 at 8:48 PM by sajay, version 6

Comments

No comments yet.