Greetings -

I'd like to solicit feedback regarding logging interface options and my latest timing measurements.

If you have not already visited the online documentation for the prototype logging solution, and are so inclined, please visit:
https://dev.lsstcorp.org/trac/wiki/db/Qserv/ProtoLog

The above documentation is mostly complete but pertains only to the boost::format style interface. In this email, I describe two other interface options: a varargs/printf style interface and a streaming style interface.

For each of the interface styles, one would write logging statements like the following:

== boost::format style interface ==
int data = 99;
LOG("myLogger", LOG_WARN_LVL, "This is a warning about data = %d. So you have been warned!") % data;
LOG_WARN("This is a warning about data = %d. So you have been warned!") % data;

== varargs/printf style interface ==
int data = 99;
LOG("myLogger", LOG_WARN_LVL, "This is a warning about data = %d. So you have been warned!", data);
LOG_WARN("This is a warning about data = %d. So you have been warned!", data);

== streaming style interface ==
int data = 99;
LOG("myLogger", LOG_WARN_LVL, "This is a warning about data = " << data << ". So you have been warned!");
LOG_WARN("This is a warning about data = " <<  data << ". So you have been warned!");

An important measurement is the time required to execute a logging statement that does not meet the presently set threshold. That is, one might have a large number of fine-level logging statements throughout their code but would normally like these turned off. Ideally, the presence of these inactive logging statements would not add appreciably to the program's running time. These timing measurements should therefore be taken into consideration when choosing between the above interfaces.

Here are the average times required to run the logging statements similar to those above with the threshold set to LOG_ERROR_LVL such that they are all suppressed. (These measurements were made on lsst-dev03 in the absence of significant competing activity.)

== boost::format style interface ==
LOG(.....): 1.3us
LOG_WARN(.....): 120ns

== varargs/printf style interface ==
LOG(....): 1.0us
LOG_WARN(.....): 27ns

== streaming style interface ==
LOG(.....): 970ns
LOG_WARN(......): 26ns

First, you'll notice that the LOG(.....) statements are generally much slower than the LOG_WARN(....) statements. This is because the LOG(....) statements must look up the logger by name, which is the bottleneck of these logging operations. The LOG_WARN(....) statements, meanwhile, use the defaultLogger. Next, you'll notice that the LOG_WARN(....) statement for the boost::format style interface is ~4X slower than that for the varargs/printf or streaming style interfaces. This is due to the creation of the boost::format object. The creation of this object is also the reason for the longer timing associated with the boost::format style LOG(....) statement.

While the boost::format style is typically slower, it offers several advantages over the other logging interfaces. For starters, it provides type safety not present with the varargs/printf style interface. For example, one can do something like:
LOG_INFO("This is %1% example of a %2% safe statement with data = %3%") % 1 % "type" % 3.14;

In fact, even if classic formatting (e.g. %d) is provided, it is only treated as a suggestion by boost::format. boost::format also offers a number of formatting options not available via the varargs/printf style interface.

Note that while the streaming interface has limited formatting abilities, it also offers a level of type safety. For example, one could do something like:
LOG_INFO("This is " << 1 << " example of a " << "type" << " safe statement with data = " << 3.14);

The boost::format style interface offers other advantages as well. While it is *relatively* expensive to create the formatting object, once created it can be reused. For example, one can do something like:
LOG_FMT logFmt = LOG("myLogger", LOG_INFO_LVL, "This is iteration %d");
for (int i=0; i < 10; i++) {
    logFmt % i;
    logFmt.dump();
}

In the above example, if the logging threshold were set to LOG_WARN_LVL such that the statements from logFmt were suppressed, the average execution time for the body of the loop (on lsst-dev03) is about 21ns--faster than the other interfaces.

Finally, it is worth mentioning that the streaming interface is native to log4cxx. As such, this is the simplest implementation.

Each of the above interfaces involves its own set of macros and functions. Combining any or all of them would result (IMHO) in an overly-complex implementation. Ideally, we can choose to adopt one of the three.

I look forward to feedback.

-- Bill

########################################################################
Use REPLY-ALL to reply to list

To unsubscribe from the QSERV-L list, click the following link:
https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=QSERV-L&A=1