Introduction Samples

This wiki page assumes
The Introduction samples focus on features that Playback provides:
  • Heterogeneous sources
  • Concepts of time
    • Past history vs. real-time
    • Virtual vs. system time

Playback_All

In a dream world everyone would agree to trace to the same format...
In reality most software is built by slapping together components built by different people as per their contemporary fashions.

Example of minor detail is the fact that you can trace into .etl OR .evtx (Event Log).
Also tracerpt.exe allows you to convert .etl to .evtx file

... But wait, these files contains the same exact event occurrences!

Try commenting out the .etl or .evtx:
Try using Do {...} to see how events are duplicated in .etl and .evtx

Playback playback = new Playback();
playback.AddEtlFiles(@"HTTP_Server.etl");
playback.AddLogFiles(@"HTTP_Server.evtx");

IObservable<SystemEvent> all = playback.GetObservable<SystemEvent>();

using (all.Count().Subscribe(Console.WriteLine))
{
    playback.Run();
    Console.ReadLine();
 }

Here Playback transforms events into C# instances ... and deliberately loses unimportant details like the original format. What you get as output are all events in order of occurrence (see Playback conceptual model)

Playback_VirtualTime

The above sample counts all events, in all files.
This query will produce one single integer after all files are processed.

But what if we want to count events per window of time ... say 5 sec?
The subtlety here is that we mean 5 sec as per the timestamps on the events, which is not the same as counting events using system time:

Playback playback = new Playback();
playback.AddEtlFiles(@"HTTP_Server.etl");
playback.AddLogFiles(@"HTTP_Server.evtx");

IObservable<SystemEvent> all = playback.GetObservable<SystemEvent>();

var counts = from window in all.Window(TimeSpan.FromSeconds(5), playback.Scheduler)
    from Count in window.Count()
    select Count;

var withTime = counts.Timestamp(playback.Scheduler);

using (withTime.Subscribe(ts => Console.WriteLine("{0} {1}", ts.Timestamp, ts.Value)))
{
    playback.Run();
    Console.ReadLine();
 }

Here the Playback exposes a Scheduler that represents virtual time just like the TestScheduler in Rx.

The concept of "virtual time" is useful in two cases:
  • Temporal queries on past events from files (like above)
  • Temporal queries on real-time feeds, arriving with latency
    • Simplest example is ETW real-time session: because the events are buffered, the time you get the event in OnNext is different than the occurrence time.

Playback_HTTP

In this sample, we take ETW trace from the kernel layer of IIS. Here we took the simple case of serving two pieces of static content: helloworld.htm (small file) and windir.txt (big file)

The goal of the query is to create a histogram of request duration like this:

RequestDuration.jpg

The pseudo-code for the query is
  1. correlate pairs of start and end events with matching ActivityId
  2. produce one event per pair (=request), that contains the Url and duration
  3. aggregate into buckets based on duration

Here is the actual LINQ:

Playback playback = new Playback();
playback.AddEtlFiles(@"HTTP_Server.etl");

IObservable<Deliver> startEvents = playback.GetObservable<Deliver>();
IObservable<FastResp> endEvents = playback.GetObservable<FastResp>();

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

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

IDisposable d = statistics.Subscribe(b =>
{
    Console.WriteLine("--------------------------");
    foreach (var s in b.OrderBy(s=>s.Milliseconds)) // <-- LINQ to Objects!
    {
        Console.WriteLine(s);
    }
});

playback.Run();

Console.ReadLine();
d.Dispose();

This is example of non-temporal query:
  • It is about the whole file, and the result will be produced at the end of the file
  • It illustrates how to mix Rx (everything up to playback.BufferAllOutput(...)) and LINQ-to-Objects (the following "order by"

Playback HTTP VirtualTime

This query modifies the one above, to produce histogram every five seconds in virtual time:

Playback playback = new Playback();
playback.AddEtlFiles(@"HTTP_Server.etl");

IObservable<Deliver> startEvents = playback.GetObservable<Deliver>();
IObservable<FastResp> endEvents = playback.GetObservable<FastResp>();

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

var statistics = from window in requests.Window(TimeSpan.FromSeconds(5), playback.Scheduler)
                    from stats in
                        (   // calculate statistics within one window
                            from request in window
                            group request by new
                                {
                                    Milliseconds = Math.Ceiling(request.Duration.TotalMilliseconds * 10) / 10,
                                    request.Url
                                } into g
                            from Count in g.Count()
                            select new
                            {
                                g.Key.Url,
                                g.Key.Milliseconds,
                                Count
                            })
                            .ToList() 
                    select stats;

IDisposable d = statistics.Subscribe(b =>
    {
        Console.WriteLine("--------------------------");
        foreach (var s in b.OrderBy(s => s.Milliseconds)) // <-- LINQ to Objects!
        {
            Console.WriteLine(s);
        }
    });

playback.Run();

Console.ReadLine();
d.Dispose();


There are several things worth noting here:
  1. we are limiting how long are we going to wait for matching end event by .Take(TimeSpan.FromSeconds(1), playback.Scheduler)
  2. we are doing Window of 5 sec virtual time
  3. the output is a list - the histogram for the given window
  4. we sort this before display, using LINQ to Objects: b.OrderBy(s => s.Milliseconds)

Playback_RealTime

Usually, it is best to practice your queries on some past traces first. This way, you can repeatedly try different LINQ tricks without the data changing at the same time.

Once you made your mind on the query, it is trivial to switch it to real-time:
Playback playback = new Playback();
playback.AddRealTimeSession("tcp");

var recv = from req in playback.GetObservable<KNetEvt_RecvIPV4>()
            select new
            {
                Time = req.OccurenceTime,
                Size = req.size,
                Address = new IPAddress(req.daddr)
            };


using (recv.Subscribe(e => Console.WriteLine("{0} : Received {1,5} bytes from {2}", e.Time, e.Size, e.Address)))
{
    playback.Start();

    Console.ReadLine();
}


Note here:
  1. instead of .AddEtlFile we did .AddRealTimeSession with the session name (see the sessions with Perfmon)
  2. instead of calling Run(), which blocks the current thread until the processing is complete, we called Start()
  3. the using (or explicitly keeping the IDisposable is necessary to prevent the query from disappearing

Note that the choice between real-time vs. past and the choice between virtual-time vs. system time are orthogonal.

Playback Real-Time and Past

Finally, it is easy to start from past traces and then continue with real-time events as they occur:

Playback playback = new Playback();
playback.AddEtlFiles("tcp.etl");
playback.AddRealTimeSession("tcp");

var recv = from req in playback.GetObservable<KNetEvt_RecvIPV4>()
            select new
            {
                Time = req.OccurenceTime,
                Size = req.size,
                Address = new IPAddress(req.daddr)
            };


using (recv.Subscribe(e => Console.WriteLine("{0} : Received {1,5} bytes from {2}", e.Time, e.Size, e.Address)))
{
    playback.Start();

    Console.ReadLine();
}

Right now, the events from the file appear after one new event occurs.
The reason is that Playback actually does not make difference between past and real-time streams

It just merges them on timestamp, while preserving the order from each stream

Last edited Feb 7, 2013 at 12:30 AM by georgis, version 8

Comments

No comments yet.