none
A simple trace method RRS feed

  • General discussion

  • Tracing OnNext, OnError, OnCompleted, Subscribe and Dispose

    Usage example:

    Observable.Interval(100).Trace("Interval").Take(2).Trace("Take").Count();

    Take1: Subscribe()
    Interval1: Subscribe()
    Interval1: OnNext(0)
    Take1: OnNext(0)
    Interval1: OnNext(1)
    Take1: OnNext(1)
    Take1: OnCompleted()
    Take1: Dispose()
    Interval1: Dispose()

    Implemetation:

    public static class ObservableTrace
    {
        public static IObservable<TSource> Trace<TSource>(this IObservable<TSource> source, string name)
        {
            int id = 0;
            return Observable.Create<TSource>(observer => 
            {
                int id1 = ++id;
                Action<string, object> trace = (m, v) => Debug.WriteLine("{0}{1}: {2}({3})", name, id1, m, v);
                trace("Subscribe", "");
                IDisposable disposable = source.Subscribe(
                    v => { trace("OnNext", v); observer.OnNext(v); },
                    e => { trace("OnError", ""); observer.OnError(e); },
                    () => { trace("OnCompleted", ""); observer.OnCompleted(); });
                return () => { trace("Dispose", ""); disposable.Dispose(); };
            });
        }
    }
    
    Monday, November 30, 2009 6:27 AM

All replies

  • Nice, I like it. 
    Monday, November 30, 2009 2:36 PM
  • This is very cool - thanks for sharing! Hmm... I wonder if you could employ a similar mechanism to this to automatically create marble diagrams.
    Monday, November 30, 2009 7:48 PM
  • I rewrote it to automatically log based on the method you pass in:

        public static IObservable<TOut> Trace<T1, TOut, TIn>(this IObservable<TIn> source, 
          Func<IObservable<TIn>, T1, IObservable<TOut>> operation, T1 arg1) {
          int id = 0;
          return Observable.Create<TOut>(observer => {
            int id1 = ++id;
            Action<string, object> trace = (m, v) => Console.WriteLine("{0}{1}: {2}({3})", operation.Method.Name, id1, m, v);
            trace("Subscribe", "");
            IDisposable disposable = operation(source, arg1).Subscribe(
                v => { 
                  trace("OnNext", v); observer.OnNext(v); 
                },
                e => { 
                  trace("OnError", ""); observer.OnError(e); 
                },
                () => {
                  trace("OnCompleted", ""); observer.OnCompleted(); 
                });
            return () => { trace("Dispose", ""); disposable.Dispose(); };
          });
        }

    Should be pretty easy to expand it to more arguments. Call it by using:

          var y = Observable.Range(1,100).Trace(Observable.Throttle, 1);
    • Edited by Aaron Friel Tuesday, December 1, 2009 2:59 AM Betterer whitespace.
    Tuesday, December 1, 2009 2:58 AM
  • My current trace implementation is only a simple printf debugging.
    A more advanced implementation could replace the Debug.WriteLine with the Scenario class from MSDN Code Gallery. This uses ETW events (Event Tracing for Windows). The Parallel Extensions uses this technique in the current version too. The Event Trace Log can be viewed in the Visual Studio 2010 Concurrency Profiler or in XPerfView in a graph or table view.

    The name parameter in Trace is the identifier for the probe point of the data flow; it must not be the last operation name.

    Friday, December 4, 2009 9:47 AM
  • Very nice.

    Another useful debugging mechanism is to insert a Do into your code. However that does not allow you to intercept OnError and OnCompleted. We should add overloads for that so that you can easily define Trace in terms of that.
    Friday, January 22, 2010 4:07 PM
  • Hi,

    That's a really nice idea, but I'd prefer if it used the built-in tracing mechanisms in .NET.  That way you could register any trace listener that you wanted, including EventLogTraceListener and ConsoleTraceListener.  This would make a nice addition to Rx.

    Usage Example:

    using System;
    using System.Diagnostics;
    using System.Linq;
    
    namespace ReactiveProgrammingConsole
    {
      class Program
      {
        static void Main()
        {
          Trace.Listeners.Add(new ConsoleTraceListener());
    
          var oncePerSecond = Observable.Interval(TimeSpan.FromSeconds(1));
    
          var ob = oncePerSecond
            .TakeWhile(value => value < 5)
            .Concat(Observable.Create<long>(subscriber =>
              {
                subscriber.OnError(new Exception("Error!"));
                return () => {};
              }));
    
          using (ob.Trace().Subscribe(
            onNext: _ => { }, 
            onError: ex => Console.WriteLine(ex.Message)))
          {
            Console.ReadKey();
          }
        }
      }
    }
    


    Source Code:


    using System;
    using System.Diagnostics.Contracts;
    using System.Linq;
    
    namespace ReactiveProgrammingConsole
    {
      public static class ObservableEx
      {
        public static IObservable<T> Trace<T>(this IObservable<T> source,
          string nextFormat = "{0}", string errorFormat = "{0}", string completedMessage = "Completed")
        {
          Contract.Requires(source != null);
          Contract.Requires(nextFormat != null || errorFormat != null || completedMessage != null);
          Contract.Ensures(Contract.Result<IObservable<T>>() != null);
    
          return Observable.CreateWithDisposable<T>(subscriber =>
          {
            return source.Subscribe(new TraceObserver<T>(subscriber, nextFormat, errorFormat, completedMessage));
          });
        }
      }
    
      public class TraceObserver<T> : IObserver<T>
      {
        private readonly bool traceNext, traceError, traceCompleted, passThrough;
        private readonly string nextFormat, errorFormat, completedMessage;
        private readonly IObserver<T> subscriber;
    
        public TraceObserver(string nextFormat)
        {
          Contract.Requires(nextFormat != null);
    
          this.nextFormat = nextFormat;
    
          traceNext = true;
        }
    
        public TraceObserver(string nextFormat, string errorFormat)
          : this(nextFormat)
        {
          Contract.Requires(errorFormat != null);
    
          this.errorFormat = errorFormat;
    
          traceError = true;
        }
    
        public TraceObserver(string nextFormat, string errorFormat, string completedMessage)
          : this(nextFormat, errorFormat)
        {
          Contract.Requires(completedMessage != null);
    
          this.completedMessage = completedMessage;
    
          traceCompleted = true;
        }
    
        internal TraceObserver(IObserver<T> subscriber, 
            string nextFormat, string errorFormat, string completedMessage)
        {
          Contract.Requires(subscriber != null);
    
          this.subscriber = subscriber;
          this.nextFormat = nextFormat;
          this.errorFormat = errorFormat;
          this.completedMessage = completedMessage;
    
          passThrough = true;
          traceNext = nextFormat != null;
          traceError = errorFormat != null;
          traceCompleted = completedMessage != null;
        }
    
        public void OnNext(T value)
        {
          if (traceNext)
            System.Diagnostics.Trace.TraceInformation(nextFormat, value);
    
          if (passThrough)
            subscriber.OnNext(value);
        }
    
        public void OnError(Exception error)
        {
          if (traceError)
            System.Diagnostics.Trace.TraceError(errorFormat, error);
    
          if (passThrough)
            subscriber.OnError(error);
        }
    
        public void OnCompleted()
        {
          if (traceCompleted)
            System.Diagnostics.Trace.TraceInformation(completedMessage);
    
          if (passThrough)
            subscriber.OnCompleted();
        }
      }
    }
    


    - Dave
    http://davesexton.com/blog
    Friday, January 22, 2010 7:04 PM
  • Hi,

    When using ConsoleTraceListener you may find that a lot of extra information is outputted with each line, such as the name of the program and the type of the event.  To keep things simple, you can register the following custom TraceListener instead:

    class SummaryConsoleTraceListener : ConsoleTraceListener
    {
      public override void TraceEvent(TraceEventCache eventCache, string source, 
        TraceEventType eventType, int id, string message)
      {
        WriteLine(message);
      }
    
      public override void TraceEvent(TraceEventCache eventCache, string source,
        TraceEventType eventType, int id, string format, params object[] args)
      {
        WriteLine(string.Format(format, args));
      }
    }

    - Dave
    http://davesexton.com/blog
    Friday, January 22, 2010 7:34 PM
  • Very nice. Makes me think that we should create some kind of "Rx Power Toys". What do you think, should we set up a codeplex site where people can post their Rx extensions?
    Saturday, January 23, 2010 6:40 AM
  • Hi,

    Yes, I'm sure lots of us would like to contribute and CodePlex would be a great location.  I think somebody else suggested starting an Rx Contrib project on CodePlex in a different thread.  I'm partial to the name "Rxx" myself ;)

    - Dave
    http://davesexton.com/blog
    Saturday, January 23, 2010 7:47 AM
  • “Rx Power Toys” on codeplex would be very nice.

    To intercept OnCompleted or OnError I could use Finally or I could use Materialize with Notification. In some cases I want additionally intercept Subscribe, for example in the case of Repeat.
    The Trace method should take an Action parameter like Do. In the Marble Diagram Generator (http://code.msdn.microsoft.com/MarbleGenerator, my Rx Power Toys candidate) I use the trace method to construct the diagram; a TraceListener would not general enough. For a production environment I would prefer Event Trace for Windows. ETW has significant better performance, can trace millions of events in real-time, can switched on and off online, contain precise time and thread information and the trace can analysed online and offline by software (machine readable).

    Sunday, January 24, 2010 4:25 PM
  • Hi Steffen,

    > To intercept OnCompleted or OnError I could use Finally or I could use Materialize with Notification.

    You certainly could, but a single call to Trace() is much easier, is it not?  Perhaps sometimes I'd even prefer a more compositional approach:

      ob.TraceNext("Value: {0}").TraceError("Error: {0}").TraceCompleted("Done!").


    > In some cases I want additionally intercept Subscribe, for example in the case of Repeat.

    I'm not sure what you mean.  I think that's exactly what the Trace method does when used immediately before Subscribe.  For example:

      ob.Trace().Subscribe(...)

    Of course, if you want to use tracing within the functions that you pass to Subscribe, then just use the System.Diagnostics.Trace class.


    > The Trace method should take an Action parameter like Do.

    I see, this is meant to control exactly how tracing is accomplished for the OnNext method?  That would definitely be useful.  For example, when a value's ToString method isn't going to output anything interesting.  But accepting an Action is not the correct choice, it should be a Func<T, string>.

       ob.Trace(value => value.SomeUsefulProperty.ToString()).Subscribe(...)

    This also made me think it would be great to have an overload of Trace that accepts a TraceSource.  That will keep things consistent and highly configurable.

    For those unfamiliar with this, tracing in .NET is controlled by sections in the web.config/app.config file; this is important because it provides more than just logging - it provides instrumentation.  By passing in a TraceSource to the Trace method I could then instrument my application by configuring a TraceSwitch and a TraceLevel for that source, thereby having full control over the trace output in specific places that I choose.  For example:

      ob.Trace(myTraceSource, "Value: {0}", "Error: {0}", "Completed")

    In the application's config file, I can configure myTraceSource to have any TraceListeners that I choose.  I can also deploy the app with a trace level of Error.  When an end-user then reports a problem for which the error information is not enough, I can flip the switch in the configuration to Verbose and see output for OnNext and OnCompleted as well without having to rebuild or deploy anything.


    > A TraceListener would not general enough. For a production environment I would prefer Event Trace for Windows.

    Actually, it's quite the opposite.  The entire purpose of TraceListener is to be general.  You could easily create an ETW trace listener, or just borrow the one from here:

    http://msdn.microsoft.com/en-us/library/ms751538.aspx

    Personally, though, I prefer to use the Windows Event Log and I think it's the best choice for most real-world apps.  Regardless, the point of TraceListener, and TraceSource for that matter, is that you can control exactly what you want your application to do wtih trace output.

    - Dave
    http://davesexton.com/blog
    Sunday, January 24, 2010 7:32 PM
  • Hi,

    Based on the aforementioned ideas being discussed I've just updated the source code to include several enhancements to support functions and TraceSource, as well as the original string formatting overloads.

    The code is much larger now so I'm not going to post it.  If anybody wants it please let me know.  Hopefully I'll be able to contribute it when/if a CodePlex project is created.

    - Dave
    http://davesexton.com/blog
    Sunday, January 24, 2010 8:53 PM
  • Hi Dave,

    >ETW:
    I mean tracing with ETW like the new Concurrency Profiler and Visualizer in Visual Studio 2010, http://msdn.microsoft.com/en-us/library/dd537632(VS.100).aspx and not tracing strings.

    > intercept Subscribe:
    In the sample with Repeat there are 2 Subcribe outputs. This outputs are not possible with only Do or Materialize.
    Observable.Range(0, 2).Trace("T").Repeat(2). Subscribe();
    T1: Subscribe()
    T1: OnNext(0)
    T1: OnNext(1)
    T1: OnCompleted()
    T2: Subscribe()
    T1: Dispose()
    T2: OnNext(0)
    T2: OnNext(1)
    T2: OnCompleted()
    T2: Dispose()

    Tuesday, January 26, 2010 10:08 AM
  • Hi Steffen,

    >ETW:

    I'm not familiar with ETW on that level yet.  From what I've read though it seems just like performance counter functionality with some really nice graphs built-in to VS.  Perhaps performance counters in .NET share a common API with ETW on Vista and later OSs.

    I definitely see some value in having extension methods for performance profiling in Rx, but I think there's a big difference between performance profiling and logging/instrumentation.  The Trace methods should be for logging and instrumentation only, IMO.  Applications I've written rely very little on custom performance counters, yet commonly use logging and instrumentation (ideally) so I wouldn't want to conflate them into one API.


    > intercept Subscribe:

    Ah, I see now.  Your Trace implementation outputted a line for each new subscription.  I didn't notice that part in your code.

    I can see how that might be useful, but I'm not sure I like it being output by default.  I've already updated my Trace implemetnation (not posted here) to support a more compositional approach (optionally), as mentioned before.  Therefore, perhaps a separate method for tracing subscriptions would be more appropriate:

        ob.TraceSubscribe().Subscribe(...);

    - Dave
    http://davesexton.com/blog
    Tuesday, January 26, 2010 11:02 AM
  • I just created the "Rx Power Toys" page on CodePlex with the first sub project ObservableTrace.
    http://RxPowerToys.codeplex.com/
    Please send your CodePlex registration name if you want to create a sub project for the Rx Power Toys.
    Friday, January 29, 2010 3:31 PM
  • Hi Steffen,

    it is wonderful that you started the PowerToys project! It could be a good way for the Rx comunity to join forces. I would also like to contribute code to the RxPower Toys. I already tried to reach you using the codeplex web form. My codeplex user-account name is "blueling".

    Andreas
    Sunday, January 31, 2010 12:04 AM