Logging practices on running solver processes in Java

We implemented a java computer program that solves a certain mathematical problem. The program runs for a long time and produces a textual representation of the best solution found.

It was the opportunity to discover the importance of adopting two usually unnoticed components: the Simple Logging Facade for Java (SLF4J) and the Logback logging framework. By employing both components a step further than they were originally designed, we increased our coding, debugging, testing and validation productivity in means far away than expected for traditional logging. All benefits were nearly for free and required no additional coding.

Six important principles

We were looking for following important six principles to aid us while developing our computer program:

  1. Produce friendly human readable messages when run manually from the console, but not when integrated to the enterprise application.
  2. During test phase, optionally print relevant data and decisions when debugging or validating a certain module.
  3. Print progress messages that might be easily parsed by the enterprise application.
  4. Measure the execution time of relevant operations and print the results to be easily parsed by a profiling tool.
  5. At important checkpoints, print a data dump that allows restarting the calculation from this point on. Such data dump saves us from starting a prolonged calculation from scratch just to debug or test a late phase of the calculation.
  6. At the end of the execution, print one or more representations of the solution.

All these principles imposed great risks: polluting the program with functionality unrelated to its main purpose, increasing code complexity and increasing effort to maintain the additional functionality  However, the next topic shows that those risks were mitigated to nearly zero.

A clever logging configuration

We were pleased to discover that SLF4J and Logback endowed us with all principles nearly for free. By a clever choice of the logger hierarchy, and a proper Logback configuration, one may adjust the behavior of each principle according to each context the program run in. Further components from Logback Classic allow one to redirect data to virtually anywhere (as stdout, stderr, file, rotating files, sockets) by properly setting appenders and formatters.

Form our experience, we would recommend that, for each module of the java program, there should be a base logger and a child logger for each principle. For example, a module “A” might define loggers as described below:

  • Root logger:
    • When running the program manually, shall accept all messages. The appender prints all messages to stdout. We prefer adjusting loggers for each module or component individually to turn off messages that are not required.
    • For integration, we recommend a rolling file appender. Or a file that is unique for each execution. In a more advanced scenario, the calling application created the java program as a POSIX process. To follow the POSIX convention, the Logback configuration should write a copy of error messages to the stderr channel, too. This allows the calling process to parse the stderr channel for error messages and meta-data, and to provide adequate feedback to the user.
  • Logger A: The base logger associated to the module. As usual, this logger one may resort to this logger to print local data and decisions with trace or debug level, which relates to principle 2. Or to print warn, errormessages and exceptions. This logger also inherits messages form all child loggers, if they are not otherwise configured.
    • When running the program manually to test or validate this module, the logger is set to accept trace or debug level. A dedicated appender (with no additivity) might filter out messages to a separated file to prevent polluting the root logger with trace and debug messages.
    • During manual execution without testing or validation, this logger is set to accept info level. The root appender is inherited.
    • For integration, this logger is set to accept only warn and error levels. The root appender is inherited.
  • Logger A.h: Instead of printing human readable messages to stdout, the program shall use a special logger for this purpose, normally with infolevel. Relates to principle 1.
    • When running the application manually, a dedicated appender (with no additivity) filters out messages from this logger to the console (stdout).
    • For integration, this logger is just turned off to prevent polluting the parent logger with user messages.
  • Logger A.p: Used only to print progress messages, normally with infolevel. Relates to principle 3.
    • When running the application manually, a dedicated appender (with no additivity) filters out messages from this logger to the console (stdout).
    • For integration, assuming the calling application created the java program as a POSIX process, a dedicated appender (with no additivity) may filter out messages from this logger to the stdout channel, using a format that may be easily recognized and parsed. The calling application observes the stdout channel for progress messages and provides proper feedback to the user, as updating a progress bar.
  • Logger A.t: Used only to print execution time measures. Relates to principle 4.
    • When running the application manually for validation, a dedicated appender (with no additivity) filters out messages from this logger into a file to be analyzed later by a profiling tool.
    • Else, this logger might just be turned off or ignored to inherit the parent logger.
  • Loggers A.c.1, A.c.2, A.c.3…: Our convention establishes that each logger is used only once to output a set of data that constitutes a checkpoint of the module. Relates to principle 5. For our application, a complete XML document was written as only one log message.
    • When running the application manually, a dedicated appender (with no additivity)  may filter out messages from this logger into a file if we are interested in creating checkpoints.
    • Else, this logger might just be turned off. The parent logger A.C groups the loggers together, to easy turning them all off at once.
  • Loggers A.r.1, A.r.2, A.r.3: Similarly to the previous item, our convention establishes that each logger is used only once to output a set of data that constitutes the calculation result. Relates to principle 6. For our application, a complete XML document was written as only one log message.
    • When running the application manually, a dedicated appender (with no additivity)  may filter out messages from this logger into a file. There may be several loggers to print the same data, one for each supported representation (eg. html, text, xml).
    • For integration, assuming that the program was called as a POSIX process, the appender might write to stdout to be captured by the calling application.  Or write to a file that is read later by the calling application.

Further discussion

Extensive logging was one of the techniques applied to assure algorithmic correctness as early as possible (of course, combined with detailed unit testing and with assertions checking for invariants). Manual debugging would be nearly impracticable due to the complexity of data and the long execution time.

All output data and messages are leveraged through SLF4J, to allow arbitrary configuration of its behavior with Logback. No message is ever written directly to stdout or stderr. No data is ever written directly to a file or any other device.

In order to write checkpoints or result data, additional care must be taken. Data will be output as structured text (html or xml) or even as a binary stream. The formatter must not insert additional characters and write the message exactly as generated by the program.

Conclusion

We have shown how to take advantage of SLF4J and Logback to incorporate six important principles into our mathematical solver program. Those principles were used to increase productivity and to save time while debugging, testing and validating the application. Further, no additional code had to be written to support those important principles, but at the expend of a slightly more complex Logback configuration with several dedicated appenders.

ILOG OPL syntax highlighting for gEdit

This article offers the syntax highlighting definition file for gEdit 2.16.
Read more of this post

ILOG OPL cannot distinguish apples from oranges

I used to think about OPL that promotes obligatorily mathematical rigor as one would expect from a mathematical modeling language. I was misunderstood: it seems that OPL deludes itself when comparing apples and oranges. OPL still requires enhancements that address serious idiosyncrasies how the model is handled.

Read more of this post

On fixing CPLEX variable names generated by OPL

You wrote your OPL model for your important mathematical programming problem. But the result looks weird: the model just cannot produce such solution. The most desperate approach consists in diving though the mathematical programming model generated by OPL, checking each (in)equation one by one.

Here I describe some issues that happened while using the OPL Java interface to create the CPLEX model and to print out the mathematical programming model as a .lp file. And after days of frustration with this .lp printout, I found myself writing my own Java class that renames all CPLEX variables generated by OPL…

Read more of this post

OPL and Java: loading dynamic Linux libraries

When calling IBM ILOG OPL (Optimization Programming Language) from a Java application running on Linux, one will face some issues regarding loading dynamic OPL libraries. Typical error messages look like:

Native code library failed to load: ensure the appropriate library (oplXXX.dll/.so) is in your path.

java.lang.UnsatisfiedLinkError: no opl63 in java.library.path
java.lang.UnsatisfiedLinkError: no opl_lang_wrap_cpp in java.library.path
java.lang.UnsatisfiedLinkError: no cp_wrap_cpp_java63 in java.library.path
java.lang.UnsatisfiedLinkError: no concert_wrap_cpp_java63 in java.library.path

This article explains my considerations and some approaches how to fix it.

Read more of this post

OPL language: the battle of array declarations

The OPL Development Studio, created by ILOG (and recently acquired by IBM), provides tools based on the Optimization Programming Language. This tool intends to simplify the process of feeding data and model formulae to other ILOG optimization tools for mathematical programming and constraint programming.

Experience has been proven OPL to be extremely helpful as a compact and high level language for both data and model. Nevertheless, this language still reveals some constructs that are not well understood nor well documented.

For example, there are many pitfalls a novice developer will face on OPL while working with arrays. Here, and on subsequente articles, I will share some advices that would have been useful while I learned OPL.

Read more of this post