Boost use monotonic clock as log timestamp

Question

I use this function to init logging with boost and it works well

void initBoostLog(std::string logfile)
{
  boost::log::add_file_log
    (
        boost::log::keywords::file_name = logfile,
        boost::log::keywords::auto_flush = true,
        boost::log::keywords::format =
        (
            boost::log::expressions::stream 
                << "[" << boost::log::expressions::format_date_time< boost::posix_time::ptime >("TimeStamp", "%Y-%m-%d %H:%M:%S.%f")
                << "] <" << boost::log::trivial::severity
                << "> " << boost::log::expressions::smessage
        )
    );
    boost::log::add_common_attributes();
    boost::log::core::get()->set_filter(boost::log::trivial::severity >= boost::log::trivial::info);
}

It gives log like this as output

[2020-07-29 16:07:20.726137] <info> My log starts
[2020-07-29 16:07:20.726619] <info> Next log line

But I want the clock to be the monotonic clock similar to this from standard C (what I rightly or wrongly call the system uptime)

struct timespec monotime;
clock_gettime(CLOCK_MONOTONIC, &monotime);
return (float)(monotime.tv_sec + monotime.tv_nsec/1.0e9);

So that log would log something like this

[1130.726137] <info> My log starts
[1130.726619] <info> Next log line

Boost offers a monotonic clock boost::log::detail::get_timestamp()

But I don't know now how to use it in the init of the boost log? How can it be used or can be solved in some other way?

My system is Ubuntu 16.04 arm64

Update after @sehe answer sehes' answer works like clockwork (pun intended!) the only thing I had to add was to set the precision in the stream. Otherwise I would only get 2 or 3 decimals (same code different Ubuntu 16.04 installations) like this

boost::log::expressions::stream 
<< "[" << std::fixed << std::setprecision(6) << boost::log::expressions::attr<double>("monoclock")
<< "] <" << boost::log::trivial::severity
<< "> " << boost::log::expressions::smessage

sehe · Accepted Answer · 2020-07-29T16:26:32.240

Boost offers a monotonic clock boost::log::detail::get_timestamp()

It's a bit misleading to say it "offers" that. It's expressly in a detail namespace so you cannot rely on it.

Is it monotonic?

It turns out that on POSIX the implementation is switched anyways:

#   if defined(_POSIX_MONOTONIC_CLOCK)

//! \c get_timestamp implementation based on POSIX monotonic clock
timestamp get_timestamp_monotonic_clock() {
    // ...
}

#       define BOOST_LOG_DEFAULT_GET_TIMESTAMP get_timestamp_monotonic_clock

#   else // if defined(_POSIX_MONOTONIC_CLOCK)
#       define BOOST_LOG_DEFAULT_GET_TIMESTAMP get_timestamp_realtime_clock
#   endif // if defined(_POSIX_MONOTONIC_CLOCK)

The switch only depends on _POSIX_MONOTONIC_CLOCK which is defined in unistd.h https://linux.die.net/man/3/clock_gettime

Availability

On POSIX systems on which these functions are available, the symbol _POSIX_TIMERS is defined in <unistd.h> to a value greater than 0. The symbols _POSIX_MONOTONIC_CLOCK, _POSIX_CPUTIME, _POSIX_THREAD_CPUTIME indicate that CLOCK_MONOTONIC, CLOCK_PROCESS_CPUTIME_ID, CLOCK_THREAD_CPUTIME_ID are available. (See also sysconf(3).)

So, yes it does use monotonic clock if available. (It does fall back to realtime if monotonic fails at runtime, which makes sense with ported binaries).

Is it used?

Yes. It's used in queued sinks, to dequeue new messages as per a "ordering window": That's not your format attribute, though.

How to make it work

Define your own attribute! We can use an adhoc formatting expression:

auto adhoc =
    expr::wrap_formatter([](boost::log::record_view const&, boost::log::formatting_ostream& strm) {
        struct ::timespec monotime;
        ::clock_gettime(CLOCK_MONOTONIC, &monotime);
        strm << std::fixed << std::setprecision(6) << (monotime.tv_sec + monotime.tv_nsec/1.0e9);
    });

When used:

boost::log::keywords::format = (boost::log::expressions::stream
     << "[" << adhoc << "] "
     << "<" << boost::log::trivial::severity << "> "
     << boost::log::expressions::smessage));

We get:

[768386.969232] <info> An informational severity message
[768386.969656] <warning> A warning severity message
[768386.969793] <error> An error severity message
[768386.969887] <fatal> A fatal severity message

See it Live On Coliru

Improvement suggestions

I called that ad-hoc, because actually it doesn't log the timestamp of the meesage, but rather the timestamp of formatting, which might significantly differ. In that respect, you may want to actually define a custom attribute which will be stored in the record, so you can format that instead.

Custom Attribute: `monoclock`

It turned out to be pretty simple: function objects as attributes.

static inline double get_monoclock() {
    struct ::timespec monotime;
    ::clock_gettime(CLOCK_MONOTONIC, &monotime);
    return monotime.tv_sec + monotime.tv_nsec/1.0e9;
}

All that's required to add the attribte to all records:

boost::log::core::get()->add_global_attribute("monoclock", attrs::make_function(&get_monoclock));

You're then free to use it in your formatters:

    boost::log::keywords::format = (boost::log::expressions::stream
         << "[" << expr::attr<double>("monoclock") << "] "
         << "<" << boost::log::trivial::severity << "> "
         << boost::log::expressions::smessage));

Again, Live On Coliru

[504214.461181] <info> An informational severity message
[504214.462371] <warning> A warning severity message
[504214.462405] <error> An error severity message
[504214.462433] <fatal> A fatal severity message

Full Listing