How can I see what my reactive extensions query is doing?
Another three years have passed, and I'm still using your idea. My version has now evolved as follows:
- Overload for choice of logging destination
- Log number of subscriptions
- Log 'downstream' exceptions from bad subscribers.
The code:
public static IObservable<T> Spy<T>(this IObservable<T> source, string opName = null)
{
return Spy(source, opName, Console.WriteLine);
}
public static IObservable<T> Spy<T>(this IObservable<T> source, string opName,
Action<string> logger)
{
opName = opName ?? "IObservable";
logger($"{opName}: Observable obtained on Thread: {Thread.CurrentThread.ManagedThreadId}");
var count = 0;
return Observable.Create<T>(obs =>
{
logger($"{opName}: Subscribed to on Thread: {Thread.CurrentThread.ManagedThreadId}");
try
{
var subscription = source
.Do(x => logger($"{opName}: OnNext({x}) on Thread: {Thread.CurrentThread.ManagedThreadId}"),
ex => logger($"{opName}: OnError({ex}) on Thread: {Thread.CurrentThread.ManagedThreadId}"),
() => logger($"{opName}: OnCompleted() on Thread: {Thread.CurrentThread.ManagedThreadId}")
)
.Subscribe(t =>
{
try
{
obs.OnNext(t);
}
catch(Exception ex)
{
logger($"{opName}: Downstream exception ({ex}) on Thread: {Thread.CurrentThread.ManagedThreadId}");
throw;
}
}, obs.OnError, obs.OnCompleted);
return new CompositeDisposable(
Disposable.Create(() => logger($"{opName}: Dispose (Unsubscribe or Observable finished) on Thread: {Thread.CurrentThread.ManagedThreadId}")),
subscription,
Disposable.Create(() => Interlocked.Decrement(ref count)),
Disposable.Create(() => logger($"{opName}: Dispose (Unsubscribe or Observable finished) completed, {count} subscriptions"))
);
}
finally
{
Interlocked.Increment(ref count);
logger($"{opName}: Subscription completed, {count} subscriptions.");
}
});
}
You can append this function liberally to your Rx operators while you are developing them to see what's happening:
public static IObservable<T> Spy<T>(this IObservable<T> source, string opName = null)
{
opName = opName ?? "IObservable";
Console.WriteLine("{0}: Observable obtained on Thread: {1}",
opName,
Thread.CurrentThread.ManagedThreadId);
return Observable.Create<T>(obs =>
{
Console.WriteLine("{0}: Subscribed to on Thread: {1}",
opName,
Thread.CurrentThread.ManagedThreadId);
try
{
var subscription = source
.Do(x => Console.WriteLine("{0}: OnNext({1}) on Thread: {2}",
opName,
x,
Thread.CurrentThread.ManagedThreadId),
ex => Console.WriteLine("{0}: OnError({1}) on Thread: {2}",
opName,
ex,
Thread.CurrentThread.ManagedThreadId),
() => Console.WriteLine("{0}: OnCompleted() on Thread: {1}",
opName,
Thread.CurrentThread.ManagedThreadId)
)
.Subscribe(obs);
return new CompositeDisposable(
subscription,
Disposable.Create(() => Console.WriteLine(
"{0}: Cleaned up on Thread: {1}",
opName,
Thread.CurrentThread.ManagedThreadId)));
}
finally
{
Console.WriteLine("{0}: Subscription completed.", opName);
}
});
}
Here's an example usage, shows a subtle behaviour difference of Range
:
Observable.Range(0, 1).Spy("Range").Subscribe();
Gives the output:
Range: Observable obtained on Thread: 7
Range: Subscribed to on Thread: 7
Range: Subscription completed.
Range: OnNext(0) on Thread: 7
Range: OnCompleted() on Thread: 7
Range: Cleaned up on Thread: 7
But this:
Observable.Range(0, 1, Scheduler.Immediate).Spy("Range").Subscribe();
Gives the output:
Range: Observable obtained on Thread: 7
Range: Subscribed to on Thread: 7
Range: OnNext(0) on Thread: 7
Range: OnCompleted() on Thread: 7
Range: Subscription completed.
Range: Cleaned up on Thread: 7
Spot the difference?
Obviously you can alter this to write to logs or to Debug, or use preprocessor directives to do a lean pass-through subscription on a Release build etc...
You can apply Spy
throughout a chain of operators. e.g.:
Observable.Range(0,3).Spy("Range")
.Scan((acc, i) => acc + i).Spy("Scan").Subscribe();
Gives the output:
Range: Observable obtained on Thread: 7
Scan: Observable obtained on Thread: 7
Scan: Subscribed to on Thread: 7
Range: Subscribed to on Thread: 7
Range: Subscription completed.
Scan: Subscription completed.
Range: OnNext(1) on Thread: 7
Scan: OnNext(1) on Thread: 7
Range: OnNext(2) on Thread: 7
Scan: OnNext(3) on Thread: 7
Range: OnCompleted() on Thread: 7
Scan: OnCompleted() on Thread: 7
Range: Cleaned up on Thread: 7
Scan: Cleaned up on Thread: 7
I'm sure you can find ways of enriching this to suit your purposes.