A new logger arrives

As Crimild moves towards a parallel architecture, several design problems are starting to appear due to processes running concurrently (and because my past-self was quite lazy to think about that when design some of the most important parts of the engine).

For example, after spending A LOT of time trying to find out the cause of a what appeared to be a strange behavior in the rendering pass, I realized that there was no problem at all. Instead, the logger itself was buggy and the reason for it was that the logger wasn’t thread-safe. Then, log messages were mixed together between threads making it look like a problem in another place:

screen-shot-2016-12-13-at-1-35-23-pm

The worst part was that I KNEW the logger was not thread-safe from the moment I designed it years ago (like I said, lazy programmer). It just happened that I forgot about that small detail.

A new logger was needed.

A more powerful, stable and, of course, thread-safe logger.

And so, after some rethinking and refactoring, this happened:

Log::debug( “BLOG”, “Hello New Logger” );

Yes, that’s it. What were you expecting? It’s just a logger after all.

Anyway, the line above produces the following output:

12345621313 0x2213133 D/BLOG - Hello New Logger

There’s a lot of information in there:

  • Timestamp (in microseconds)
  • Thread ID
  • Log Level (‘D’ for ‘Debug’)
  • Log Tag (‘BLOG’)
  • The actual message (“Hello…”)

If you’re thinking that it looks like the kind of logs produced by the Android Monitor, you’re right. That was one of the basis for the new logger.

The logger also support enabling or disabling levels with a single flag (instead of having to disable individual ones), and the tag argument is useful for filtering. About tags, there’s also a new function (disguised as a macro) to get the class name from within a member function. Check this out:

void StreamingSystem::loadScene( std::string filename, SceneBuilder *builder )
{
   // ...
   Log::error( CRIMILD_CURRENT_CLASS_NAME, "Undefined scene builder" );
   // ...
}

The line above will output something like this:

12345627214 0x2213215 E/crimild::StreamingSystem - Undefined scene builder

Of course, you can use the tag as you please.

This new logger is implemented using C++11 variadic templates. I preferred this method over the typical printf-like one since it allow us to pass objects (as long as they overload the flux operator) instead of having to work with individual values.

Concerning concurrency (that was the whole point of this, right?), the logger is designed so that only one lock is required at the top-most level, right when we’re printing the message (for example, to the standard output). That way, mutexes are used only when needed.

 class ConsoleOutputHandler : public OutputHandler {
 public:
    ConsoleOutputHandler( void ) { }
    virtual ~ConsoleOutputHandler( void ) { }
 
    virtual void printLine( std::string const &line ) override
    {
       std::lock_guard< std::mutex > lock( _mutex );
       std::cout << line << "\n";
    }
 
 private:
    std::mutex _mutex;
 };

Well, that’s it for the logger. I just pushed the new code to the devel branch in Github if you want to take a look at it. And while you’re at it, there might be a little Christmas present there too a little ahead of schedule 😉

Happy Holidays!

 

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s