Added option to buffer log messages (which can reduce debug output

overhead).

sources.cmake

@@ -1,5 +1,5 @@
 # Modify this file to change the last-modified date when you add/remove a file.
-# This will then trigger a new cmake run automatically.
+# This will then trigger a new cmake run automatically.  
 file(GLOB_RECURSE STK_HEADERS RELATIVE ${CMAKE_CURRENT_SOURCE_DIR} "src/*.hpp")
 file(GLOB_RECURSE STK_SOURCES RELATIVE ${CMAKE_CURRENT_SOURCE_DIR} "src/*.cpp")
 file(GLOB_RECURSE STK_SHADERS RELATIVE ${CMAKE_CURRENT_SOURCE_DIR} "data/shaders/*")

src/main.cpp

@@ -594,6 +594,7 @@ void cmdLineHelp()
     "  -h,  --help             Show this help.\n"
     "       --log=N            Set the verbosity to a value between\n"
     "                          0 (Debug) and 5 (Only Fatal messages)\n"
+    "       --logbuffer=N      Buffers up to N lines log lines before writing.\n"
     "       --root=DIR         Path to add to the list of STK root directories.\n"
     "                          You can specify more than one by separating them\n"
     "                          with colons (:).\n"
@@ -664,6 +665,8 @@ int handleCmdLineOutputModifier()
     int n;
     if(CommandLine::has("--log", &n))
         Log::setLogLevel(n);
+    if (CommandLine::has("--logbuffer", &n))
+        Log::setBufferSize(n);
 
     if(CommandLine::has("--log=nocolor"))
     {
@@ -1807,8 +1810,10 @@ int main(int argc, char *argv[] )
     }  // try
     catch (std::exception &e)
     {
+        Log::flushBuffers();
         Log::error("main", "Exception caught : %s.",e.what());
         Log::error("main", "Aborting SuperTuxKart.");
+        Log::flushBuffers();
     }
 
     /* Program closing...*/
@@ -1832,6 +1837,8 @@ int main(int argc, char *argv[] )
     MemoryLeaks::checkForLeaks();
 #endif
 
+    Log::flushBuffers();
+
 #ifndef WIN32
     if (user_config) //close logfiles
     {

src/utils/log.cpp

@@ -36,6 +36,8 @@ Log::LogLevel Log::m_min_log_level = Log::LL_VERBOSE;
 bool          Log::m_no_colors     = false;
 FILE*         Log::m_file_stdout   = NULL;
 std::string   Log::m_prefix        = "";
+size_t        Log::m_buffer_size = 1;
+Synchronised<std::vector<struct Log::LineInfo> > Log::m_line_buffer;
 
 // ----------------------------------------------------------------------------
 /** Selects background/foreground colors for the message depending on
@@ -107,25 +109,22 @@ void Log::setTerminalColor(LogLevel level)
  */
 void Log::resetTerminalColor()
 {
-    if(m_no_colors)
+    if(m_no_colors) return;
-    {
-        printf("\n");
-        return;
-    }
-
 
 #ifdef WIN32
     SetConsoleTextAttribute(GetStdHandle(STD_OUTPUT_HANDLE),
                             /*TERM_BLACK*/0 << 4 | /*TERM_LIGHTGRAY*/7);
-    printf("\n");
 #else
     printf("%c[0;;m\n", 0x1B);
 #endif
 }   // resetTerminalColor
 
 // ----------------------------------------------------------------------------
-/** This actually prints the log message. If log messages are not redirected
+/** This actually creates a log message. If the messages are to be buffered,
- *  to a file, it tries to select a terminal colour.
+ *  it will be appended to the output buffer. If the buffer is full, it will
+ *  be flushed. If the message is not to be buffered, it will be immediately
+ *  written using writeLine().
+
  *  \param level Log level of the message to print.
  *  \param format A printf-like format string.
  *  \param va_list The values to be printed for the format.
@@ -133,114 +132,119 @@ void Log::resetTerminalColor()
 void Log::printMessage(int level, const char *component, const char *format,
                        VALIST args)
 {
-    assert(level>=0 && level <=LL_FATAL);
+    assert(level >= 0 && level <= LL_FATAL);
 
-    if(level<m_min_log_level) return;
+    if (level < m_min_log_level) return;
 
-#ifdef ANDROID
+    static const char *names[] = { "debug", "verbose  ", "info   ",
-    android_LogPriority alp;
+                                  "warn   ", "error  ", "fatal  " };
-    switch (level)
+    const int MAX_LENGTH = 2048;
+    char line[MAX_LENGTH + 1];
+    int index = 0;
+    if (!m_prefix.empty())
+        index += snprintf(line+index, MAX_LENGTH-index, "%s ", m_prefix.c_str());
+
+    index += snprintf (line + index, MAX_LENGTH - index, "[%s] %s: ", names[level], component);
+    index += vsnprintf(line + index, MAX_LENGTH - index, format, args);
+    va_end(args);
+    index = snprintf (line + index, MAX_LENGTH - index, "\n");
+
+    // If the data is not buffered, immediately print it:
+    if (m_buffer_size <= 1)
     {
-    // STK is using the levels slightly different from android
+        writeLine(line, level);
-    // (debug lowest, verbose above it; while android reverses
+        return;
-    // this order. So to get the same behaviour (e.g. filter
-    // out debug message, but still get verbose, we swap
-    // the order here.
-    case LL_VERBOSE: alp = ANDROID_LOG_DEBUG;   break;
-    case LL_DEBUG:   alp = ANDROID_LOG_VERBOSE; break;
-    case LL_INFO:    alp = ANDROID_LOG_INFO;    break;
-    case LL_WARN :   alp = ANDROID_LOG_WARN;    break;
-    case LL_ERROR:   alp = ANDROID_LOG_ERROR;   break;
-    case LL_FATAL:   alp = ANDROID_LOG_FATAL;   break;
-    default:         alp = ANDROID_LOG_FATAL;
     }
-#endif
 
-    static const char *names[] = {"debug", "verbose  ", "info   ",
+    // Now the data needs to be buffered. Add an entry to the buffer,
-                                  "warn   ", "error  ", "fatal  "};
+    // and if necessary flush the buffers.
-
+    struct LineInfo li;
-    // Using a va_list twice produces undefined results, ie crash.
+    li.m_level = level;
-    // So make a copy if we're going to use it twice.
+    li.m_line  = std::string(line);
-    VALIST copy;
+    m_line_buffer.lock();
-    if (m_file_stdout)
+    m_line_buffer.getData().push_back(li);
+    if (m_line_buffer.getData().size() < m_buffer_size)
     {
-        va_copy(copy, args);
+        // Buffer not yet full, don't flush data.
+        m_line_buffer.unlock();
+        return;
     }
-#if defined(_MSC_FULL_VER) && defined(_DEBUG)
+    m_line_buffer.unlock();
-    VALIST copy2;
+    // Because of the unlock above it can happen that another thread adds
-    va_copy(copy2, args);
+    // another line and calls flushBuffers() first before this thread can
-#endif
+    // call it, but that doesn't really matter, when this thread will finally
+    // call flushBuffer() it will then just print nothing if another thread
+    // had been actively flushing it in between.
+    flushBuffers();
+}   // printMessage
+
+// ----------------------------------------------------------------------------
+/** Writes the specified line to the various output devices, e.g. terminal,
+ *  log file etc. If log messages are not redirected to a file, it tries to
+ *  select a terminal colour.
+ *  \param line The line to write.
+ *  \param level Message level. Only used to select terminal colour.
+ */
+void Log::writeLine(const char *line, int level)
+{
 
     // If we don't have a console file, write to stdout and hope for the best
-    if(!m_file_stdout || level >= LL_WARN ||
+    if (!m_file_stdout || level >= LL_WARN ||
         UserConfigParams::m_log_errors_to_console) // log to console & file
     {
-        VALIST out;
-        va_copy(out, args);
-
         setTerminalColor((LogLevel)level);
-        #ifdef ANDROID
+#ifdef ANDROID
-        __android_log_vprint(alp, "SuperTuxKart", format, out);
+        android_LogPriority alp;
-        #else
+        switch (level)
-        if(!m_prefix.empty())
+        {
-            printf("%s ", m_prefix.c_str());
+            // STK is using the levels slightly different from android
-        printf("[%s] %s: ", names[level], component);
+            // (debug lowest, verbose above it; while android reverses
-        vprintf(format, out);
+            // this order. So to get the same behaviour (e.g. filter
-        #endif
+            // out debug message, but still get verbose, we swap
+            // the order here.
+        case LL_VERBOSE: alp = ANDROID_LOG_DEBUG;   break;
+        case LL_DEBUG:   alp = ANDROID_LOG_VERBOSE; break;
+        case LL_INFO:    alp = ANDROID_LOG_INFO;    break;
+        case LL_WARN:    alp = ANDROID_LOG_WARN;    break;
+        case LL_ERROR:   alp = ANDROID_LOG_ERROR;   break;
+        case LL_FATAL:   alp = ANDROID_LOG_FATAL;   break;
+        default:         alp = ANDROID_LOG_FATAL;
+        }
+        __android_log_vprint(alp, "SuperTuxKart", line);
+#else
+        printf(line);
+#endif
         resetTerminalColor();  // this prints a \n
-
-        va_end(out);
     }
 
 #if defined(_MSC_FULL_VER) && defined(_DEBUG)
-    static char szBuff[2048];
+    OutputDebugString(line);
-    vsnprintf(szBuff, sizeof(szBuff), format, copy2);
-
-    if (!m_prefix.empty())
-    {
-        OutputDebugString(m_prefix.c_str());
-        OutputDebugString(" ");
-    }
-    OutputDebugString("[");
-    OutputDebugString(names[level]);
-    OutputDebugString("] ");
-    OutputDebugString(component);
-    OutputDebugString(": ");
-    OutputDebugString(szBuff);
-    OutputDebugString("\r\n");
 #endif
 
-
+    if (m_file_stdout) fprintf(m_file_stdout, line);
-    if(m_file_stdout)
-    {
-        if(!m_prefix.empty())
-            fprintf(m_file_stdout, "%s ", m_prefix.c_str());
-        fprintf (m_file_stdout, "[%s] %s: ", names[level], component);
-        vfprintf(m_file_stdout, format, copy);
-        fprintf (m_file_stdout, "\n");
-        va_end(copy);
-    }
 
 #ifdef WIN32
     if (level >= LL_FATAL)
     {
-        std::string message;
+        MessageBoxA(NULL, line, "SuperTuxKart - Fatal error", MB_OK);
-
-        char tmp[2048];
-        sprintf(tmp, "[%s] %s: ", names[level], component);
-        message += tmp;
-
-        VALIST out;
-        va_copy(out, args);
-        vsprintf(tmp, format, out);
-        message += tmp;
-        va_end(out);
-
-        MessageBoxA(NULL, message.c_str(), "SuperTuxKart - Fatal error", MB_OK);
     }
 #endif
-}   // printMessage
+}   // _fluhBuffers
 
+// ----------------------------------------------------------------------------
+/** Flushes all stored log messages to the various output devices (thread safe).
+ */
+void Log::flushBuffers()
+{
+    m_line_buffer.lock();
+    for (unsigned int i = 0; i < m_line_buffer.getData().size(); i++)
+    {
+        const LineInfo &li = m_line_buffer.getData()[i];
+        writeLine(li.m_line.c_str(), li.m_level);
+    }
+    m_line_buffer.getData().clear();
+    m_line_buffer.unlock();
+}   // flushBuffers
 
 // ----------------------------------------------------------------------------
 /** This function opens the files that will contain the output.

src/utils/log.hpp

@@ -20,11 +20,15 @@
 #ifndef HEADER_LOG_HPP
 #define HEADER_LOG_HPP
 
+#include "utils/synchronised.hpp"
+
 #include <assert.h>
 #include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string>
+#include <vector>
+
 
 #ifdef __GNUC__
 #  define VALIST __gnuc_va_list
@@ -59,16 +63,30 @@ private:
     /** The file where stdout output will be written */
     static FILE* m_file_stdout;
 
+    /** An optional buffer for lines to be output. */
+    struct LineInfo
+    {
+        std::string m_line;
+        int m_level;
+    };
+    static Synchronised<std::vector<struct LineInfo> > m_line_buffer;
+    
+    /** <0 if no buffered logging is to be used, otherwise this is
+     ** the maximum number of lines the buffer should hold. */
+    static size_t m_buffer_size;
+
     /** An optional prefix to be printed. */
     static std::string m_prefix;
 
     static void setTerminalColor(LogLevel level);
     static void resetTerminalColor();
-
+    static void writeLine(const char *line, int level);
-public:
 
     static void printMessage(int level, const char *component,
                              const char *format, VALIST va_list);
+
+public:
+
     // ------------------------------------------------------------------------
     /** A simple macro to define the various log functions.
      *  Note that an assert is added so that a debugger is triggered
@@ -98,7 +116,12 @@ public:
     static void openOutputFiles(const std::string &logout);
 
     static void closeOutputFiles();
+    static void flushBuffers();
 
+    // ------------------------------------------------------------------------
+    /** Sets the number of lines to buffer. Setting the buffer size to a 
+     *  a value <=1 means no buffering, lines will be immediately printed. */
+    static void setBufferSize(size_t n) { m_buffer_size = n;  }
     // ------------------------------------------------------------------------
     /** Defines the minimum log level to be displayed. */
     static void setLogLevel(int n)