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.0230 2382.8835 6.71%
2235.5306 2398.1216 7.27%
2236.2449 2386.4416 6.72%
2236.8529 2389.2090 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.4110 2398.3124 7.14%
2235.7398 2388.1340 6.82%
2262.3454 2380.0595 5.20%
2340.0243 2385.0553 1.92%
2249.3693 2383.6925 5.97%
2246.9835 2381.5070 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 ❤