BT

Facilitating the Spread of Knowledge and Innovation in Professional Software Development

Write for InfoQ

Topics

Choose your language

InfoQ Homepage News Chronon 2.0 Offers Post Execution Logging

Chronon 2.0 Offers Post Execution Logging

This item in japanese

Bookmarks

Chronon Systems has recently released version 2 of their recording JVM debugger which allows for post execution logging.

Chronon is a recording JVM debugger that monitors systems in production, recording their internal state while active. Afterwards it can replay the application flow pin-pointing the exact cause of a bug. The Chronon time travelling debugger was already covered by InfoQ in a previous post.

Version 2 of the debugger supports post execution logging, meaning that programmers now can "insert" logging statements into code after the application has already run. Because Chronon does not actually run the application, but simply shifts it from one state into another, post execution logging has an extra advantage compared to traditional logging. The results are instant. Even if your program ran for 5 hours and you put a logging statement on a line that is normally hit after 4 hours, Chronon will instantly show you the results. There is no waiting for the issue to happen so that the log is triggered.

Logging levels in a running Java application are pre-defined and binding. While they can change on the fly even when a system is already running in production, any change only affects future logging statements. If a bug appeared when the log level was too high then logs have incomplete information. This forces programmers to include excessive logging into an application in order to catch most program states. The application is usually deployed with the maximum possible level (e.g. TRACE) and as it matures and programmers feel more confident, they decrease the verbosity of logging into a higher level (e.g. INFO).

This however has a heavy toll on production performance since logging in big enterprise applications can have noticeable impact. In the worst case scenario a serious error can manifest when the logging level has already been raised (e.g. to WARN) leaving developers with little or no clues with what happened. In this scenario they have to change the logging level again and attempt to reproduce the issue in the production system in order to capture meaningful log information.

However with post execution logging a programmer does not have to constrain the program to a specific level. This concept can be taken to the extreme by removing all logging statements altogether allowing for maximum performance.

InfoQ contacted Prashant Deva (CTO, Founder) for an explanation on how this works:

Chronon knows the entire state of your application at any point in time since it has recorded it in production. Using this information Chronon can look at any method/line of your code and tell you the exact time at which it was hit. When you put Post Execution Logging statements on a line, Chronon sees all the times at which that line was hit and gets the state of the program at that point in time. This way it can calculate the value of any variables or expressions you put in your logging statement. Since you can put logging statements on different lines of code, once it gets the results of the logging statements on each line, all it has to do is sort the results by time and you get a log output that is exactly 100% like if the log statements actually were present in your program when it was executing.

So essentially Chronon prints out what would happen if you had placed logging statements in the code for this particular recorded time period. This gives great flexibility to programmers because now they can insert logging statements anywhere into code, knowing that if they need additional information (lower level or more statements) after an issue has hit the production system, they can do so without redeploying/reproducing it again.

Prashant clarifies:

There are no gimmicks. The logging statements you put in are, in a sense 'executed', exactly as if they were actually present in code. For example, they know the thread on which they are being executed; if you put them on a line inside say an 'if' block and that line is hit only 5 times out of the 10 calls of that method, then the log output will only show 5 log statements.

More details on Chronon can be found in the official FAQ.

Rate this Article

Adoption
Style

BT