Welcome back! I consider the very first thing a project needs to be somewhat proper debugging facilities, so we’ll start with developing a logging system. I kind of like the std::ostream message formatting style, so I’ll make something that resembles an ostream object. So let’s make a list of the things we’d like to support:<\/p>\n
1. User friendly (writing to a log should be painless, short and threadsafe and reading them should be informative)
\n2. Automatic adding of surrounding information (timestamps, originating file\/line)
\n3. (Bonus) Tweakable performance (log levels, debug\/release presets, background I\/O)<\/p>\n
I’d like the logging system to be able to handle the following code:<\/p>\n
\r\nint i = 5;\r\nfloat f = 3.0f;\r\n\r\nlogger << \"value 1: \" << i << \"\\nvalue 2: \" << f << std::endl;\r\n<\/pre>\nThe first thing you'd notice for something like that is that the << operator would have to be provided for multiple types. In the example above, we encounter 3 types of value classes (char*, int, float) and an iostream manipulator function (std::endl). Let's start by creating a class that just contains a buffer to accumulate the entire message: \n\n
\r\n\/\/ ---- Header ----\r\nclass LogMessage {\r\npublic:\r\n\ttemplate \r\n\tLogMessage& operator << (const T& value);\r\n\tLogMessage& operator << (std::ostream& (*fn)(std::ostream& os));\r\n\r\nprivate:\r\n\tstd::ostringstream mBuffer;\r\n};\r\n\r\n\/\/ ---- Implementation ----\r\ntemplate \r\nLogMessage& LogMessage::operator << (const T& value) {\r\n\tmBuffer << value;\r\n\treturn *this;\r\n}\r\n\r\nLogMessage& LogMessage::operator << (std::ostream& (*fn)(std::ostream& os)) {\r\n\tfn(mBuffer);\r\n\treturn *this;\r\n}\r\n<\/pre>\nThis would allow us to accumulate a message in a single string, before flushing it somewhere. Let's continue by creating a bit of a front-end for the LogMessage class: <\/p>\n
\r\n\/\/ ---- Header ----\r\nclass Logger {\r\npublic:\r\n\tLogMessage operator()();\r\n\r\n\tvoid flush(const LogMessage& message);\r\n};\r\n\r\nclass LogMessage {\r\n...\r\nprivate:\r\n\tfriend class Logger; \/\/ only allow the Logger class to instantiate a LogMessage\r\n\r\n\tLogMessage(Logger* owner);\r\npublic:\r\n\t~LogMessage();\r\n\r\nprivate:\r\n\tLogger* mOwner; \/\/ the Logger object is guaranteed to outlive the message, so a raw pointer is fine\r\n};\r\n\r\n\/\/ ---- Implementation ----\r\nLogMessage Logger::operator()() {\r\n\treturn LogMessage(this);\r\n}\r\n\r\nvoid Logger::flush(const LogMessage& message) {\r\n\tstd::string asString = message.mBuffer.str();\r\n\tstd::cout << asString << \"\\n\"; \/\/ auto-append newlines\r\n}\r\n\r\nLogMessage::LogMessage(Logger* owner):\r\n\tmOwner(owner)\r\n{\r\n}\r\n\r\nLogMessage::~LogMessage() {\r\n\tmOwner->flush(*this);\r\n}\r\n<\/pre>\nUsing a LogMessage via the Logger front end now creates a temporary object that accumulates values and then flushes itself upon destruction. There are a couple of things that can go wrong here, especially when the LogMessage is moved around -- partially constructed objects should not flush themselves. This is just a small fix:<\/p>\n
\r\n\/\/ ---- Header ----\r\nclass LogMessage {\r\n...\r\n\tLogMessage(LogMessage&& msg);\r\n\t~LogMessage();\r\n\r\n\/\/ ---- Implementation ----\r\nLogMessage::LogMessage(LogMessage&& msg):\r\n\tmBuffer(std::move(msg.mBuffer)),\r\n\tmOwner(std::move(msg.mOwner))\r\n{\r\n\tmsg.mOwner = nullptr;\r\n}\r\n\r\nLogMessage::~LogMessage() {\r\n\tif (mOwner)\r\n\t\tmOwner->flush(*this);\r\n}\r\n<\/pre>\nNow we're ready to start adding more conveniences. There are a couple of standard preprocessor definitions that would be nice - __FILE__ and __LINE__ come to mind. However, using preprocessor macros to yield some kind of logging object would need to have some kind of static\/global object to refer to. I don't take this lightly, but it *really* helps with making the logger as user-friendly as possible, so let's just get it over with. Also, create some facilities in the LogMessage to hold the __FILE__ and __LINE__ content.<\/p>\n
\r\n\/\/ ---- Header ----\r\nnamespace overdrive {\r\n\textern Logger gLogger; \/\/ global storage with external linkage\r\n}\r\n\r\n#define gLog ::overdrive::gLogger(__FILE__, __LINE__)\r\n\r\nclass Logger {\r\n...\r\n\tLogMessage operator()(const std::string& file, int line);\r\n\tvoid flush(const LogMessage& message);\r\n\r\nclass LogMessage {\r\n...\r\n\tLogMessage(const std::string& file, int line, Logger* owner);\r\n\r\n\tstruct Meta {\r\n\t\tstd::string mFile;\r\n\t\tint mLine;\r\n\t};\r\n\r\n\tMeta mMeta;\r\n<\/pre>\nLet's adress the logger output next -- for now we've been writing to std::cout, but a *real* logger would log to a file. In fact, I'd like to set up the Logger class so that, in debug mode at least, it writes both to a file and std::cout. So here the problem is that we would like to use multiple implementations of an interface -- polymorphism. In fact there are many ways to do this, but I like the encapsulated polymorphism approach first presented (afaik) by <\/a> at Going Native. Let's start with a class that has an internal base class for the interface we're trying to support:<\/p>\n\r\nclass LogSink {\r\npublic:\r\n\tvoid operator()(const LogMessage::Meta& meta, const std::string& message);\r\n\r\nprivate:\r\n\tstruct Concept {\r\n\t\tvirtual ~Concept() {}\r\n\t\tvirtual void operator()(const LogMessage::Meta& meta, const std::string& message) = 0;\r\n\t};\r\n\r\n\tstd::unique_ptr mWrapper;\r\n};\r\n<\/pre>\nBy specifying the interface as an operator() we'll be able to support lambda's as well. Now, we can add a templated constructor that can be used to implicitly create an implementation of the interface. There are some issues with copying the object though, so we'll also need to add explicit cloning operations. Taken together, this is all about properly forwarding stuff.<\/p>\n
\r\n...\r\n\tstruct Concept {\r\n\t\tvirtual ~Concept() {}\r\n\t\tvirtual Concept* clone() const = 0;\r\n\t\tvirtual void operator()(const LogMessage::Meta& meta, const std::string& message) = 0;\r\n\t};\r\n\r\n\ttemplate \r\n\tstruct Model: Concept {\r\n\t\tModel(T impl):\r\n\t\t\tmImpl(std::move(impl))\r\n\t\t{\r\n\t\t}\r\n\r\n\t\tvirtual Concept* clone() const override {\r\n\t\t\treturn new Model(mImpl);\r\n\t\t}\r\n\r\n\t\tvirtual void operator()(const LogMessage::Meta& meta, const std::string& message) {\r\n\t\t\tmImpl(meta, message);\r\n\t\t}\r\n\r\n\t\tT mImpl;\r\n\t};\r\n\r\n\ttemplate \r\n\tLogSink(T impl):\r\n\t\tmImpl(new Model(std::move(impl)))\r\n\t{\r\n\t}\r\n\r\n\tLogSink(const LogSink& sink):\r\n\t\tmWrapper(sink.mWrapper->clone())\r\n\t{\r\n\t}\r\n\r\n\tLogSink& operator = (LogSink sink) {\r\n\t\t\/\/ the function signature already specifies a copy, so we only need to move the result from the temporary\r\n\t\tmWrapper = std::move(sink.mWrapper);\r\n\t\treturn *this;\r\n\t}\r\n<\/pre>\nBy using this nifty approach, we can wrap all objects that conform to the interface specified in the Concept structure. It also gained value semantices, which is extremely nice to have. The downside is that each and every copy does a memory allocation. There are ways around that, but they make the implementation a lot more complex. Until it really becomes a problem, I'm going to just roll with it as it is. Let's use the polymorphic wrapper to create a sink that outputs the message to the standard output just like we've been using:<\/p>\n
\r\nLogSink makeConsoleSink() {\r\n\treturn [](const LogMessage::Meta& meta, const std::string& message) {\r\n\t\tstd::cout << message << \"\\n\";\r\n\t};\r\n} \/\/ really, that's it! (it's implicitly converted to a LogSink)\r\n<\/pre>\nAs the standard output requires no additional state, a single lambda does everything we want. Writing to a file does require some extra state though, so let's write something with internal state for that:<\/p>\n
\r\nstruct FileSink {\r\n\tFileSink(const std::string& filename):\r\n\t\tmFile(std::make_shared(filename))\r\n\t{\r\n\t\tif (!mFile.good()) {\r\n\t\t\tstd::string message = \"Failed to open file sink: \";\r\n\t\t\tmessage.append(filename);\r\n\t\t\tthrow std::runtime_error(message);\r\n\t\t}\r\n\t}\r\n\r\n\tvoid operator()(const LogMessage::Meta& meta, const std::string& message) {\r\n\t\t(*mFile)\r\n\t\t\t<< message\r\n\t\t\t<< \" (\"\r\n\t\t\t<< meta.mFile\r\n\t\t\t<< \":\"\r\n\t\t\t<< meta.mLine\r\n\t\t\t<< \")\\n\";\r\n\t}\r\n\r\n\tstd::shared_ptr mFile; \/\/ by using shared_ptr this can be copied around\r\n};\r\n\r\nLogSink makeFileSink(const std::string& filename) {\r\n\treturn FileSink(filename); \/\/ implicitly converted to LogSink\r\n}\r\n<\/pre>\nThis way, the message written to the file contains some extra information, while leaving the standard output relatively bare. When working with logs I like to have minimal reporting straight up, with additional information whenever I would like to see it, and this is one way to do just that.<\/p>\n
The final upgrade worth discussing is to offload the I\/O stuff to a separate thread. Writing messages should ideally not interfere with the rest of the program, and I\/O operations are vastly slower than other operations. An approach I like is to use an Active Object to handle the writing -- an object that wraps calls to operations on a different thread. A couple of years ago, Herb Sutter<\/a> wrote about how to implement one, and we'll use a small variation on that.<\/p>\n\r\nclass Active {\r\nprivate:\r\n\t\/\/ only allow creation via factory method\r\n\tActive():\r\n\t\tmRunning(true)\r\n\t{ \r\n\t}\r\n\r\npublic:\r\n\ttypedef std::function Callback;\r\n\r\n\t\/\/ don't copy this around\r\n\tActive(const Active&) = delete;\r\n\tActive& operator = (const Active&) = delete;\r\n\r\n\t~Active() {\r\n\t\tsend([this] { mRunning = false; });\r\n\t\tmThread.join();\r\n\t}\r\n\r\n\tstatic std::unique_ptr create() {\r\n\t\tstd::unique_ptr result(new Active);\r\n\r\n\t\tresult->mThread = boost::thread(&Active::run, result.get());\r\n\r\n\t\treturn result;\r\n\t}\r\n\r\n\tvoid send(Callback message) {\r\n\r\n\t\/\/ this should almost always be called with [=] {...} style lambda's\r\n\t\/\/ (in order to ensure that the data being operated on in the other\r\n\t\/\/ thread is still present)\r\n\r\n\t\tmMessageQueue.push_back(std::move(message));\r\n\t}\r\n\r\nprivate:\r\n\tvoid run() {\r\n\t\twhile (mRunning) {\r\n\t\t\tCallback fn;\r\n\t\t\t\r\n\t\t\tmMessageQueue.wait_pull_front(fn);\r\n\r\n\t\t\tfn();\r\n\t\t}\r\n\t}\r\n\r\n\tbool mRunning;\r\n\tboost::sync_queue mMessageQueue;\r\n\tboost::thread mThread;\r\n};\r\n<\/pre>\nThere we have it -- a userfriendly, threadsafe logging facility with multiple backends. The complete source can be downloaded here<\/a>.<\/p>\n[edit] Gah... there's an issue in visual studio with joining threads in the destructor of global objects, sometimes causing unexpected deadlocks. Effectively this means you shouldn't use std::thread in any sort of global object (static, extern or plain global). It seems that boost::thread doesn't have this issue though, so use that instead.<\/p>\n
[edit] I received some feedback and made a small change to the code -- replacing std::forward instances with std::move for clarity. Thanks kiokko89 \ud83d\ude42<\/p>\n","protected":false},"excerpt":{"rendered":"
Welcome back! I consider the very first thing a project needs to be somewhat proper debugging facilities, so we’ll start with developing a logging system. I kind of like the std::ostream message formatting style, so I’ll make something that resembles an ostream object. So let’s make a list of the Read More…<\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"parent":25,"menu_order":0,"comment_status":"open","ping_status":"open","template":"","meta":{"ngg_post_thumbnail":0,"footnotes":""},"_links":{"self":[{"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=\/wp\/v2\/pages\/158"}],"collection":[{"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=\/wp\/v2\/pages"}],"about":[{"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=\/wp\/v2\/types\/page"}],"author":[{"embeddable":true,"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=158"}],"version-history":[{"count":18,"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=\/wp\/v2\/pages\/158\/revisions"}],"predecessor-version":[{"id":981,"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=\/wp\/v2\/pages\/158\/revisions\/981"}],"up":[{"embeddable":true,"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=\/wp\/v2\/pages\/25"}],"wp:attachment":[{"href":"https:\/\/www.grandmaster.nu\/blog\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=158"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}