Logging to with a ringbuffer. Much faster.

src/xenia/base/logging.cc

@@ -11,12 +11,15 @@
 
 #include <gflags/gflags.h>
 
+#include <atomic>
 #include <cstdarg>
 #include <mutex>
 #include <vector>
 
+#include "xenia/base/filesystem.h"
 #include "xenia/base/main.h"
 #include "xenia/base/math.h"
+#include "xenia/base/ring_buffer.h"
 #include "xenia/base/threading.h"
 
 // For MessageBox:
@@ -25,91 +28,150 @@
 #include "xenia/base/platform_win.h"
 #endif  // XE_PLATFORM_WIN32
 
-DEFINE_bool(fast_stdout, false,
-            "Don't lock around stdout/stderr. May introduce weirdness.");
-DEFINE_bool(flush_stdout, true, "Flush stdout after each log line.");
+DEFINE_string(log_file, "",
+              "Logs are written to the given file instead of the default.");
+DEFINE_bool(flush_log, true, "Flush log file after each log line batch.");
 
 namespace xe {
 
-std::mutex log_lock;
+thread_local std::vector<char> log_format_buffer_(64 * 1024);
 
-thread_local std::vector<char> log_buffer(16 * 1024);
-
-void format_log_line(char* buffer, size_t buffer_capacity,
-                     const char level_char, const char* fmt, va_list args) {
-  char* buffer_ptr;
-  buffer_ptr = buffer;
-  *(buffer_ptr++) = level_char;
-  *(buffer_ptr++) = '>';
-  *(buffer_ptr++) = ' ';
-  buffer_ptr +=
-      std::snprintf(buffer_ptr, buffer_capacity - (buffer_ptr - buffer), "%.4X",
-                    xe::threading::current_thread_id());
-  *(buffer_ptr++) = ' ';
-
-  // Scribble args into the print buffer.
-  size_t remaining_capacity = buffer_capacity - (buffer_ptr - buffer) - 3;
-  size_t chars_written = vsnprintf(buffer_ptr, remaining_capacity, fmt, args);
-  if (chars_written >= remaining_capacity) {
-    buffer_ptr += remaining_capacity - 1;
-  } else {
-    buffer_ptr += chars_written;
+class Logger {
+ public:
+  Logger() : ring_buffer_(buffer_, kBufferSize), running_(true) {
+    flush_event_ = xe::threading::Event::CreateAutoResetEvent(false);
+    write_thread_ =
+        xe::threading::Thread::Create({}, [this]() { WriteThread(); });
+    write_thread_->set_name("xe::FileLogSink Writer");
   }
 
-  // Add a trailing newline.
-  if (buffer_ptr[-1] != '\n') {
-    buffer_ptr[0] = '\n';
-    buffer_ptr[1] = 0;
+  ~Logger() {
+    running_ = false;
+    flush_event_->Set();
+    xe::threading::Wait(write_thread_.get(), true);
+    fflush(file_);
+    fclose(file_);
   }
+
+  void Initialize(const std::wstring& app_name) {
+    if (!FLAGS_log_file.empty()) {
+      auto file_path = xe::to_wstring(FLAGS_log_file.c_str());
+      xe::filesystem::CreateParentFolder(file_path);
+      file_ = xe::filesystem::OpenFile(file_path, "wt");
+    } else {
+      auto file_path = app_name + L".log";
+      file_ = xe::filesystem::OpenFile(file_path, "wt");
+    }
+  }
+
+  void AppendLine(uint32_t thread_id, const char level_char, const char* buffer,
+                  size_t buffer_length) {
+    LogLine line;
+    line.thread_id = thread_id;
+    line.level_char = level_char;
+    line.buffer_length = buffer_length;
+    while (true) {
+      mutex_.lock();
+      if (ring_buffer_.write_count() < sizeof(line) + buffer_length) {
+        // Buffer is full. Stall.
+        mutex_.unlock();
+        xe::threading::MaybeYield();
+        continue;
+      }
+      ring_buffer_.Write(&line, sizeof(LogLine));
+      ring_buffer_.Write(buffer, buffer_length);
+      mutex_.unlock();
+      break;
+    }
+    flush_event_->Set();
+  }
+
+ private:
+  static const size_t kBufferSize = 32 * 1024 * 1024;
+
+  struct LogLine {
+    uint32_t thread_id;
+    char level_char;
+    size_t buffer_length;
+  };
+
+  void WriteThread() {
+    while (running_) {
+      mutex_.lock();
+      bool did_write = false;
+      while (!ring_buffer_.empty()) {
+        did_write = true;
+        LogLine line;
+        ring_buffer_.Read(&line, sizeof(line));
+        ring_buffer_.Read(log_format_buffer_.data(), line.buffer_length);
+        const char prefix[3] = {line.level_char, '>', ' '};
+        fwrite(prefix, 1, sizeof(prefix), file_);
+        fwrite(log_format_buffer_.data(), 1, line.buffer_length, file_);
+        if (log_format_buffer_[line.buffer_length - 1] != '\n') {
+          const char suffix[1] = {'\n'};
+          fwrite(suffix, 1, sizeof(suffix), file_);
+        }
+      }
+      mutex_.unlock();
+      if (did_write) {
+        if (FLAGS_flush_log) {
+          fflush(file_);
+        }
+      }
+      xe::threading::Wait(flush_event_.get(), true);
+    }
+  }
+
+  FILE* file_ = nullptr;
+  uint8_t buffer_[kBufferSize];
+  RingBuffer ring_buffer_;
+  std::mutex mutex_;
+  std::atomic<bool> running_;
+  std::unique_ptr<xe::threading::Event> flush_event_;
+  std::unique_ptr<xe::threading::Thread> write_thread_;
+};
+
+Logger logger_;
+
+void InitializeLogging(const std::wstring& app_name) {
+  logger_.Initialize(app_name);
 }
 
-void log_line(const char level_char, const char* fmt, ...) {
-  // SCOPE_profile_cpu_i("emu", "log_line");
-
+void LogLineFormat(const char level_char, const char* fmt, ...) {
   va_list args;
   va_start(args, fmt);
-  format_log_line(log_buffer.data(), log_buffer.capacity(), level_char, fmt,
-                  args);
+  size_t chars_written = vsnprintf(log_format_buffer_.data(),
+                                   log_format_buffer_.capacity(), fmt, args);
   va_end(args);
-
-  if (!FLAGS_fast_stdout) {
-    log_lock.lock();
-  }
-#if 0  // defined(OutputDebugString)
-  OutputDebugStringA(log_buffer.data());
-#else
-  fprintf(stdout, "%s", log_buffer.data());
-  if (FLAGS_flush_stdout) {
-    fflush(stdout);
-  }
-#endif  // OutputDebugString
-  if (!FLAGS_fast_stdout) {
-    log_lock.unlock();
-  }
+  logger_.AppendLine(xe::threading::current_thread_id(), level_char,
+                     log_format_buffer_.data(), chars_written);
 }
 
-void handle_fatal(const char* fmt, ...) {
+void LogLineVarargs(const char level_char, const char* fmt, va_list args) {
+  size_t chars_written = vsnprintf(log_format_buffer_.data(),
+                                   log_format_buffer_.capacity(), fmt, args);
+  logger_.AppendLine(xe::threading::current_thread_id(), level_char,
+                     log_format_buffer_.data(), chars_written);
+}
+
+void LogLine(const char level_char, const std::string& str) {
+  logger_.AppendLine(xe::threading::current_thread_id(), level_char,
+                     str.c_str(), str.length());
+}
+
+void FatalError(const char* fmt, ...) {
   va_list args;
   va_start(args, fmt);
-  format_log_line(log_buffer.data(), log_buffer.capacity(), 'X', fmt, args);
+  LogLineVarargs('X', fmt, args);
   va_end(args);
 
-  if (!FLAGS_fast_stdout) {
-    log_lock.lock();
-  }
-#if defined(OutputDebugString)
-  OutputDebugStringA(log_buffer.data());
-#else
-  fprintf(stderr, "%s", log_buffer.data());
-  fflush(stderr);
-#endif  // OutputDebugString
-  if (!FLAGS_fast_stdout) {
-    log_lock.unlock();
-  }
-
 #if XE_PLATFORM_WIN32
   if (!xe::has_console_attached()) {
-    MessageBoxA(NULL, log_buffer.data(), "Xenia Error",
+    va_start(args, fmt);
+    vsnprintf(log_format_buffer_.data(), log_format_buffer_.capacity(), fmt,
+              args);
+    va_end(args);
+    MessageBoxA(NULL, log_format_buffer_.data(), "Xenia Error",
                 MB_OK | MB_ICONERROR | MB_APPLMODAL | MB_SETFOREGROUND);
   }
 #endif  // WIN32
@@ -117,4 +179,6 @@ void handle_fatal(const char* fmt, ...) {
   exit(1);
 }
 
+void FatalError(const std::string& str) { FatalError(str.c_str()); }
+
 }  // namespace xe