Timestamps for logs

[nilsnolde]

I’d like to add timestamps to the processing logs of the various commands. I didn’t look into the code base yet, not sure if the logging is centralized, so it’d be quick to add, or it needs a logging abstraction.

We had some issues lately where custom PBFs take a whole longer to pass through osrm-contract. Timestamps would help to see in which phase of the pipeline it’s hanging. And it’s general good practice IMO. Shout out if any objections/thoughts.

[SiarheiFedartsou]

At glance it looks like it will be as easy as modifying this Log class.

osrm-backend/include/util/log.hpp

Line 56 in be35363

template <typename T> inline Log &operator<<(const T &data)

We can try https://github.com/fmtlib/fmt to implement timestamp formatting btw.

[nilsnolde]

Thanks, that was what I hoping for:)

[SiarheiFedartsou]

Here is draft #6375
How it looks now for osrm-extract:

I still see some logs which have no timestamps though and also not sure we need one more dependency because of it, but fmtlib is nice library(and actually is the same as std::format from C++20)

[SiarheiFedartsou]

I still see some logs which have no timestamps though

This ok, after is the "end" of Collecting traffic signal information on 2292 signals....

We use UnbufferedLog to output it

osrm-backend/src/extractor/extraction_containers.cpp

Line 1196 in be35363

util::UnbufferedLog log;

I.e. if some other logs are happening in the middle(like these warnings in this case) they are "interleave" logs coming from this UnbufferedLog, tbh I'd stop using this.

[SiarheiFedartsou]

Current log system is prone to race conditions, i.e. if we are doing something like:

util::Log() << "Hello, " << "OSRM";

we have no guarantee that log will be outputted "atomically", instead we may have it interleaved by some another log happening in another thread.

What about refactoring it a bit to something like:

util::Log::info("{} {}", "Hello, ", "OSRM");

This way we will be able to guarantee that logs are "atomic".

@mjjbell @nilsnolde would appreciate your opinion here

[nilsnolde]

I.e. if some other logs are happening in the middle(like these warnings in this case) they are "interleave" logs coming from this UnbufferedLog, tbh I'd stop using this.

Yeah, I agree, those could easily be refactored to use standard logging. No need for the "ok, after.. " bit if we have timestamps IMO (if it's not ok, it'll throw right). What doesn't take more than a second is not worth measuring time on anyways;)

What about refactoring it a bit to something like:
I'd put it in an issue, unless you really want to tackle it now:) It's true, but hasn't ever been reported or observed I think?

Thanks a ton for this @SiarheiFedartsou ! I'll immediately try your branch on our PBFs!

[nilsnolde]

Or we report down to milliseconds? Could do "22-09-23" instead to save some space?

[SiarheiFedartsou]

Or we report down to milliseconds? Could do "22-09-23" instead to save some space?

Not sure I got it, but timestamps I output in this PR are precise up to second.

[nilsnolde]

Sorry that wasn't too clearly worded..

What I meant: we can get rid of UnbufferedLog in multi-threaded functions, I agree. There's some spots where it makes sense, e.g. when printing progress (in %) in single-threaded processes.

But all the instances where it's printing it's busy with some processing and then later it adds "ok, after .." on the same line and reports the duration down to nanoseconds, they can be removed IMO (esp if they're running in multiple threads). Then, if we add timestamps which go down to milliseconds, I think that's all the resolution one needs (and we can add another line saying
<whatever_process> done if we wanna be explicit).

What do you think @SiarheiFedartsou ? I'd like to help out, but got a weird error building tbb with ENABLE_CONAN=ON..

[cmake] [ 58%] Building CXX object src/tbb/CMakeFiles/tbb.dir/observer_proxy.cpp.o
[cmake] [ 60%] Linking CXX shared library ../../gnu_12.2_cxx11_64_release/libtbbbind_2_4.so
[cmake] /usr/bin/ld: error: /usr/lib: read: Is a directory
[cmake] collect2: error: ld returned 1 exit status

I'm on Arch Linux, gcc 12.2.0, ld 2.39. Any clue?

EDIT: with clang 14.0.6 it fails with a similar but slightly different way:

[cmake] [ 58%] Building CXX object src/tbb/CMakeFiles/tbb.dir/private_server.cpp.o
[cmake] [ 60%] Linking CXX shared library ../../clang_14.0_cxx11_64_release/libtbbbind_2_4.so
[cmake] [ 63%] Building CXX object src/tbb/CMakeFiles/tbb.dir/profiling.cpp.o
[cmake] /usr/bin/ld: read in flex scanner failed
[cmake] clang-14: error: linker command failed with exit code 1 (use -v to see invocation)

I also have the issue with ld not linking properly on Arch, I can try again with Ubuntu 22.04 later.

[SiarheiFedartsou]

I also have #6219 (comment) with ld not linking properly on Arch, I can try again with Ubuntu 22.04 later.

yeah, I would try on Ubuntu. I’ll probably try to build it in some Arch-based docker image one day - may be will find something.

And, yeah, agree about your “nanoseconds” point :)

[nilsnolde]

It's ok for me, there's now and then projects where I have to Ubuntu instead, I have it in dual-boot. But thanks for the offer. I'm really happy to see you pushing things again with @mjjbell !

There weren't many occurrences of UnbufferedLog where it's problematic. In fact, you found the only user-facing one:) Others will be mangled with Debug Logs in a very similar way, but IMO Debug is fine. Not that it's a huge deal anyways, I did a few changes here based on your branch: https://github.com/Project-OSRM/osrm-backend/compare/sf-log-timestamp...gis-ops:osrm-backend:nn-log-timestamp-cleanup?expa

Milliseconds is more trouble than it's worth. The C++20 spec says it should print milliseconds when using :%S format specifier, but fmt doesn't (yet). Since we're keeping most timers it's fine to only display seconds resolution IMO.

Regarding this:

we have no guarantee that log will be outputted "atomically", instead we may have it interleaved by some another log happening in another thread.

The Log() seems to be guarded by a std::lock_guard. Or is the problem the streaming? I might misunderstand smth basic here 😅

[SiarheiFedartsou]

The Log() seems to be guarded by a std::lock_guard. Or is the problem the streaming? I might misunderstand smth basic here

Yep, I am a bit wrong here. In case of util::Log there is no problem, because we have mutex here

osrm-backend/src/util/log.cpp

Line 113 in 660cea8

std::lock_guard<std::mutex> lock(get_mutex());

But UnbufferedLog writes directly to std::cout/std::cerr as I can see, that's why we may have this problem I mentioned.

[nilsnolde]

I checked all usages of UnbufferedLog, it's not used in multi-threaded functions AFAICT. I only changed the one occurrence in traffic signals, where it was mangled with warnings. Others looked fine.

If you want you can implement my changes, for me this PR looks good either way:)

[SiarheiFedartsou]

I updated PR to also output fractional part of second. Implementation is a bit ugly on my taste, but it works!

 const auto timestamp = std::chrono::system_clock::now();
            return fmt::format(
                "{}[{:%FT%H:%M:}{:%S}] [{}] ", is_terminal ? color : "", timestamp, timestamp.time_since_epoch(), level);

[SiarheiFedartsou]

Going to merge #6375 soon.

I only changed the one occurrence in traffic signals, where it was mangled with warnings.

btw IMO this is the main problem with UnbuferredLog - you never know if methods you are calling will log something or not. That's why I'd propose to get rid of it completely(at least I don't see any benefits of it)

[nilsnolde]

The benefit AFAICT is to print stuff on the same line, eg when reporting progress in percent, which is arguably nice for UX. It just the logs fairly concise. I’d personally keep it, but have not a very strong opinion about it.

[SiarheiFedartsou]

Closing as #6375 was merged.