Log Duration time does not correlate with log TimeStamps

[sfuser3]

I'm seeing a significant discrepancy between the logged TimeStamps and the logged duration of the timed function. The following simple test program has a DurationLogger class whose ctor issues a START log (and registers the Duration attribute) and whose dtor issues a STOP log. The class has a logger member variable to which the START/STOP logs are sent:

$ cat logtest.cc 
#include <string>

#include <boost/core/null_deleter.hpp>
#include <boost/date_time/posix_time/posix_time.hpp>
#include <boost/log/common.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/sinks.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/log/trivial.hpp>
#include <boost/log/attributes/clock.hpp>
#include <boost/log/attributes/timer.hpp>
#include <boost/log/expressions/attr.hpp>
#include <boost/log/expressions/formatters/date_time.hpp>
#include <boost/log/expressions/formatters/stream.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>

namespace logging   = boost::log;
namespace src       = boost::log::sources;
namespace sinks     = boost::log::sinks;
namespace attrs     = boost::log::attributes;
namespace keywords  = boost::log::keywords;
namespace expr      = boost::log::expressions;

using namespace logging::trivial;

class DurationLogger
{
    DurationLogger();
    boost::log::sources::severity_channel_logger_mt<
        boost::log::trivial::severity_level,
        std::string >       lg_;
    std::string             name_;

public:
    DurationLogger(const std::string& name)
    :   lg_(keywords::channel = "my_duration_logger")
    ,   name_(name)
    {
        BOOST_LOG_SEV(lg_, trace) << name_ << " STARTED";
        lg_.add_attribute("Duration", attrs::timer());
    }

    ~DurationLogger()
    {
        BOOST_LOG_SEV(lg_, trace) << name_ << " STOPPED ";
    }
};

void work()
{
    DurationLogger timer1("timer1");
    DurationLogger timer2("timer2");
    boost::this_thread::sleep_for(boost::chrono::microseconds(10));
}

void logging_init()
{
    typedef sinks::synchronous_sink< sinks::text_ostream_backend > ConsoleSink;
    boost::shared_ptr< ConsoleSink > console_sink = boost::make_shared< ConsoleSink >();
    boost::shared_ptr< std::ostream > console(&std::clog, boost::null_deleter());
    console_sink->locked_backend()->add_stream(console);
    console_sink->locked_backend()->auto_flush(true);
    console_sink->set_formatter(
        expr::stream
            << expr::format_date_time< boost::posix_time::ptime >("TimeStamp", "%Y-%m-%dT%H:%M:%S.%f") << " "
            << "<" << expr::attr< attrs::current_thread_id::value_type >("ThreadID") << "> "
            << expr::smessage
            << expr::if_(expr::has_attr< boost::posix_time::ptime::time_duration_type >("Duration"))
                  [
                      expr::stream << " Duration=" << expr::attr< boost::posix_time::ptime::time_duration_type >("Duration")
                  ]
    );
    logging::add_common_attributes();
    logging::core::get()->add_sink(console_sink);
}

int main()
{
    logging_init();
    work();

    return 0;
}

$ g++ -o logtest -std=c++11 -DOS_LINUX -DOS_UNIX -D__EXTENSIONS__ -D_RWSTD_MULTI_THREAD -D_REENTRANT -D_THREAD_SAFE logtest.cc -L$BOOST/boost/linux64-x86 -lboost_log -lboost_system -lboost_date_time -lboost_thread -lpthread

$ ./logtest
2017-11-15T15:36:00.620317 <0x00007f3e8823c740> timer1 STARTED
2017-11-15T15:36:00.620526 <0x00007f3e8823c740> timer2 STARTED
2017-11-15T15:36:00.620741 <0x00007f3e8823c740> timer2 STOPPED  Duration=00:00:00.000086
2017-11-15T15:36:00.621019 <0x00007f3e8823c740> timer1 STOPPED  Duration=00:00:00.000503

$ g++ --version
g++ (GCC) 4.8.5 20150623 (Red Hat 4.8.5-16)

$ grep "define BOOST_LIB_VERSION" /usr/include/boost/version.hpp 
#define BOOST_LIB_VERSION "1_63"

Based on the TimeStamps, above, the expected Durations are:
1. 621019 - 620317 = 702us (rather than the indicated 503us)
2. 620741 - 620526 = 215us (rather than the indicated 86us)

I see even worse discrepancies when running multithreaded, but I have deliberately simplified the problem.

NOTE: I always see that timer1 takes longer than timer2, but I assume that's because timer1 waits for timer2 to complete its logging.

[sfuser3]

I've been looking at "Post awaiting moderation." for 24 hours. Anybody home?

[Andrey Semashev]

The discrepancy is caused by multiple reasons.

1. The timer starts counting when the attribute is created. In your code it happens after the first log record is fully processed, which means the time for the first record processing is mostly included in the timestamps span and not included in the timer. You can swap the attribute creation and the first log record and see that the timers start to register longer durations.
2. The timestamps and timer value are obtained separately. While this happens relatively close in time, Linux clocks are precise enough to register the different time points.
3. Your test time span is very short. You can increase the sleep duration and see that the timestamps and timers indicate roughly the same durations (or rather, the amount of discrepancy is insignificant compared to the measured duration). Sub-millisecond durations are difficult to measure reliably on a non-realtime system because there are many factors involved, like memory allocation, thread contention and IO latency.

If you're trying to benchmark some code using Boost.Log then consider either increasing workload (to increase the measured time durations and make the error insignificant) or use more specialized tools like measuring CPU cycles instead of reading system clocks.

[sfuser3]

The code presented in this post [which still cannot be seen, as it remains in quarantine], was contrived to be simple and yet demonstrate the discrepancy. In the actual application where these discrepancies were first identified, the durations are longer.

Rather than use Boost.Log's Duration attribute, I have achieved satisfactory results with the following RAII approach:

class ScopedLogger
{
    ScopedLogger() = delete;
    ScopedLogger(const ScopedLogger&) = delete;
    boost::log::sources::severity_channel_logger_mt<
        boost::log::trivial::severity_level,
        std::string >                              lg_;
    const boost::log::trivial::severity_level    level_;
    const std::string                            message_;
    const std::chrono::steady_clock::time_point  start_time_;

public:
    ScopedLogger(   const std::string& channel,
                    const boost::log::trivial::severity_level level,
                    const std::string& message)
    :   lg_(boost::log::keywords::channel = channel)
    ,   level_(level)
    ,   message_(message)
    ,   start_time_(std::chrono::steady_clock::now())
    {
        BOOST_LOG_SEV(lg_, level_) << message_ << " BEGIN SCOPE";
    }

    ~ScopedLogger()
    {
        std::chrono::steady_clock::time_point end_time = std::chrono::steady_clock::now();
        uint64_t elapsed_us = std::chrono::duration_cast<std::chrono::microseconds>(end_time - start_time_).count();

        BOOST_LOG_SEV(lg_, level_) << message_ << " END SCOPE, Elapsed=" << elapsed_us << "us";
    }
};

Using the above ScopedLogger, the calculated duration is typically within 150us of the TimeStamp delta -- even when substituting ScopedLogger for DurationLogger in the posted example:

$ ./logtest
2017-11-16T19:08:23.093979 <0x00007f6e2cf66740> timer1 BEGIN SCOPE
2017-11-16T19:08:23.094184 <0x00007f6e2cf66740> timer2 BEGIN SCOPE
2017-11-16T19:08:23.094419 <0x00007f6e2cf66740> timer2 END SCOPE, Elapsed=232us
2017-11-16T19:08:23.094499 <0x00007f6e2cf66740> timer1 END SCOPE, Elapsed=679us

[Andrey Semashev]

Functionally, your code is equivalent to the original one with timers. You can see it also has discrepancy in durations, though of slightly lower magnitude due to a bit less overhead. Enabling optimization may reduce the difference.

PS: Oddly, I'm not receiving notifications of posts requiring moderaion. It may be that this only happens to posts with code samples. I'm not using SF actively, but it wasn't like this before, so something has changed. Not sure how to fix it.

[sfuser3]

Thanks for your comments; they're much appreciated.

I'm not using SF actively, ...

If not SF, which forum would you recommend for Boost.Log related questions?

[Andrey Semashev]

If not SF, which forum would you recommend for Boost.Log related questions?

Posting here is fine, if it is convenient for you. I'm also following Boost developers mailing list, where you can post your questions with a "[log]" tag in the subject. You can also post on StackOverflow.