Home KjellKod Code Page
Performance data:  Also published at CodeProject: http://www.codeproject.com/KB/library/g2log.aspxIntroductiong2log was made to be a simple, efficient, and easy to understand asynchronous logger. The core of g2log is only a few, short files and it should be easy to modify to suit your needs. It comes with logging, design-by-contract CHECK macros, and catching and logging of fatal signals such as SIGSEGV (illegal memory access) and SIGFPE (floating point error) and more. It is cross-platform, tested on both Linux and Windows. What separates g2log from other logger utilities is that it is asynchronous. By using the Active Object pattern g2log does the slow disk access in the background. LOG calls are asynchronous and thereby g2log gets improved application performance. A comparison with the pseudo asynchronous Google glog (v.0.3.1) shows that g2log is much more efficient, especially in a worst case scenario. I have split this presentation in two parts
g2log is made with code techniques and building blocks suggested by many great software gurus. I have just connected the dots. There are probably other free asynchronous loggers out there, but at the time of this writing, I have not yet encountered one. That is why I am sharing this code with you. My contribution to the community and thanks for all the great help I have received in person, from articles and blogs. Of course, with this in mind, it just makes sense to make g2log free as a public domain dedication. A version of this article was originally published at www.kjellkod.cc.
Contents
[Part 1] g2Log: asynchronous loggingIntroducing g2logg2log is an asynchronous logging utility made to be efficient and easy to use, understand, and modify. The reason for creating g2log was simply that other logging software I researched were not good enough API-wise or efficiency-wise. API-wise I was just not happy with the calls to some of the logging utilities I tried. They were too verbose and made the code look cluttered. Efficiency-wise, I am of the firm belief that whenever there is a slow file/disk/network access, it should be tried to the utmost to process this in a background thread. I got disappointed with all the logging software I tried, as they were serial (synchronous), i.e., a LOG call was written to file before the log caller could continue, which obviously slows down the log caller. There are good, traditional, [#reasons] for using a synchronous logger but I believe g2log satisfies those reasons while still being asynchronous. Being responsive is a key requirement in the software I work with. Slowing down a thread because it is doing a LOG call is not good enough. Thus I decided to create the asynchronous g2log. For those who are interested, and not for flaming reasons, the loggers I looked into and found lacking were: Google's glog, ezlogger, and log4Cplus. To get the essence of g2log it is only needed to read a few highlights:
There you have it, g2log in essence. A side point: g2 was a keyword in the first commercial project that used g2log. It stands for second generation (g2), thus the naming was easy. It is just a happy coincidence that one of the inspirations to g2log's API was called glog.
Why the synchronous logger is traditionally preferred to the asynchronousA logger requirement is often to have the log entry on file, on disk, before the software would continue with the next logical code instruction. Traditionally, that meant only using a synchronous logger since it seemingly guaranteed that it would write straight to a file. The demand that a made log entry is on file before continuing is common when debugging a crashing application. From now on, we call this the crashing requirement. To the developer, it is vital to know that all the information is caught in the log before taking the next, potentially fatal, step. The downside to this is that the synchronous, slow, logging will penalize performance. How g2log satisfies the crashing requirementThe crashing handling requirement was addressed by using a signal handler. You can see this at https://bitbucket.org/KjellKod/g2log/src please browse to g2log/src/ and see crashhandler.h and OS specific crashhandler_win.cpp or crashhandler_unix.cpp. The signal handler will catch common OS or C-library triggered fatal signals that would kill the application. When catching a fatal signal, g2log sends the background worker a message telling it to handle a fatal event. The calling thread then sleeps until the background worker is finished. Meanwhile, the background worker is processing the messages in FIFO order. When the background worker receives the (FIFO queued) fatal-event-message, it writes it to file and then continues to kill the application with the original signal. This way all the FIFO queued log messages that came before the fatal-event-message will be written to file before the crash is finished. For the crashing requirement, when the application is killed with a fatal signal, g2log is still to be preferred to a synchronous logger. Performance will be good while still managing to handle flushing all written logs to file.
Using g2logg2log uses level-specific logging. This is done without slowing down the log-calling part of the software. Thanks to the concept of active object g2log gets asynchronous logging - the actual logging work with slow disk I/O access is done in a background thread. Compared to other logging utilities that does the I/O in the calling thread, the logging performance gain can be huge with g2log. This is shown below in the [#Performance comparison] page where I compare the mostly awesome Google glog library to g2log. Google's glog is what I call pseudo asynchronous since it can fake asynchronous behavior while it is really a synchronous logger. What is apparent is that the average time is up to 48% better with g2log. In the worst case scenarios, g2log is a factor 10-35 times faster than glog. g2log provides both stream syntax and InitializationA typical scenario for using g2log would be as shown below. Immediately at start up, in the main function body, #include "g2log.h"
int main(int argc, char** argv)
{
g2logWorker g2log(argv[0], "/tmp/whatever-directory-path-you-want/");
g2::initializeLogging(&g2log);
// ....
The example program g2log-example would generate a log file at /tmp/ according to the rule prefix.g2log.YYYYMMDD-HHMMSS.log, i.e. something like g2log-example.g2log.20111114-092342.log. Flush at shutdownAt closing of the application software, Active::~Active() {
Callback quit_token = std::bind(&Active::doDone, this);
send(quit_token); // tell thread to exit, this is the last message to be processed.thd_.join(); // after join is done, all messages are processed }
Logging levelsThe available logging levels are: By using the C preprocessor macro for token concatenation, the level itself is used to call the appropriate function. #define LOG(level) G2_LOG_##level.messageStream()
Typos, or using log levels that do not exist, will give compiler errors. LOG(UNKNOWN_LEVEL) << "This log attempt will cause a compiler error";
The compiler error will express something like:
>> ...
>> 'G2_LOG_UNKNOWN_LEVEL' was not declared in this scope
>> ...
For a log level that does not exist, or is spelled incorrectly, the concatenation will end up in a call to a non-existent function. This will then generate the compilation error. Thanks to this safe use of a C preprocessor macro, the API is clean and direct.
Logging levels example
#include "g2log.h"
int main(int argc, char** argv)
{
g2logWorker g2log(argv[0], "/tmp/whatever-directory-path-you-want/");
g2::initializeLogging(&g2log);
LOG(INFO) << "Simple to use with streaming syntax, easy as ABC or " << 123;
LOGF(WARNING, "Printf-style syntax is also %s", "available");
LOGF(FATAL, "This %s is FATAL. After log flush -> Abort()", "message");
// or using the stream API
LOG(FATAL) << "This message is FATAL. After log flush -> Abort()";
}
Conditional loggingConditional logging is provided. Conditional logging is handy when making a log entry under a certain condition. LOG_IF(INFO, (1 < 2)) << "If " << 1 << "<" << 2 << " : this text will be logged"; // or
LOGF_IF(INFO, (1<2), "if %d<%d : then this text will be logged", 1,2);
// : if 1<2 : then this text will be logged
Of course, conditional logging can be used together with the LOG_IF(FATAL, (2>3)) << "This message is not FATAL";
LOG_IF(FATAL, (2<3)) << "This message is FATAL";
Streaming APIThe streaming API uses a normal C++ LOG(DEBUG) << "Hello I have " << 1 << " car";
LOG(INFO) << "PI is: " << std::setprecision(6) << PI;
printf-like APIFor the first release of g2log, I was persuaded to add
If deciding to use a LOGF(DEBUG, "This API is popular with some %s", "programmers");
LOGF_IF(DEBUG, (1 != 2), "if true, then this %s will be logged", "message");
CHECKF(foo(), "if 'false == foo()' then the %s is broken: FATAL), "contract");
The risks with a const std::string logging = "logging";
LOGF(DEBUG, "Printf-type %s is the number 1 for many %s", logging.c_str());
The log call above is badly formatted. It has two To be on the safe side, I personally prefer to use the stream API, both on Linux and Windows. Design by contract (a.k.a. assertion programming)It is common programming practice to have early error detection through assert. Conditions in the code are checked and the application is aborted if the conditions are not fulfilled. This is an important part of Design-by-Contract and is sometimes called assertion programming. Most common is to use various CHECK(1 != 2); // true: won't be FATAL
CHECK(1 > 2) << "CHECK(false) will trigger a FATAL message, put it on log, then exit";
Or with const std::string arg = "CHECKF";
CHECKF(1 > 2, "This is a test to see if %s works", arg.c_str());
Influencesg2log's streaming API as well as the macro concatenation for creating a log API with compiler check for log levels can be found in other logging utilities. Similar logging usage can be found in Petru Marginean's Dr. Dobbs logging articles [4] and [5] and Google's glog [6]. If you have read my previous blogs or already browsed through g2log's code, then it should come as no surprise that g2log was influenced and inspired by:
RequirementsVersion 1.0 of g2log is released with this article. Building it requires just::thread's implementation of The next version of g2log is planned. So far no major code changes are planned, mostly build changes. Already, a reader has contacted me, he's using g2log with the If you do not have gcc 4.7 and do not plan to buy just::thread's The thread part of g2log is encapsuled within an active object. I have previously done similar active objects with QThread, pthread and more. If you do not have access to std::thread then maybe these could help. The code is available at https://github.com/KjellKod/active-object. The codeI have put up a BitBucket repository for g2log. You can access the files there: https://bitbucket.org/KjellKod/g2log/src. You can do the mercurial download using the command If you have any suggestions for improvements or notice something that should be corrected, then please tell me and I will do my best to incorporate it with the rest of the code.
Why and what-if
[Part 2] Performance: g2log vs. Google's glogIn the [#performance page] I compare g2log against a pseudo asynchronous logger: Google's glog version 0.3.1. If this is not so important to you I suggest you just skim it or go straight away to the [#Conclusions] below. ConclusionsPerformance conclusion [copied from part 2]]It is obvious that KjellKod's g2log is faster than Google's glog, both when measuring the average times and when measuring the worst cases. This has more to do with the fact that glog is (partly) synchronous in nature while g2log is asynchronous. In the average case, Kjellkod's g2log is 10-48% faster than Google's glog. In the worst case scenarios, g2log is a factor 10-35 times faster than glog. The pseudo asynchronous glog is much more efficient than a traditional synchronous logger. However, the peak times are alarming and discouraging. The tests were made on a laptop with a solid state drive. On another system using a standard hard drive, with even slower disk access, the difference between synchronous (glog) and asynchronous (g2log) would be considerable. The implication of using a synchronous logger is that sometimes the I/O wait times will be long. Using a synchronous logger can halt the log calling thread for a very long time. This is usually not desired since being responsive is a normal software design goal. G2log's average time is less than glog's average time. In the worst case scenario, the asynchronous g2log has a tremendous advantage over the synchronous glog.
g2log summary and reflectionsI can only speculate why the public versions of Google's glog, ezlogger, and log4Cplus are not made with true asynchronous logging. It is the traditional approach to a logger, but if you think about it, it is almost silly not having the slow disk access operations done in the background. This is clearly shown in the performance comparison section above. It does seem that Google's glog might indeed be asynchronous when used internally at Google. This according to the glog owner, Shinichi's comment at the glog forum google-glog/issues/detail?id=55. A probable reason not already discussed could be that these loggers were made pre C++11 ( Either way, C++11 is already here. g2log is free. Use it with Thank your for reading my article. I hope you can use g2log as is, parts of it or just be inspired to something else.
References
|
Added zip file from December 11 (cosmetic changes)