Re: How to add thread-safety in a logging library?
On 3 Aug, 17:11, ZHENG Zhong <heavyzh...@gmail.com> wrote:
I implemented a small logging library with the API like this:
[snip]
logger& log = log_manager::instance().get_logger("my_logger");
log.stream(DEBUG) << "this is a debug message" << std::endl;
log.stream(INFO) << "this is an info message" << std::endl;
[/snip]
The problem with this ostream-like output syntax is that arguments to
operator<<() always get evaluated, even if output at that level is
disabled.
The usual solution is to check the logging level first and only if it
is enabled proceed with logging.
Every logger has a unique name, and manages an output stream
(std::ostream). The 'stream(log_level_t)' member function returns an
ostream_proxy object, which is implemented as the following:
[snip]
class ostream_proxy {
public:
// other member functions...
template<typename T>
ostream_proxy& operator<<(T const& t) {
(*os_) << t;
return *this;
}
private:
std::ostream* os_; // ostream_proxy objects from the same logger
object share
// the same output stream.};
[/snip]
Thus it is possible that two threads retrieve the same logger object
and write messages to the logging stream at the same time.
Now i want to add thread-safety to my logging library, and i realize
that in ostream_proxy, the statement "(*os_) << t;" is not thread-safe
(std::ostream is not thread-safe, right?). So i need to re-implement
the operator << in ostream_proxy like this:
[snip]
class ostream_proxy {
public:
// other member functions...
template<typename T>
ostream_proxy& operator<<(T const& t) {
{
boost::mutex::scoped_lock lock(*os_mutex_);
(*os_) << t;
}
return *this;
}
private:
std::ostream* os_; // ostream_proxy objects from the same
logger object
boost::mutex* os_mutex_; // share the same output stream and the
same mutex.};
[/snip]
In this way, i can guarantee that at any moment, there is at most one
thread calling "(*os_) << t;".
But since logging may be an action that is frequently performed, the
code above may be too expensive to bear... Surely i can use a policy
to allow user to choose if s/he want thread-safety or not. But in a
multi-threaded application, user still has to pay for logging...
Please note here that one logically atomic piece of information (log
line) gets output using several operator<<() invocations, so that it
can be intervened by output from another thread. Thus, locking in
operator<<() is too fine-grained and not sufficient, the lock should
be held for the duration of several operator<<() invocations.
One way to overcome these difficulties is to replace wordy
operator<<() syntax with terse format strings and a logging function
with variable number of arguments (char const* fmt, ...). By using
such a function you may assume that each call to the logging function
generates one complete message (one or several lines of output), as
the ellipsis allows you to pass all the arguments in one call. That
logging function then would only use local variable to build the
complete message (possibly with file name, line number and a
timestamp) and finally submit the message to the file. Please note,
that in this design only submitting the complete message to the file
might require locking. On practice one often use write() syscall (or
something like WriteFile() on windoze) to put the message to the file,
so that no locking required.
Here is a sketch:
[max@k-pax test]$ cat test.cc
#include <stdio.h>
#include <stdarg.h>
#include <unistd.h>
#include <algorithm>
enum log_level_type { debug, info, error } log_level = debug;
char const* log_level_name[] = { "dbg", "inf", "err" };
// the function that actually writes a message to the log
void write_log(char const* msg, size_t msg_len)
{
write(STDOUT_FILENO, msg, msg_len); // error checking omitted
}
void log(
char const* file
, int line
, log_level_type lvl
, char const* fmt
, ...
)
{
// generate a compete log message in buf
char buf[0x1000];
size_t n = snprintf(buf, sizeof buf, "[%s] %s:%d: ",
log_level_name[lvl], file, line);
va_list ap; va_start(ap, fmt);
size_t m = vsnprintf(buf + n, sizeof buf - n - 1, fmt, ap); // - 1
for '\n'
va_end(ap);
n += std::min(sizeof buf - n - 1 - 1, m); // - 1 for '\n'
buf[n] = '\n';
// submit it to log
write_log(buf, n + 1);
}
#define DO_LOG(lvl, ...) \
do { if(log_level <= lvl) \
log(__FILE__, __LINE__, lvl, __VA_ARGS__); \
} while(0)
#define LOG_DBG(...) DO_LOG(debug, __VA_ARGS__)
#define LOG_INFO(...) DO_LOG(info, __VA_ARGS__)
#define LOG_ERR(...) DO_LOG(error, __VA_ARGS__)
void print(int n)
{
LOG_DBG("message %d", n);
LOG_INFO("message %d", n);
LOG_ERR("message %d", n);
}
int main()
{
print(1);
// change the log level at run-time to output only error messages
log_level = error;
print(2);
}
[max@k-pax test]$ g++ -Wall -o test test.cc
[max@k-pax test]$ ./test
[dbg] test.cc:47: message 1
[inf] test.cc:48: message 1
[err] test.cc:49: message 1
[err] test.cc:49: message 2
--
[ See http://www.gotw.ca/resources/clcm.htm for info about ]
[ comp.lang.c++.moderated. First time posters: Do this! ]