Mining for gold in your log files

Once you’ve already learned the ins and outs of a library, it may seem obvious how it should be used (and which parts should be avoided). The thing is that, from one project to the next, we often make use of new and different libraries and frameworks and may not appreciate some of the more subtle differences among those technologies.

The better frameworks out there will log all kinds of information, often telling you when you’re using them incorrectly. So don’t just think of log files as something only relevant for production. There are nuggets in there that can really help you in development as well.

Look at your log files at regular intervals. Doing that from time to time and, even better, automating it, can save you from headaches even before you release your products into production. Eventually, this practice will not only prevent bugs but it can also dramatically improve performance in certain cases. NHibernate, for example, logs a lot of helpful information at various log levels. Look at the following simple method using NHibernate. Imagine this code would be called hundreds of times. We can actually save up to 50% database load by looking at the log files and making a small change.

void StoreEntity(EntityData data, ISession session, Guid dataId)  {
    ...
   session.SaveOrUpdate(new Entity { Id = dataId, SomeProperty = data.SomeProperty });
   ...
}

While running the code above, you’d detect the following warning in your log files:

2015-05-08 09:28:40,547 [45] WARN NHibernate.Engine.ForeignKeys [(null)] <(null)> - Unable to determine if Entity with assigned identifier 79ddf583-fccc-4814-a1dc-a492009c3105 is transient or detached; querying the database. Use explicit Save() or Update() in session to prevent this.

Let me summarize the contents of this message for you. NHibernate is telling us that it couldn’t determine the state (transient or detached) of the object of type Entity that we attempted to save in the StoreEntity method. Therefore, to determine whether NHibernate needs to create an INSERT or an UPDATE statement, it first needed to query the database for the existence of the identifier …c3105. NHibernate goes even further and tells us how we can resolve that situation by calling either Save() or Update(). That’s what I call a helpful log message!

We can verify that by analyzing what is happening on the SqlServer.

Figure 1 - Before

Analyzing the code flow that called the StoreEntity method shows that we are only saving new entities. So the code should only generate INSERT statements and never UPDATE statements. Let’s change the code above from SaveOrUpdate to Save, as NHibernate suggests:

void StoreEntity(EntityData data, ISession session, Guid dataId)  {
    ...
   session.Save(new Entity { Id = dataId, SomeProperty = data.SomeProperty });
   ...
}

The results on the SqlServer:

![After] 2
Figure 2 - After

As you can see, we just halved the number of statements we are issuing to the database. All the SELECT statements are gone, just by following a recommendation in our log files.

Did you know that NServiceBus has these same kinds of helpful log messages? For example, if you have enabled the outbox, NServiceBus checks if the MSDTC service is still running on the machine, the endpoint is running on, and gives you the following hint:

WARN NServiceBus.Features.Outbox.DtcRunningWarning We have detected that MSDTC service is running on your machine. Because you have configured this endpoint to run with Outbox enabled we recommend turning MSDTC off to ensure that the Outbox behavior is working as expected and no other resources are enlisting in distributed transactions.

That log entry tells you that you still have the MSDTC service running on the endpoint’s machine and the outbox feature is enabled. The purpose of the outbox feature is to have similar delivery guarantees to the ones we have with MSDTC without having to feed the DTC monster. By turning the off the service, you avoid potential escalation to the so-called two-phase commit protocol and the latency overhead associated with it. Again, another performance improvement!

Back to NHibernate. It has even more of these nuggets built-in. Consider the following example:

WARN NHibernate.Cache.ReadWriteCache An item was expired by the cache while it was locked (increase your cache timeout)…

That log entry tells us, in the case of using a second level cache, we just had a cache miss in our system. A cache miss means that the next transaction will load the object from the database. The log message, again, gives us a hint as to what we could do: increase the cache timeout to avoid potentially unnecessary queries to the database, improving performance.

I only showed you a few examples with NHibernate and NServiceBus, looking just at the WARNING log level. Be sure also to check your log files for the INFO and DEBUG levels. Surely you want to capture potential performance hits before they occur in production, right? Check your log files and you’ll find nuggets!

For more background around MSDTC and the outbox feature here is some reference material

• Transactions in NServiceBus
• Transactions and Message Processing
• MSDTC on Technet
• Is MSDTC a big resource drain?
• The outbox
• The outbox and NHibernate

About the author: Daniel Marbach is a solution architect at Particular Software, Microsoft Integration MVP, coach and passionate blogger.