Adding thread handle to logging.

src/xenia/base/logging.cc

@@ -12,6 +12,7 @@
 #include <gflags/gflags.h>
 
 #include <atomic>
+#include <cinttypes>
 #include <cstdarg>
 #include <mutex>
 #include <vector>
@@ -34,11 +35,24 @@ DEFINE_bool(flush_log, true, "Flush log file after each log line batch.");
 
 namespace xe {
 
+class Logger;
+
+Logger* logger_ = nullptr;
 thread_local std::vector<char> log_format_buffer_(64 * 1024);
 
 class Logger {
  public:
-  Logger() : ring_buffer_(buffer_, kBufferSize), running_(true) {
+  Logger(const std::wstring& app_name)
+      : ring_buffer_(buffer_, kBufferSize), running_(true) {
+    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");
+    }
+
     flush_event_ = xe::threading::Event::CreateAutoResetEvent(false);
     write_thread_ =
         xe::threading::Thread::Create({}, [this]() { WriteThread(); });
@@ -53,17 +67,6 @@ class Logger {
     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;
@@ -104,8 +107,24 @@ class Logger {
         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, '>', ' '};
+        char prefix[] = {
-        fwrite(prefix, 1, sizeof(prefix), file_);
+            line.level_char,
+            '>',
+            ' ',
+            '0',  // Thread ID gets placed here (8 chars).
+            '0',
+            '0',
+            '0',
+            '0',
+            '0',
+            '0',
+            '0',
+            ' ',
+            0,
+        };
+        std::snprintf(prefix + 3, sizeof(prefix) - 3, "%08" PRIX32 " ",
+                      line.thread_id);
+        fwrite(prefix, 1, sizeof(prefix) - 1, 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'};
@@ -131,10 +150,9 @@ class Logger {
   std::unique_ptr<xe::threading::Thread> write_thread_;
 };
 
-Logger logger_;
-
 void InitializeLogging(const std::wstring& app_name) {
-  logger_.Initialize(app_name);
+  // We leak this intentionally - lots of cleanup code needs it.
+  logger_ = new Logger(app_name);
 }
 
 void LogLineFormat(const char level_char, const char* fmt, ...) {
@@ -143,19 +161,25 @@ void LogLineFormat(const char level_char, const char* fmt, ...) {
   size_t chars_written = vsnprintf(log_format_buffer_.data(),
                                    log_format_buffer_.capacity(), fmt, args);
   va_end(args);
-  logger_.AppendLine(xe::threading::current_thread_id(), level_char,
+  logger_->AppendLine(xe::threading::current_thread_id(), level_char,
                       log_format_buffer_.data(), chars_written);
 }
 
 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,
+  logger_->AppendLine(xe::threading::current_thread_id(), level_char,
                       log_format_buffer_.data(), chars_written);
 }
 
+void LogLine(const char level_char, const char* str, size_t str_length) {
+  logger_->AppendLine(
+      xe::threading::current_thread_id(), level_char, str,
+      str_length == std::string::npos ? std::strlen(str) : str_length);
+}
+
 void LogLine(const char level_char, const std::string& str) {
-  logger_.AppendLine(xe::threading::current_thread_id(), level_char,
+  logger_->AppendLine(xe::threading::current_thread_id(), level_char,
                       str.c_str(), str.length());
 }
 

src/xenia/base/logging.h

@@ -27,6 +27,8 @@ void InitializeLogging(const std::wstring& app_name);
 void LogLineFormat(const char level_char, const char* fmt, ...);
 void LogLineVarargs(const char level_char, const char* fmt, va_list args);
 // Appends a line to the log.
+void LogLine(const char level_char, const char* str,
+             size_t str_length = std::string::npos);
 void LogLine(const char level_char, const std::string& str);
 
 // Logs a fatal error with printf-style formatting and aborts the program.

src/xenia/base/string_buffer.cc

@@ -16,12 +16,15 @@
 
 namespace xe {
 
-StringBuffer::StringBuffer(size_t initial_capacity) : buffer_offset_(0) {
+StringBuffer::StringBuffer(size_t initial_capacity) {
   buffer_capacity_ = std::max(initial_capacity, static_cast<size_t>(16 * 1024));
   buffer_ = reinterpret_cast<char*>(malloc(buffer_capacity_));
 }
 
-StringBuffer::~StringBuffer() { free(buffer_); }
+StringBuffer::~StringBuffer() {
+  free(buffer_);
+  buffer_ = nullptr;
+}
 
 void StringBuffer::Reset() { buffer_offset_ = 0; }
 

src/xenia/base/threading.cc

@@ -0,0 +1,25 @@
+/**
+ ******************************************************************************
+ * Xenia : Xbox 360 Emulator Research Project                                 *
+ ******************************************************************************
+ * Copyright 2015 Ben Vanik. All rights reserved.                             *
+ * Released under the BSD license - see LICENSE in the root for more details. *
+ ******************************************************************************
+ */
+
+#include "xenia/base/threading.h"
+
+namespace xe {
+namespace threading {
+
+thread_local uint32_t current_thread_id_ = UINT_MAX;
+
+uint32_t current_thread_id() {
+  return current_thread_id_ == UINT_MAX ? current_thread_system_id()
+                                        : current_thread_id_;
+}
+
+void set_current_thread_id(uint32_t id) { current_thread_id_ = id; }
+
+}  // namespace threading
+}  // namespace xe

src/xenia/base/threading.h

@@ -56,7 +56,13 @@ void EnableAffinityConfiguration();
 
 // Gets a stable thread-specific ID, but may not be. Use for informative
 // purposes only.
+uint32_t current_thread_system_id();
+
+// Gets a stable thread-specific ID that defaults to the same value as
+// current_thread_system_id but may be overridden.
+// Guest threads often change this to the guest thread handle.
 uint32_t current_thread_id();
+void set_current_thread_id(uint32_t id);
 
 // Sets the current thread name.
 void set_name(const std::string& name);
@@ -345,8 +351,8 @@ class Thread : public WaitHandle {
   // threads that had been waiting for the thread to terminate.
   static void Exit(int exit_code);
 
-  // Returns the ID of the thread
+  // Returns the ID of the thread.
-  virtual uint32_t id() const = 0;
+  virtual uint32_t system_id() const = 0;
 
   // Returns the current name of the thread, if previously specified.
   std::string name() const { return name_; }

src/xenia/base/threading_win.cc

@@ -35,7 +35,7 @@ void EnableAffinityConfiguration() {
   SetProcessAffinityMask(process_handle, system_affinity_mask);
 }
 
-uint32_t current_thread_id() {
+uint32_t current_thread_system_id() {
   return static_cast<uint32_t>(GetCurrentThreadId());
 }
 
@@ -358,7 +358,7 @@ class Win32Thread : public Win32Handle<Thread> {
   }
 
   int32_t priority() override { return GetThreadPriority(handle_); }
-  uint32_t id() const override { return GetThreadId(handle_); }
+  uint32_t system_id() const override { return GetThreadId(handle_); }
 
   void set_priority(int32_t new_priority) override {
     SetThreadPriority(handle_, new_priority);

src/xenia/cpu/mmio_handler_win.cc

@@ -67,7 +67,8 @@ LONG CALLBACK MMIOExceptionHandler(PEXCEPTION_POINTERS ex_info) {
     return EXCEPTION_CONTINUE_SEARCH;
   }
 
-  SCOPE_profile_cpu_i("cpu", "MMIOExceptionHandler");
+  // Disabled because this can cause odd issues during handling.
+  // SCOPE_profile_cpu_i("cpu", "MMIOExceptionHandler");
 
   // http://msdn.microsoft.com/en-us/library/ms679331(v=vs.85).aspx
   // http://msdn.microsoft.com/en-us/library/aa363082(v=vs.85).aspx

src/xenia/cpu/thread_state.cc

@@ -41,7 +41,7 @@ ThreadState::ThreadState(Processor* processor, uint32_t thread_id,
   if (thread_id_ == UINT_MAX) {
     // System thread. Assign the system thread ID with a high bit
     // set so people know what's up.
-    uint32_t system_thread_handle = xe::threading::current_thread_id();
+    uint32_t system_thread_handle = xe::threading::current_thread_system_id();
     thread_id_ = 0x80000000 | system_thread_handle;
   }
   backend_data_ = processor->backend()->AllocThreadData();

src/xenia/kernel/objects/xthread.cc

@@ -34,8 +34,8 @@ DEFINE_bool(ignore_thread_affinities, true,
 namespace xe {
 namespace kernel {
 
-uint32_t next_xthread_id = 0;
+uint32_t next_xthread_id_ = 0;
-thread_local XThread* current_thread_tls = nullptr;
+thread_local XThread* current_thread_tls_ = nullptr;
 xe::mutex critical_region_;
 
 XThread::XThread(KernelState* kernel_state, uint32_t stack_size,
@@ -43,7 +43,7 @@ XThread::XThread(KernelState* kernel_state, uint32_t stack_size,
                  uint32_t start_context, uint32_t creation_flags,
                  bool guest_thread)
     : XObject(kernel_state, kTypeThread),
-      thread_id_(++next_xthread_id),
+      thread_id_(++next_xthread_id_),
       guest_thread_(guest_thread) {
   creation_params_.stack_size = stack_size;
   creation_params_.xapi_thread_startup = xapi_thread_startup;
@@ -90,11 +90,13 @@ XThread::~XThread() {
   }
 }
 
-bool XThread::IsInThread(XThread* other) { return current_thread_tls == other; }
+bool XThread::IsInThread(XThread* other) {
-bool XThread::IsInThread() { return current_thread_tls != nullptr; }
+  return current_thread_tls_ == other;
+}
+bool XThread::IsInThread() { return current_thread_tls_ != nullptr; }
 
 XThread* XThread::GetCurrentThread() {
-  XThread* thread = current_thread_tls;
+  XThread* thread = current_thread_tls_;
   if (!thread) {
     assert_always("Attempting to use kernel stuff from a non-kernel thread");
   }
@@ -221,7 +223,7 @@ X_STATUS XThread::Create() {
   thread_state_ = new cpu::ThreadState(
       kernel_state()->processor(), thread_id_, cpu::ThreadStackType::kUserStack,
       0, creation_params_.stack_size, pcr_address_);
-  XELOGI("XThread%04X (%X) Stack: %.8X-%.8X", handle(),
+  XELOGI("XThread%08X (%X) Stack: %.8X-%.8X", handle(),
          thread_state_->thread_id(), thread_state_->stack_limit(),
          thread_state_->stack_base());
 
@@ -298,6 +300,9 @@ X_STATUS XThread::Create() {
   params.stack_size = 16 * 1024 * 1024;  // Ignore game, always big!
   params.create_suspended = true;
   thread_ = xe::threading::Thread::Create(params, [this]() {
+    // Set thread ID override. This is used by logging.
+    xe::threading::set_current_thread_id(handle());
+
     // Set name immediately, if we have one.
     thread_->set_name(name());
 
@@ -305,9 +310,9 @@ X_STATUS XThread::Create() {
     xe::Profiler::ThreadEnter(name().c_str());
 
     // Execute user code.
-    current_thread_tls = this;
+    current_thread_tls_ = this;
     Execute();
-    current_thread_tls = nullptr;
+    current_thread_tls_ = nullptr;
 
     xe::Profiler::ThreadExit();
 
@@ -326,7 +331,7 @@ X_STATUS XThread::Create() {
   if (name_.empty()) {
     char thread_name[32];
     snprintf(thread_name, xe::countof(thread_name), "XThread%04X (%04X)",
-             handle(), thread_->id());
+             handle(), thread_->system_id());
     set_name(thread_name);
   }
 
@@ -365,7 +370,7 @@ X_STATUS XThread::Exit(int exit_code) {
   }
 
   // NOTE: unless PlatformExit fails, expect it to never return!
-  current_thread_tls = nullptr;
+  current_thread_tls_ = nullptr;
   xe::Profiler::ThreadExit();
 
   running_ = false;
@@ -399,8 +404,7 @@ X_STATUS XThread::Terminate(int exit_code) {
 
 void XThread::Execute() {
   XELOGKERNEL("XThread::Execute thid %d (handle=%.8X, '%s', native=%.8X)",
-              thread_id_, handle(), name_.c_str(),
+              thread_id_, handle(), name_.c_str(), thread_->system_id());
-              xe::threading::current_thread_id());
   running_ = true;
 
   // Let the kernel know we are starting.
@@ -694,7 +698,7 @@ XHostThread::XHostThread(KernelState* kernel_state, uint32_t stack_size,
 void XHostThread::Execute() {
   XELOGKERNEL(
       "XThread::Execute thid %d (handle=%.8X, '%s', native=%.8X, <host>)",
-      thread_id_, handle(), name_.c_str(), xe::threading::current_thread_id());
+      thread_id_, handle(), name_.c_str(), thread_->system_id());
 
   // Let the kernel know we are starting.
   kernel_state()->OnThreadExecute(this);

src/xenia/kernel/objects/xuser_module.cc

@@ -268,7 +268,7 @@ X_STATUS XUserModule::Launch(uint32_t flags) {
 
   // We know this is the 'main thread'.
   char thread_name[32];
-  std::snprintf(thread_name, xe::countof(thread_name), "Main XThread %04X",
+  std::snprintf(thread_name, xe::countof(thread_name), "Main XThread%08X",
                 thread->handle());
   thread->set_name(thread_name);
 

src/xenia/kernel/util/shim_utils.h

@@ -394,11 +394,10 @@ void PrintKernelCall(cpu::Export* export_entry, const Tuple& params) {
   string_buffer.Append('(');
   AppendKernelCallParams(string_buffer, export_entry, params);
   string_buffer.Append(')');
-  auto str = string_buffer.GetString();
   if (export_entry->tags & ExportTag::kImportant) {
-    XELOGI(str);
+    xe::LogLine('i', string_buffer.GetString(), string_buffer.length());
   } else {
-    XELOGD(str);
+    xe::LogLine('d', string_buffer.GetString(), string_buffer.length());
   }
 }