Let’s do DHCP: diagnostic events

There is always something new to do with the DHCP server sample. Today we will look at how to add diagnostic events. After all, any good server technology intended to run in real world production scenarios needs observability.

One approach to achieve this would be to simply implement an EventSource class and be done with it. However, this is not ideal for many reasons. First, though EventSource is relatively agnostic to platform-specific concerns, it is still a specific technology typically targeted toward ETW tracing. As a result of its focus on shipping data out of process, EventSource imposes several restrictions on the data types which can be used. Finally, since the DHCP server is a library and not a framework, I believe it is more appropriate to provide diagnostics via user-controlled extensibility points.

The design I landed on was the use of extension methods to provide decorators which wrap and augment the base functionality with appropriate events. The diagnostic “events” themselves are simply methods on an interface corresponding to the base type. For example, this is how to get an augmented socket instance with events:

// client code
IPEndpointV4 endpoint = new IPEndpointV4(IPAddressV4.Loopback, 67);
ISocketEvents socketEvents = new MySocketEvents();
ISocket socketWithEvents = new DhcpSocket(this.endpoint)
    .WithEvents(1, socketEvents);
// . . .

// implementation code
class MySocketEvents : ISocketEvents
{
    public void SendStart(SocketId id, int bufferSize, IPEndpointV4 endpoint)
    {
        // . . .
    }

    public void SendEnd(SocketId id, bool succeeded, Exception exception)
    {
        // . . .
    }

    // . . . etc.
}

The chosen design rules are roughly as follows:

• An event corresponding to operation Xyz (or XyzAsync) has two interface methods: XyzStart and XyzEnd. This allows calculating durations from the resulting event stream, by subtracting precise timestamps of the correlated start and end events.
• The decorator implementations respect activity ID correlation by propagating the captured ID from the start to the end event.
• Every event has an object identifier (convertible to Int32) to record which instance the event is for.
• Start events carry useful information about all the input arguments, e.g. the buffer size for a Memory<T> value.
• End events carry the return value if appropriate, as well as two additional values: a Boolean succeeded flag and an Exception object if the operation threw.
• Events interfaces are provided only for types where a concrete implementation is provided by the library. In this sample, that includes ISocket, IDhcpInputChannelFactory, and IDhcpInputChannel. IDhcpReceiveCallbacks is not included, since that is a completely user-facing type with no implementation in the library — if you want events here, your implementation can provide them.

With these ground rules, it is very natural to write an EventSource integration layer for consumers who wish to do so. But it would be just as easy to use a completely different system such as Serilog. Or maybe you want performance counters instead? The point is that the interfaces impose no restriction on what you ultimately do as long as you follow the contract.

Now, to be clear, there are some costs that must be considered in such an implementation. The first is the amount of boilerplate and ceremony. It is just not completely straightforward in C# to implement a class that forwards all calls to an inner implementation, especially when you need to handle async behavior and potential exceptions. You can see all this for yourself in the Events namespace of the DhcpServer core library.

But really that is just a burden for the poor library author. What about cost in pay-for-use performance? As expected, there are overheads with wrapping Task-based methods, additional virtual dispatch on interface calls, and so on. To quantify it, I updated the receive loop benchmark to include the cheapest possible likely implementation — empty interface methods hanging off an empty EventSource class (using [NonEvent] since the signatures are not EventSource-compatible). The benchmark results are as follows:

|   Method |    N |     Mean |    Error |   StdDev |    Gen 0 | Gen 1 | Gen 2 |  Allocated |
|--------- |----- |---------:|---------:|---------:|---------:|------:|------:|-----------:|
|      Run | 1000 | 14.94 ms | 0.304 ms | 0.548 ms | 109.3750 |     - |     - |  892.19 KB |
| RunEvent | 1000 | 15.49 ms | 0.300 ms | 0.401 ms | 125.0000 |     - |     - | 1042.42 KB |

There is approximately 4% execution time and 17% allocation overhead. With some tuning we might be able to improve this but that is an exercise for a different time. In any case, the numbers we’re talking about are fractional microseconds and bytes per operation. I will call this an acceptable tradeoff for the high value benefit of flexible instrumentation.