I was recently tasked with figuring out a way to performance test database calls being made via NHibernate to PostgreSQL. As far as I could find, NHibernate doesn't expose any really easy ways to intercept and manually log both the SQL and execution times for each query.

After a little more digging, I came across a handy lesser-known tool that allows you to easily proxy any interface, be it user-defined or from a third party library. This tool lives in the System.Reflection.DispatchProxy nuget package. With a little code, you can wrap any instance of a class that implements an interface with a proxy to not only log but also manipulate both arguments and returned data.

Example

Take this simple class and interface.

interface IHello
{
    bool SayHello(string name);
}

class Hello : IHello
{
    public bool SayHello(string name)
    {
        Console.WriteLine($"Hello {name}");
        return true;
    }
}

Nothing special, only one method exposed which takes a simple name parameter, writes out a string to the console and returns a bool indicating success.

Say, although contrived in this example, we wanted to record calls going to SayHello.

class HelloDispatchProxy<T> : DispatchProxy where T : class, IHello
{
    private IHello Target { get; set; }

    protected override object Invoke(MethodInfo targetMethod, object[] args)
    {
        // Code here to track time, log call etc.
        var result = targetMethod.Invoke(Target, args);
        return result;
    }

    public static T CreateProxy(T target)
    {
        var proxy = Create<T, HelloDispatchProxy<T>>() as HelloDispatchProxy<T>;
        proxy.Target = target;
        return proxy as T;
    }
}

This is our DispatchProxy, HelloDispatchProxy. Usage is pretty simple.

IHello hello = HelloDispatchProxy<IHello>.CreateProxy(new Hello());

The CreateProxy method calls Create<T> on the base abstract class to generate a proxy object for you. The target instance is then assigned to the Target property before returning the proxy cast to type T (IHello in this instance).

Any method that is then called on the proxied IHello instance will trigger Invoke(). It's your proxies responsibility to call the target method, pass through the parameters and return the result. In this method, you can do whatever you like, and you'll also have access to your original Target instance.

You can see a complete example of this over on my GitHub

With great power comes great responsibility

This allows you quite a lot of control, so be careful what you do with args and the returned result or you can cause some unexpected behaviour.

Performance testing

DispatchProxy lives under the System.Reflection namespace. Because of this, I was curious about what overhead is introduced by this approach. What better way to understand than to test it myself.

I set up a slightly over-engineered set of tests to give a raw comparison between calls to both an unproxied and proxied instance. I ran these multiple times to get an average before analysing the results.

    100000 W/O  100000 W    % Increase
    2233.023    2382.8835   6.71%
    2235.5306   2398.1216   7.27%
    2236.2449   2386.4416   6.72%
    2236.8529   2389.209    6.81%
    2239.9692   2402.4627   7.25%
    2227.0108   2367.0306   6.29%
    2237.8432   2384.8429   6.57%
    2233.5528   2392.8394   7.13%
    2238.411    2398.3124   7.14%
    2235.7398   2388.134    6.82%
    2262.3454   2380.0595   5.20%
    2340.0243   2385.0553   1.92%
    2249.3693   2383.6925   5.97%
    2246.9835   2381.507    5.99%
    2240.7711   2381.4675   6.28%
    2232.5296   2374.0465   6.34%
    2248.0095   2359.8636   4.98%
    2250.2518   2394.8422   6.43%
    2234.7757   2387.8114   6.85%
    2238.7645   2387.8047   6.66%


    0.00112245  0.001192661 6.27%

So on average, the execution took an extra 6 or so percent with just the introduction of the proxy. Bear in mind in this current state, the proxy is doing nothing useful at all, but this helps put into context the efficiency.

But if you were to add something slow like a blocking console write line in the proxy, the % increase shoots up from 6.27% to over 100%.

System.Console.WriteLine($"Going to call {targetMethod.Name}");

The most important part with the performance impact is what you decide to do in the Invoke method, something you'll need to benchmark yourself.

In all but the highest performance-critical applications, the overhead of the proxy itself is minor. If you take for example proxying 2-3 DB calls in the context of something like a HTTP web request or message handler the impact is negligible. In fact, in my testing with a real-world application, the numbers are within an acceptable margin of error even when tracing into an APM tool.

NHibernate & PostgreSQL

If you're specifically interested in collecting information from NHibernate as I was, you can do this by wrapping the IDBCommand in a custom driver implementation.

public class ProfiledNpgsqlDriver : NpgsqlDriver {
    public override IDbCommand CreateCommand() {
        var command = base.CreateCommand();

        if (ConfigurationManager.AppSettings["EnableDBTracing"]?.ToLower() == "true") {
            command = ProfiledDbCommandDispatchProxy<IDbCommand>.CreateProxy(command);
        }

        return command;
    }
}

You can access the command being executed from the target IDBCommand's Command property and record time etc. with a StopWatch. I went a step further and implemented the proxy as an IObservable<T> so I can handle it differently depending on the use case.

Wrap up

Hopefully, you found this interesting. Can you think of any good use cases for this, or have any comments? Would love to hear them ❤