Transactional Logging
When do we add logging?
In order to analyze problems, developers tend to add additional logging information to the source code. There are different logging frameworks available, e.g.: log4j, log4net, EnterpriseLibrary Logging, … which provide an easy and extensible way to create log files. Logging offers additional insight into what’s actually going on in in the application when it is under load or when it is deployed in production without having a great impact on performance.
Why and when is Logging turned on?
When problems come up in a load-testing, staging or in the live environment, developers either provide a new version of the software including additional logging outputs or ask the Tester/IT Admin to turn up the log-level. The additional logging will then provide more contextual information about why a certain problem, e.g: performance problem or error occurred.
What’s the problem with logging?
There is a big downside of logging - which is the amount of data that is produced in a non-contextual manner. Once the log files are available for developers they need to be analyzed and correlated with other log files or other metrics that have been gathered by other tools used in the system, e.g.: load testing or monitoring solutions. Browsing through large log files – looking for log entries with particular timestamps and correlating those entries to certain events (performance or functional issues) usually takes a long time and not always result in the discovery of the root cause of the problem.
Transactional Logging: Getting the log information in the right context!
In order to improve root cause analysis based on log file entries log entries should be viewed based on a single transaction of the application, e.g.: a single page request or a click on a button. Knowing which transaction had a problem allows us to only focus on those log entries that are essential for the error analysis.
On the other side we should also be able to analyze certain log entries which indicate a problematic situation – and trace it to an individual transaction. This allows us to identify the transaction flow and why the transaction execution ended up in a problematic situation causing the log entry to be created.
dynaTrace captures log entries of the major logging frameworks along every transaction that is recorded. The log entries show up as PurePath nodes right at the location where the log messages have been created including the log message and severity. With this information its possible to analyze all log messages created for a single transaction – or identify those transactions that logged a certain message. The following image shows how to identify an individual transaction based on a certain log message.
Log Entries identified in a single PurePath
Conclusion
Developers spend a lot of time analyzing problems based on log file entries. Analyzing and correlating values to other measures is a tedious job and takes a lot of time. Offering log entries in the context of a single transaction (web request, user interaction, …) will speed up the root cause analysis.
Related posts:
- Extending Visual Studio with Transactional Tracing Visual Studio is the number one development environment for Microsoft...
- Boston .NET User Group: Load and Performance Testing: How to do Transactional Root-Cause Analysis with Visual Studio Team System for Testers I am going to present at the next Boston .NET...
- Extending Visual Studio Unit Testing with Transactional Tracing In my previous blog entry I wrote about how to...
It’s a good idea. I’ve downloaded the plugin and checked out the demos you posted; am waiting to see more.
This is not a new idea, even for Java, though. The most successful Java tool using this approach is perhaps jEdit, where you can write “macros” using a scripting language; the default language for jEdit macros is BeanShell, but you can use others. There are dozens of macros available, many of them contributed by the community.
Upside: people can contribute with less effort, and it takes pressure off the developer of the editor for new features.
Downside: in my experience, the biggest downside at least in jEdit’s case, was that scripts are somewhat slower than compiled Java. For any script that gets executed while the UI is being used, you can get tiny pauses when a script is fired, which can make the UI feel sluggish if too much is based on scripts. Also, since scripts were so easy to write, I found people spent less time creating reusable libraries (to write scripts on top of) and there was a certain amount of duplication between them.
Looking forward to seeing what you do with it.
Patrick
Very interesting.
Just wandering how your correlate the transaction cross JVMs, for example the web tier and the business logic tier.
We have a technology called PurePath which allows us to trace calls across runtimes and across technologies. Check out the PurePath page on our website: http://www.dynatrace.com/en/purepath_technology.aspx