1
\$\begingroup\$

I have a custom logging system, use of which is scattered all over the engine and game. The system is linked to a "LogStore" that has an std::vector<string> logs[NUM_LOG_TYPES] - each vector corresponds with it's log type (info, error, debug, etc.). There's one extra std::vector that has "coordinates" to all log entries in the order they were received.

Now, all the logging output is also displayed inside my development console in the game. The game console is handled by HTML-type GUI and therefore requires a new <p> element being added for each log output.

My problem is that the log entries that are generated in the main loop each frame freeze the engine, because they continue to add elements to the in-game console, and if the console or guy generates a warning - that creates an infinite logging loop.

I want to solve it by handling the recurring log entries in an elegant way that lets you know that something is critically wrong, but won't freeze the engine - like displaying the count of errors in the last 60 frames instead of displaying errors themselves. But how do you guys handle this? Does anyone know any nifty tricks to do this?

I understand the question may sound vague, but if someone came across this type of issue I'm sure they would know exactly what's happening.

Example problematic log entries:

  • OpenGL warnings (I actually do check for errors every frame in many places)
  • Really any prints anywhere in the main loop (may be debugging, may be warnings)
\$\endgroup\$
1
  • 2
    \$\begingroup\$ I have implemented something in the past along the lines of "(... repeated n-times)" rather than printing the message out repeatedly; that kind of thing requires asynchronously writing the log output, which is not always good for certain types of events. It actually sounds like your log is simply too verbose to begin with. Do you have a system in place to vary the verbosity? I would consider implementing that first - there are sometimes you absolutely want every error/warning no matter how many times it repeats, but most of the time you don't need that at all after about the 2nd or 3rd time. \$\endgroup\$ – Andon M. Coleman Jun 11 '14 at 6:00
1
\$\begingroup\$

There are some basic techniques you can use to reduce log spam.

You can implement a runtime-configurable log verbosity filter. This allows you to reject the display of log messages below are certain filter level (for example, allowing you to display only errors, hiding debug and warning classes of message). You can obviously make this filter apply both (and/or independently) to the visual display of the log messages during the game and the saved logs on the disk. Since you are already tracking the verbosity level of each message, this should be relatively simple.

You can implement message throttling. This involves defining, where the message is logged, a value indicating how often the log message appears. For example,

Log(LogInterval.AtMostOncePerSecond, "I am a log message!")

Here, LogInterval.AtMostOncePerSecond is either an enumerated constant, a symbol representation of a floating point time span, or a number of game frames. Whatever works for you to define how often the log message should pop up on the screen. This generally involves storing more than just the final std::string in the log buffer, though; you'll want to make some kind of LogEntry structure to contain the relevant data, such as the interval, the last time the message was processed to the screen, and some unique identifier for the message (more on that later).

You can also implement duplicate detection and compression. This means that if you see a consecutive collection of log messages, all with the same unique identifier, you only display the first one and a repeat count ("I am a log message! (x15 times)"). This, like above, generally works best if you store more than just a string in the log message storage. Like above, it will also warrant the use of some unique identifier (although not necessarily the same identifier as above, if you also do throttling).


Uniquely identifying log messages has a bit of a subjective art to it. There are several ways you can implement it, with potential pros and cons. You should choose the one that works best for you.

You could consider the message text the unique property. I think this is the worst option, personally, because it means two textually identical messages in two different source locations could be throttled or suppressed, making it more difficult to figure out which code is the offending code. It also means slight variations in message state ("Bad render state value: 22 for field AlphaMask." and "Bad render state value: -10 for field DepthMask.") will not clump together for throttling and duplicate detection purposes, and usually this isn't what I want.

Alternatively, you can consider the source location (via __FILE__ and __LINE__ in C++ or similar constructs in other languages) the unique thing. This tends to flip the behavior from the first option around on its head.

You can also consider messages unique based on the format string instead of the unformatted value (in the case of the fake render state message above, that would be "Bad render state value: {0} for field {1}.").

I personally tend to use different methods for throttling and for duplicate detection (and usually do both), but the specific methods I choose tends to depend on what the general shape of the logging in an individual project tends to be.

\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.