Ayende @ Rahien

Hi!
My name is Oren Eini
Founder of Hibernating Rhinos LTD and RavenDB.
You can reach me by phone or email:

ayende@ayende.com

+972 52-548-6969

, @ Q c

Posts: 18 | Comments: 82

filter by tags archive

How to mis-configure your production to dead crawl

time to read 2 min | 322 words

One of the things that I avidly subscribe to is that when you are building server applications, visibility into what the application is doing is key. If you don’t have visibility into the application, you are left in the dark, stumbling and alone.

NH Prof is a good example of how you make things much more visible to developers, but I am doing this in many other places, Rhino Service Bus is another example of how important it is to have visibility into what your servers are doing. Being able to see what is actually going on in your apps is priceless!

However, that does come at a cost. And a pretty steep one at that.

Logging is expensive. It is expensive to gather the data to log, it is expensive to actually log the data, in order to produce coherent logs in multi threaded environment, you need to perform synchronization, etc.

One of the most common performance problems that people run into is when they push their debug logging configuration to production. If we will look into NHibernate as a good example, if you set the log level to debug, you are going to get tens of thousands of messages just for the startup! And you are going to get hundreds and thousands of log messages for routine operations.

That is going to slow things down, considerably.

Production configuration management is a big topic, and it deserves its own post, but the impact of setting the log level too low in production cannot be stressed strongly enough.

Pay attention to this, or it will make you pay attention to it.

In one notable case, several years ago, we re-implemented a whole module in the application (significantly optimizing it) to get exactly zero benefit (well, negative benefit, actually) from the exercise, since the actual problem was slow logging database.

In another, we improved performance by over 60% by simply raising the log level from DEBUG to ERROR.


Comments

configurator

I strongly agree, but I have a question: as a person who's never had the pleasure of maintaining a big enough server system while it was in production (the only ones I've written had very low usage) - what do you log on production? I suppose you don't turn off logging entirely, do you?

Ayende Rahien

I am going to touch on that in a separate blog post

Bryant

A solution that has worked well for me is to aggregate logging messages and periodically flush them to the log. Of course- and you've indicated this above- the messages being batched in production are much less verbose than the development / test environments.

Mr_Simple

SmartInspect by Gurock Software. Logs all, very - very -very fast, viewer filters by threads, too many features to list. Nuff said.

Eyston

"visibility into what the application is doing is key"

That is one of the things I found interesting from your NDC talk where you mention SLA's and queues. Not necessarily logging, but still a glimpse inside your applications state.

Jan Willem B

The Rhino Service Bus link is broken (404).

Rafal

@Bryan

I don't know if you have used NLog for logging in your application, but NLog has some nice features that can help to keep both log messages and performance. For example, there's an async log target that writes messages to a log in a background thread, without slowing down threads that do the real work. There's also a caching target (I don't really remember the details) that collects thread's debug messages in memory and writes them all to log file if an exception occurs. If there's no exception thrown no debug messages are written - this way you can have debug information only for requests ending with an exception. And it has minimum overhead for non-logged messages.

mendicant

I recently converted a bunch of logging in an app from Debug.Trace to log4net since we actually needed the logs.

Long story short, turning logging from DEBUG to INFO took a reporting process down from about half an hour to about a minute and a half.

Chris Smith

Our stuff automatically sets all loggers to ERROR on deployment after precisely that cock up. It's even worse with the verbose logging in Spring.Net

Comment preview

Comments have been closed on this topic.

FUTURE POSTS

  1. The insidious cost of allocations - 5 hours from now
  2. Buffer allocation strategies: A possible solution - 3 days from now
  3. Buffer allocation strategies: Explaining the solution - 4 days from now
  4. Buffer allocation strategies: Bad usage patterns - 5 days from now
  5. The useless text book algorithms - 6 days from now

And 1 more posts are pending...

There are posts all the way to Sep 11, 2015

RECENT SERIES

  1. Find the bug (5):
    20 Apr 2011 - Why do I get a Null Reference Exception?
  2. Production postmortem (10):
    03 Sep 2015 - The industry at large
  3. What is new in RavenDB 3.5 (7):
    12 Aug 2015 - Monitoring support
  4. Career planning (6):
    24 Jul 2015 - The immortal choices aren't
View all series

Syndication

Main feed Feed Stats
Comments feed   Comments Feed Stats