fmtlog
fmtlog is a performant asynchronous logging library using fmt library format.
Features
- Faster - lower runtime latency than NanoLog and higher throughput than spdlog (see Performance below).
- Headers only or compiled
- Feature rich formatting on top of excellent fmt library.
- Asynchronous multi-threaded logging in time order and can also be used synchronously in single thread.
- Custom formatting
- Custom handling - user can set a callback function to handle log msgs in addition to writing into file.
- Log filtering - log levels can be modified in runtime as well as in compile time.
- Log frequency limitation - specific logs can be set a minimum logging interval.
Platforms
- Linux (GCC 10.2 tested)
- Windows (MSVC 2019 tested)
Install
C++17 is required, and fmtlog is dependent on fmtlib, you need to install fmtlib first if you haven't.
Header only version
Just copy fmtlog.h and fmtlog-inl.h to your project, and define macro FMTLOG_HEADER_ONLY before including fmtlog.h. You might also want to define FMT_HEADER_ONLY if you are using fmtlib in header-only way.
Static/Shared lib version built by CMake
$ git clone https://github.com/MengRao/fmtlog.git
$ cd fmtlog
$ git submodule init
$ git submodule update
$ ./build.sh
Then copy fmtlog.h and libfmtlog-static.a/libfmtlog-shared.so generated in .build dir.
Usage
#include "fmtlog/fmtlog.h"
int main()
{
FMTLOG(fmtlog::INF, "The answer is {}.", 42);
}
There're also shortcut macros logd, logi, logw and loge defined for logging DBG, INF, WRN and ERR msgs respectively:
logi("A info msg");
logd("This msg will not be logged as the default log level is INF");
fmtlog::setLogLevel(fmtlog::DBG);
logd("Now debug msg is shown");
Note that fmtlog is asynchronous in nature, msgs are not written into file/console immediately after the log statements: they are simply pushed into a queue. You need to call fmtlog::poll() to collect data from log queues, format and write it out:
fmtlog::setThreadName("aaa");
logi("Thread name is bbb in this msg");
fmtlog::setThreadName("bbb");
fmtlog::poll();
fmtlog::setThreadName("ccc");
logi("Thread name is ccc in this msg");
fmtlog::poll();
fmtlog::setThreadName("ddd");
fmtlog supports multi-threaded logging, but can only have one thread calling fmtlog::poll(). By default, fmtlog doesn't create a polling thread internally, it requires the user to poll it periodically. The idea is that this allows users to manage the threads in their own way, and have full control of polling/flushing behavior. However, you can ask fmtlog to create a background polling thread for you by fmtlog::startPollingThread(interval) with a polling interval, but you can't call fmtlog::poll() when the thread is running.
Format
fmtlog is based on fmtlib, almost all fmtlib features are supported(except for color):
#include "fmt/ranges.h"
using namespace fmt::literals;
logi("I'd rather be {1} than {0}.", "right", "happy");
logi("Hello, {name}! The answer is {number}. Goodbye, {name}.", "name"_a = "World", "number"_a = 42);
std::vector<int> v = {1, 2, 3};
logi("ranges: {}", v);
logi("std::move can be used for objects with non-trivial destructors: {}", std::move(v));
assert(v.size() == 0);
std::tuple<int, char> t = {1, 'a'};
logi("tuples: {}", fmt::join(t, ", "));
enum class color {red, green, blue};
template <> struct fmt::formatter<color>: formatter<string_view> {
// parse is inherited from formatter<string_view>.
template <typename FormatContext>
auto format(color c, FormatContext& ctx) {
string_view name = "unknown";
switch (c) {
case color::red: name = "red"; break;
case color::green: name = "green"; break;
case color::blue: name = "blue"; break;
}
return formatter<string_view>::format(name, ctx);
}
};
logi("user defined type: {:>10}", color::blue);
logi("{:*^30}", "centered");
logi("int: {0:d}; hex: {0:#x}; oct: {0:#o}; bin: {0:#b}", 42);
logi("dynamic precision: {:.{}f}", 3.14, 1);
// A compile-time error because 'd' is an invalid specifier for strings.
logi("{:d}", "foo");
As an asynchronous logging library, fmtlog provides additional support for passing arguments by pointer(which is seldom needed for fmtlib and it only supports void and char pointers). User can pass a pointer of any type as argument to avoid copy overhead if the lifetime of referred object is assured(otherwise the polling thread will refer to a dangling pointer!). For string arg as an example, fmtlog copies string content for type std::string by default, but only a pointer for type std::string*:
std::string str = "aaa";
logi("str: {}, pstr: {}", str, &str);
str = "bbb";
fmtlog::poll();
// output: str: aaa, pstr: bbb
In addition to raw pointers, fmtlog supports std::shared_ptr and std::unique_ptr as well, which makes object lifetime management much easier:
int a = 4;
auto sptr = std::make_shared<int>(5);
auto uptr = std::make_unique<int>(6);
logi("void ptr: {}, ptr: {}, sptr: {}, uptr: {}", (void*)&a, &a, sptr, std::move(uptr));
a = 7;
*sptr = 8;
fmtlog::poll();
// output: void ptr: 0x7ffd08ac53ac, ptr: 7, sptr: 8, uptr: 6
Log header pattern can also be customized with fmtlog::setHeaderPattern() and the argument is a fmtlib format string with named arguments. The default header pattern is "{HMSf} {s:<16} {l}[{t:<6}] " (example: "15:46:19.149844 log_test.cc:43 INF[448050] "). All supported named arguments in header are as below:
| Name | Meaning | Example |
|---|---|---|
l |
Log level | INF |
s |
File base name and line num | log_test.cc:48 |
g |
File path and line num | /home/raomeng/fmtlog/log_test.cc:48 |
t |
Thread id by default, can be reset by fmt::setThreadName() |
main |
a |
Weekday | Mon |
b |
Month name | May |
Y |
Year | 2021 |
C |
Short year | 21 |
m |
Month | 05 |
d |
Day | 03 |
H |
Hour | 16 |
M |
Minute | 08 |
S |
Second | 09 |
e |
Millisecond | 796 |
f |
Microsecond | 796341 |
F |
Nanosecond | 796341126 |
Ymd |
Year-Month-Day | 2021-05-03 |
HMS |
Hour:Minute:Second | 16:08:09 |
HMSe |
Hour:Minute:Second.Millisecond | 16:08:09.796 |
HMSf |
Hour:Minute:Second.Microsecond | 16:08:09.796341 |
HMSF |
Hour:Minute:Second.Nanosecond | 16:08:09.796341126 |
YmdHMS |
Year-Month-Day Hour:Minute:Second | 2021-05-03 16:08:09 |
YmdHMSe |
Year-Month-Day Hour:Minute:Second.Millisecond | 2021-05-03 16:08:09.796 |
YmdHMSf |
Year-Month-Day Hour:Minute:Second.Microsecond | 2021-05-03 16:08:09.796341 |
YmdHMSF |
Year-Month-Day Hour:Minute:Second.Nanosecond | 2021-05-03 16:08:09.796341126 |
Note that using concatenated named args is more efficient than seperated ones, e.g. {YmdHMS} is faster than {Y}-{m}-{d} {H}:{M}:{S}.
Output
By default, fmtlog output to stdout. Normally users want to write to a log file instead, this is accomplished by fmtlog::setLogFile(filename,truncate). For performance, fmtlog internally buffer data, and under certain conditions will the buffer be flushed into the underlying file. The flushing conditions are:
- The underlying FILE* is not managed by fmtlog, then fmtlog will not buffer at all. For example, the default stdout FILE* will not be buffered. User can also pass an existing FILE* and indicate whether fmtlog should manage it by
fmtlog::setLogFile(fp, manageFp), e.g.fmtlog::setLogFile(stderr, false), then fmtlog will log into stderr without buffering. - The buffer size is larger than 8 KB, this number can be reset by
fmtlog::setFlushBufSize(bytes). - The oldest data in the buffer has passed a specified duration. The duration is by default 3 seconds, and can be set by
fmtlog::setFlushDelay(ns). - The new log has at least a specified flush log level. The default flush log level can't be reached by any log, but it can be set by
fmtlog::flushOn(logLevel). - User can actively ask fmtlog to flush by
fmtlog::poll(true).
Optionally, user can ask fmtlog to close the log file by fmtlog::closeLogFile(), and subsequent log msgs will not be output.
In addition to writing to a FILE*, user can register a callback function to handle log msgs by fmtlog::setLogCB(cb, minCBLogLevel). This can be useful in circumstances where warning/error msgs need to be published out in real time for alerting purposes. Log callback will not be buffered as log file, and can be triggered even when the file is closed. The signiture of callback function is:
// callback signature user can register
// ns: nanosecond timestamp
// level: logLevel
// location: full file path with line num, e.g: /home/raomeng/fmtlog/fmtlog.h:45
// basePos: file base index in the location
// threadName: thread id or the name user set with setThreadName
// msg: full log msg with header
// bodyPos: log body index in the msg
typedef void (*LogCBFn)(int64_t ns, LogLevel level, fmt::string_view location, size_t basePos,
fmt::string_view threadName, fmt::string_view msg, size_t bodyPos);
Performance
Benchmark is done in terms of both front-end latency and throughput, with comparisons to Nanolog and spdlog basic_logger_st. Test log messages use NanoLog benchmark Log-Messages-Map, and header pattern uses spdlog default pattern(e.g. "[2021-05-04 10:36:38.098] [spdlog] [info] [bench.cc:111] "), check bench.cc for details.
The results on a linux server with "Intel(R) Xeon(R) Gold 6144 CPU @ 3.50GHz" is:
| Message | fmtlog | Nanolog | spdlog |
|---|---|---|---|
| staticString | 6.4 ns, 7.08 M/s | 6.5 ns, 33.10 M/s | 156.4 ns, 6.37 M/s |
| stringConcat | 6.4 ns, 6.05 M/s | 7.5 ns, 14.20 M/s | 209.4 ns, 4.77 M/s |
| singleInteger | 6.3 ns, 6.22 M/s | 6.5 ns, 50.29 M/s | 202.3 ns, 4.94 M/s |
| twoIntegers | 6.4 ns, 4.87 M/s | 6.6 ns, 39.25 M/s | 257.2 ns, 3.89 M/s |
| singleDouble | 6.2 ns, 5.37 M/s | 6.5 ns, 39.62 M/s | 225.0 ns, 4.44 M/s |
| complexFormat | 6.4 ns, 2.95 M/s | 6.7 ns, 24.30 M/s | 390.9 ns, 2.56 M/s |
Note that the throughput of Nanolog is not comparable here because it outputs to binary log file instead of human-readable text format, e.g. it saves an int64 timestamp instead of a long formatted date time string.
How can fmtlog achieve such low and stable latency? Two key optimization techniques are employed inspired by Nanolog:
One is allocating a single producer single consumer queue for each logging thread, and have the background thread polling for all these queues. This avoids threads contention and performance will not deteriorate when thread number increases. The queue is automatically created on the first log msg of a thread, so queue is not created for threads that don't use fmtlog. The thread queue has a fixed size of 1 MB, and it takes a little time to allocate the queue. It's recommended that user actively calls fmt::preallocate() once the thread is created, so even the first log can have low latency.
What happens when the queue is full? By default, fmtlog simply dump addtional log msgs and return. Alternatively, front-end logging can be blocked while the queue is full by defining macro FMTLOG_BLOCK=1, then no log will be missing. Normally, consumer(fmtlog::poll()) should keep up with producers(log statments in multiple threads) and log queues seldom become full, but incautious user could leave log statements that are invoked in an unexpected high frequency, e.g. a tcp client spamming with "Connection refused" errors without a connection retry delay. To handle this problem in an elegant way, fmtlog provides a log macro which limits mininum interval of this log: FMTLOG_LIMIT and 4 shortcuts logdl, logil, logwl and logel respectively, user needs to pass the mininum interval in nanosecond as the first argument, e.g.
logil(1000000000, "this log will be displayed at most once per second").
The other optimization is that static information of a log(such as format string, log level and location) is saved in a table at its first call, and fmtlog simply pushes the index of the static info table entry with dynamic arguments to the queue, minimizing the msg size. In addition, fmtlog defines a decoding function for each log statment, which is invoked in fmtlog::poll() when the log msg is popped from the queue.
However, these decoding functions bloat program size with each function consuming around 50 bytes. In addition, the static infomation entry also consumes 50-ish bytes runtime memory for each log statement. Such memory overhead may not be worthwhile for those infrequent and latency insensitive logs(e.g. program initialization info), thus fmtlog provides user with another log macro which disables this optimization: FMTLOG_ONCE and of couse shortcuts: logdo, logio, logwoand logeo. FMTLOG_ONCE will not create a static info table entry, nor add a decoding function: it pushes static info along with formatted msg body onto the queue. Note that passing argument by pointer is not supported by FMTLOG_ONCE.
For those who prefer to further optimize memory usage by filtering log at compile time, macro FMTLOG_ACTIVE_LEVEL is applied with a default value FMTLOG_LEVEL_INF, meaning debug logs will simply be discarded at compile time. Note that FMTLOG_ACTIVE_LEVEL only applies to log shortcut macros, e.g. logi, but not FMTLOG.
![[Question] Several logs output in one line in multithreaded application](https://avatars.githubusercontent.com/u/6689673?v=4)
677 Dec 20, 2022
10 Jul 17, 2022
3.3k Dec 31, 2022
1 Feb 17, 2022
191 Dec 20, 2022
1.5k Jan 7, 2023
1.6k Dec 29, 2022
16.6k Jan 1, 2023
3 Oct 13, 2022
20 Dec 5, 2022
46 Oct 21, 2020
157 Dec 22, 2022
802 Dec 23, 2022
5.9k Jan 9, 2023
1.4k Jan 4, 2023
15 Sep 29, 2022
445 Dec 20, 2022