Quick Summary

This is just a short post that shows a real-life example of why it is often good to view the debug log and check things out in the debugger even when things seem to be working fine.

The Bug

Today I found a very small bug in some code with a very large impact (thankfully in our development environment).

Some Java code was mapping namespace strings to IDs.  It did this by:

• Checking a cache for the mapping.
• Checking the database for the mapping if it didn’t exist in the cache.
• Creating the mapping in the DB if it didn’t exist and putting it into the cache.

This had all been working great… until I refactored it to allow nested namespaces.  Suddenly, the namespace being used in the key wasn’t a string, it was an object!

We were building the cache key explicitly by adding the namespace to the value.  So, the fix was as simple as adding a toString() method to the new namespace class.  Without that, the toString() method had the instance reference, and every single item coming in was therefore unique!

So… effectively we got no caching and had our caches growing rapidly with useless data (the second part of which was somewhat okay as they were LRU caches).

 Finding the Bug

This bug definitely could have been found with unit tests had one been there.  But… one wasn’t. We noticed the bug when a consumer dumped millions of records of data against our environment and pointed out that it was vastly slower than it had been before.

It was still working in a way that got it past our general testing; it was just slower.

Once the consumer pointed this out, I turned on debug logging and immediately saw that every single record was incurring the overhead of 6 database calls, even though this should have stopped after the first thousand records or so triggered data caching.

Sending just one request against my IDE immediately showed that the cache key we were using was garbage as per the reasons noted above.

Lesson Learned!

It immediately occurred to me how silly it is that I no longer had debug logging on in my IDE.  Also, on top of that, it occurred to me how silly it is that I don’t habitually take 30 seconds to watch the new code execute in a debugger just to verify it does what I intended.

Again, unit tests would catch many of these situations… but some standard debug logging and debugger checks can definitely help to significantly limit errors in new code.