Tracing exceptions - guidelines

(Don't know what Excel Services are? Find out!)

Since Excel Services (in the Microsoft Office Sharepoint Server 2007 product) is, well, a server product, we rely heavily on tracing when we debug or try to figure out what’s going on. Most servers and quite a few client applications use that. Our logging has proven to be incredibly useful and it sometimes happens that we figure out what is causing a bug simply by looking at a log without even having to reproduce the bug.

Among other things, our logging mechanism allows us to dynamically decide what level of debugging we want to do (verbose, medium, critical etc). It also allows us to ask only for specific categories or sub-categories. On shipping production servers, logging is set to a minimum – this is mainly so that there is no unnecessary performance cost if everything is going okay with the server.

The way it works for us (and I would guess in most logging solutions) is that you pass into your logging function the level you consider the log item to be, and whatever other information you want to control it by (in our case - categories and sub-categories). The logging function then looks at the runtime settings and decides whether or not it should actually log.

What made me post this entry, is a code review I did a while ago. I noticed that people tended to call ToString() or Message on exceptions before logging them. For the most part, logging just the Message property is not enough for good logs – one wants the most information possible. However, calling ToString() on an exception every single time has its own issues. To get a clear picture on this, our logging function looks something like this:

ULS.SendTraceTag(category, subcategory, text, params object[] args);

For example:

ULS.SendTraceTag(
Categories.ExcelService,
Categories.Session,
“An error has occurred – exception was: {0}”,
ex.ToString());

When the tracing infrastructure decides it actually needs to log the message, it will format the message with the passed in args (much like String.Format() does) and output it. What this in turn means, is that if you, as a developer, explicitly call ToString()on your exception, you will incur an unnecessary perf cost – you will actually build a whole callstack (and potentially multiple callstacks if you have inner exceptions). Depending on where this happens, it can have a devastating effect on your perf.

Instead, always pass the object itself to the function you call – make it do the work of calling ToString() if it will actually need to.