From a86b3821f2f71b8b71634723a6ca18a16cff9f0d Mon Sep 17 00:00:00 2001 From: Ben Vanik Date: Sat, 29 Aug 2015 20:49:17 -0700 Subject: [PATCH] Adding thread handle to logging. --- src/xenia/base/logging.cc | 70 ++++++++++++++++-------- src/xenia/base/logging.h | 2 + src/xenia/base/string_buffer.cc | 7 ++- src/xenia/base/threading.cc | 25 +++++++++ src/xenia/base/threading.h | 10 +++- src/xenia/base/threading_win.cc | 4 +- src/xenia/cpu/mmio_handler_win.cc | 3 +- src/xenia/cpu/thread_state.cc | 2 +- src/xenia/kernel/objects/xthread.cc | 32 ++++++----- src/xenia/kernel/objects/xuser_module.cc | 2 +- src/xenia/kernel/util/shim_utils.h | 5 +- 11 files changed, 113 insertions(+), 49 deletions(-) create mode 100644 src/xenia/base/threading.cc diff --git a/src/xenia/base/logging.cc b/src/xenia/base/logging.cc index f0fe335d0..d6cc807ba 100644 --- a/src/xenia/base/logging.cc +++ b/src/xenia/base/logging.cc @@ -12,6 +12,7 @@ #include #include +#include #include #include #include @@ -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 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, '>', ' '}; - fwrite(prefix, 1, sizeof(prefix), file_); + char prefix[] = { + 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 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,20 +161,26 @@ 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, - log_format_buffer_.data(), chars_written); + 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, - log_format_buffer_.data(), chars_written); + 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, - str.c_str(), str.length()); + logger_->AppendLine(xe::threading::current_thread_id(), level_char, + str.c_str(), str.length()); } void FatalError(const char* fmt, ...) { diff --git a/src/xenia/base/logging.h b/src/xenia/base/logging.h index 00f3dbd5f..9a846eca7 100644 --- a/src/xenia/base/logging.h +++ b/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. diff --git a/src/xenia/base/string_buffer.cc b/src/xenia/base/string_buffer.cc index b91db3d90..3f2a8bb79 100644 --- a/src/xenia/base/string_buffer.cc +++ b/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(16 * 1024)); buffer_ = reinterpret_cast(malloc(buffer_capacity_)); } -StringBuffer::~StringBuffer() { free(buffer_); } +StringBuffer::~StringBuffer() { + free(buffer_); + buffer_ = nullptr; +} void StringBuffer::Reset() { buffer_offset_ = 0; } diff --git a/src/xenia/base/threading.cc b/src/xenia/base/threading.cc new file mode 100644 index 000000000..40d89a6c0 --- /dev/null +++ b/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 diff --git a/src/xenia/base/threading.h b/src/xenia/base/threading.h index fdedec71e..9b77a5a52 100644 --- a/src/xenia/base/threading.h +++ b/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 - virtual uint32_t id() const = 0; + // Returns the ID of the thread. + virtual uint32_t system_id() const = 0; // Returns the current name of the thread, if previously specified. std::string name() const { return name_; } diff --git a/src/xenia/base/threading_win.cc b/src/xenia/base/threading_win.cc index 30ad0e4d3..b87192307 100644 --- a/src/xenia/base/threading_win.cc +++ b/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(GetCurrentThreadId()); } @@ -358,7 +358,7 @@ class Win32Thread : public Win32Handle { } 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); diff --git a/src/xenia/cpu/mmio_handler_win.cc b/src/xenia/cpu/mmio_handler_win.cc index 157be2567..f9ef3b919 100644 --- a/src/xenia/cpu/mmio_handler_win.cc +++ b/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 diff --git a/src/xenia/cpu/thread_state.cc b/src/xenia/cpu/thread_state.cc index a512f92a4..582f7cae3 100644 --- a/src/xenia/cpu/thread_state.cc +++ b/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(); diff --git a/src/xenia/kernel/objects/xthread.cc b/src/xenia/kernel/objects/xthread.cc index e950c1d9b..72dfcfadd 100644 --- a/src/xenia/kernel/objects/xthread.cc +++ b/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; -thread_local XThread* current_thread_tls = nullptr; +uint32_t next_xthread_id_ = 0; +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() { return current_thread_tls != nullptr; } +bool XThread::IsInThread(XThread* other) { + 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(), - xe::threading::current_thread_id()); + thread_id_, handle(), name_.c_str(), thread_->system_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, )", - 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); diff --git a/src/xenia/kernel/objects/xuser_module.cc b/src/xenia/kernel/objects/xuser_module.cc index 7605a7e94..1240ecb45 100644 --- a/src/xenia/kernel/objects/xuser_module.cc +++ b/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); diff --git a/src/xenia/kernel/util/shim_utils.h b/src/xenia/kernel/util/shim_utils.h index edfd524ce..5af5b33c3 100644 --- a/src/xenia/kernel/util/shim_utils.h +++ b/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()); } }