The Real Cost of Logging

In order to manage today’s highly dynamic application environments, many organizations turn to their logging system for answers – but reliance on these systems may be having an undesired impact on the applications themselves.

The vast majority of organisations use some sort of logging system — it could log errors, traces, information messages or debugging information. Applications can write logs to a file, database, Windows event log, or big data store and there are many logging frameworks and practices being used.

Logging brings good insights about the application behavior, especially about failures. However, by being part of the application, logging also participates in the execution chain, which can have its disadvantages. While working with customers we often see the negative consequences when logging alone introduced the adverse impact to the application.

Most of the time the overhead of logging is negligible. It only matters when the application is under significant load — but these are the times when it matters the most. Think about Walmart or Best Buy during Black Friday and Cyber Monday. Online sales are particularly crucial for these retail companies during this period and this is the time when their applications are under most stress.

To better explain the logging overhead I created a lightweight .NET application that:

  1. implemented using ASP.NET
  2. performs lightweight processing
  3. has an exception built in
  4. exceptions are always handled within try…catch statement
  5. exceptions are either logged using log4net or ignored based on the test

In my example I used log4net as I recently diagnosed a similar problem with a customer who was using log4net, however this could be replaced for any other framework that you use.

Test #1

First, we set up a baseline by running an application when exceptions are not being logged from the catch statement.

 

Test #2

Next I enabled logging exceptions by logging those to a local file and running same load test.

As you can see not only is the average response time significantly higher now, but also the throughput of the application is lower.

The AppDynamics snapshot is collected automatically when there is a performance problem or failure and includes full call graph with timings for each executed method.

By investigating the call graph AppDynamics produces, we see that log4net method, FileAppender, renders error information to a file using FileStream. On the right you can see duration of each call and the most time was spent in WriteFileNative as it was competing with similar requests trying to append the log file with error details.

Test #3

I often come across attempting to make exception logging asynchronous by using ThreadPool. Below is how the performance looks like in this setup under exactly the same load.

This is a clever concept and works adequately for low throughput applications, but as you can see the average response time is still in a similar range as the non-asynchronous version, but a slightly lower throughput is achieved.

Why is this? Having logging running in separate threads means the resources are still consumed, there are less threads available, and the number of context switches will be greater.

In my experience logging to a file is exceptionally common. Other types of storage could introduce better performance, however they always need to be further tested and logging to a file is the easier solution.

Summary

While logging is important and helps with application support and troubleshooting, logging should be treated as part of the application logic. This means logging has to be designed, implemented, tested, monitored and managed. In short, it should become a part of full application lifecycle management.

How well do you understand the your logging framework and it’s performance cost?

 Take five minutes to get complete visibility into the performance of your production applications with AppDynamics today.

Users share their AppDynamics Lite for .NET Experiences

A week has passed since we officially launched our free version of AppDynamics Lite for .NET to the public, and so far its been garnering attention and positive reviews from the APM community. For example, someone from a major Canadian telecommunications company downloaded .NET Lite and informed us on how quickly they were able to gain value from using it.

We’re equally impressed and delighted that they’re heavily pushing our Lite product internally and on the path to becoming an AppDynamics Pro user. Even though we hear praises from customers often, it’s always satisfying to hear about our products delivering real, quantifiable results in under 24 hours.

We also received this blog review from another .NET Lite user just the other day. They deployed AppDynamics Lite to monitor their overall site performance called Everymarket.ru – an open e-commerce market that connects resellers with a community of buyers for products that are discounted when purchased in bulk. The users of Lite are also able to monitor the outbound web service calls to VK.com which is Russia’s version of Facebook to ensure outbound requests to the social site are responsive.

EveryMarket.ru Describes the Entire .NET Lite Experience

AppDynamics Lite looks nice and catchy. Right after installation we started to obtain information about our application and performance metrics immediately. The following screenshot nicely illustrates that there are some hidden errors occurring for three of the business transactions in the following list. We have actually seen these errors before, but it was quite hard to estimate their frequency and severity. Now it can be easily understood from this view here and on the Business Transactions view, though it is limited to only 20 transactions.

The first thing I did after the installation, I decreased the snapshot frequency from 100 to 50. It was more out of curiosity without much purpose. It’s nice to see the historical information about errors and requests presented on one screen. We then changed the default sorting “By timestamp” in order to see errors as they happened by recency.

In this case, the error in question didn’t involve a SQL query. The Bad Request details were quite simple and repeated what we could find in a set of stack trace logs. However, the main advantage for us is that AppDynamics can catch these errors and notify our team immediately by email. Once inside the tool, the information is well organized for faster root cause diagnosis.

In general I found it very useful that AppDynamics operates with business transaction logic. The semantic of transaction is easy to understand and one can have a detailed overview of a precise transaction. And of course the “red bar” matters. In case of many errors it is straightforward that “more red” means “look first”.

From two examples you can see that our .NET Lite users are able to install and run our product with ease while gaining insight into their application’s health and performance bottlenecks to improve upon for faster runtime. If you have a success story using AppDynamics Lite, please let us know!

AppDynamics for .NET is almost here!

When we launched AppDynamics Pro back in October 2009, it redefined the way organizations could monitor and manage the performance of their production Java applications. The feedback we’ve received to date can be summed up as “Simple, Smart, Powerful and easy to use.” Over the last decade, words like “simple” and “smart” were rarely associated with Application Performance Management (APM) solutions. Why? Because APM solutions were only as good as the users that configured them. For most organizations it was a full-time job just to keep their APM instrumentation, metrics, thresholds and alerts up-to-date so they could safely run in production, albeit with limited visibility because of overhead concerns.