Adding thread ID to trace lines and cleaning up their formatting.

src/xenia/cpu/global_exports.cc

@@ -9,6 +9,7 @@
 
 #include <xenia/cpu/global_exports.h>
 
+#include <xenia/logging.h>
 #include <xenia/cpu/cpu-private.h>
 #include <xenia/cpu/processor.h>
 #include <xenia/cpu/sdb.h>
@@ -75,16 +76,20 @@ void _cdecl XeAccessViolation(
 void _cdecl XeTraceKernelCall(
     xe_ppc_state_t* state, uint64_t cia, uint64_t call_ia,
     KernelExport* kernel_export) {
-  XELOGCPU("TRACE: %.8X -> k.%.8X (%s)",
-           (uint32_t)call_ia - 4, (uint32_t)cia,
-           kernel_export ? kernel_export->name : "unknown");
+  uint32_t thread_id = state->thread_state->thread_id();
+  xe_log_line("", thread_id, "XeTraceKernelCall", 't',
+              "KERNEL CALL: %.8X -> k.%.8X (%s)",
+              (uint32_t)call_ia - 4, (uint32_t)cia,
+              kernel_export ? kernel_export->name : "unknown");
 }
 
 void _cdecl XeTraceUserCall(
     xe_ppc_state_t* state, uint64_t cia, uint64_t call_ia,
     FunctionSymbol* fn) {
-  XELOGCPU("TRACE: %.8X -> u.%.8X (%s)",
-           (uint32_t)call_ia - 4, (uint32_t)cia, fn->name());
+  uint32_t thread_id = state->thread_state->thread_id();
+  xe_log_line("", thread_id, "XeTraceUserCall", 't',
+              "USER CALL %.8X -> u.%.8X (%s)",
+              (uint32_t)call_ia - 4, (uint32_t)cia, fn->name());
 }
 
 void _cdecl XeTraceBranch(
@@ -97,16 +102,45 @@ void _cdecl XeTraceBranch(
     target_ia = state->ctr;
     break;
   }
-  XELOGCPU("TRACE: %.8X -> b.%.8X",
-           (uint32_t)cia, (uint32_t)target_ia);
+
+  uint32_t thread_id = state->thread_state->thread_id();
+  xe_log_line("", thread_id, "XeTraceBranch", 't',
+              "BRANCH %.8X -> b.%.8X",
+              (uint32_t)cia, (uint32_t)target_ia);
 }
 
 void _cdecl XeTraceInstruction(
     xe_ppc_state_t* state, uint64_t cia, uint64_t data) {
+  char buffer[2048];
+  buffer[0] = 0;
+  int offset = 0;
+
+  ppc::InstrData i;
+  i.address = (uint32_t)cia;
+  i.code = (uint32_t)data;
+  i.type = ppc::GetInstrType(i.code);
+  if (i.type && i.type->disassemble) {
+    ppc::InstrDisasm d;
+    i.type->disassemble(i, d);
+    std::string disasm;
+    d.Dump(disasm);
+    offset += xesnprintfa(buffer + offset, XECOUNT(buffer) - offset,
+        "%.8X %.8X %s %s",
+        i.address, i.code,
+        i.type && i.type->emit ? " " : "X",
+        disasm.c_str());
+  } else {
+    offset += xesnprintfa(buffer + offset, XECOUNT(buffer) - offset,
+        "%.8X %.8X %s %s",
+        i.address, i.code,
+        i.type && i.type->emit ? " " : "X",
+        i.type ? i.type->name : "<unknown>");
+  }
+
   if (FLAGS_trace_registers) {
-    XELOGCPU(
+    offset += xesnprintfa(buffer + offset, XECOUNT(buffer) - offset,
         "\n"
-        " lr=%.16llX ctr=%.16llX  cr=%.4X    xer=%.16llX\n"
+        " lr=%.16llX ctr=%.16llX  cr=%.4X         xer=%.16llX\n"
         " r0=%.16llX  r1=%.16llX  r2=%.16llX  r3=%.16llX\n"
         " r4=%.16llX  r5=%.16llX  r6=%.16llX  r7=%.16llX\n"
         " r8=%.16llX  r9=%.16llX r10=%.16llX r11=%.16llX\n"
@@ -126,25 +160,8 @@ void _cdecl XeTraceInstruction(
         state->r[28], state->r[29], state->r[30], state->r[31]);
   }
 
-  ppc::InstrData i;
-  i.address = (uint32_t)cia;
-  i.code = (uint32_t)data;
-  i.type = ppc::GetInstrType(i.code);
-  if (i.type && i.type->disassemble) {
-    ppc::InstrDisasm d;
-    i.type->disassemble(i, d);
-    std::string disasm;
-    d.Dump(disasm);
-    XELOGCPU("TRACE: %.8X %.8X %s %s",
-           i.address, i.code,
-           i.type && i.type->emit ? " " : "X",
-           disasm.c_str());
-  } else {
-    XELOGCPU("TRACE: %.8X %.8X %s %s",
-           i.address, i.code,
-           i.type && i.type->emit ? " " : "X",
-           i.type ? i.type->name : "<unknown>");
-  }
+  uint32_t thread_id = state->thread_state->thread_id();
+  xe_log_line("", thread_id, "XeTraceInstruction", 't', buffer);
 
   // if (cia == 0x82012074) {
   //   printf("BREAKBREAKBREAK\n");

src/xenia/cpu/ppc/state.h

@@ -13,6 +13,14 @@
 #include <stdint.h>
 
 
+namespace xe {
+namespace cpu {
+class Processor;
+class ThreadState;
+}  // namespace cpu
+}  // namespace xe
+
+
 // namespace FPRF {
 //   enum FPRF_e {
 //     QUIET_NAN             = 0x00088000,
@@ -143,10 +151,9 @@ typedef struct XECACHEALIGN64 xe_ppc_state {
 
   // Runtime-specific data pointer. Used on callbacks to get access to the
   // current runtime and its data.
-  uint8_t* membase;
-  void* processor;
-  void* thread_state;
-  void* runtime;
+  uint8_t*                membase;
+  xe::cpu::Processor*     processor;
+  xe::cpu::ThreadState*   thread_state;
 
   void SetRegFromString(const char* name, const char* value);
   bool CompareRegWithString(const char* name, const char* value,

src/xenia/cpu/processor.cc

@@ -191,9 +191,10 @@ uint32_t Processor::CreateCallback(void (*callback)(void* data), void* data) {
 }
 
 ThreadState* Processor::AllocThread(uint32_t stack_size,
-                                    uint32_t thread_state_address) {
+                                    uint32_t thread_state_address,
+                                    uint32_t thread_id) {
   ThreadState* thread_state = new ThreadState(
-      this, stack_size, thread_state_address);
+      this, stack_size, thread_state_address, thread_id);
   return thread_state;
 }
 

src/xenia/cpu/processor.h

@@ -53,7 +53,8 @@ public:
 
   uint32_t CreateCallback(void (*callback)(void* data), void* data);
 
-  ThreadState* AllocThread(uint32_t stack_size, uint32_t thread_state_address);
+  ThreadState* AllocThread(uint32_t stack_size, uint32_t thread_state_address,
+                           uint32_t thread_id);
   void DeallocThread(ThreadState* thread_state);
   int Execute(ThreadState* thread_state, uint32_t address);
   uint64_t Execute(ThreadState* thread_state, uint32_t address, uint64_t arg0);

src/xenia/cpu/thread_state.cc

@@ -19,8 +19,9 @@ using namespace xe::cpu;
 
 ThreadState::ThreadState(
     Processor* processor,
-    uint32_t stack_size, uint32_t thread_state_address) :
-    stack_size_(stack_size), thread_state_address_(thread_state_address) {
+    uint32_t stack_size, uint32_t thread_state_address, uint32_t thread_id) :
+    stack_size_(stack_size), thread_state_address_(thread_state_address),
+    thread_id_(thread_id) {
   memory_ = processor->memory();
 
   stack_address_ = xe_memory_heap_alloc(memory_, 0, stack_size, 0);
@@ -42,6 +43,10 @@ ThreadState::~ThreadState() {
   xe_memory_release(memory_);
 }
 
+uint32_t ThreadState::thread_id() const {
+  return thread_id_;
+}
+
 xe_ppc_state_t* ThreadState::ppc_state() {
   return &ppc_state_;
 }

src/xenia/cpu/thread_state.h

@@ -25,9 +25,12 @@ class Processor;
 class ThreadState {
 public:
   ThreadState(Processor* processor,
-              uint32_t stack_size, uint32_t thread_state_address);
+              uint32_t stack_size, uint32_t thread_state_address,
+              uint32_t thread_id);
   ~ThreadState();
 
+  uint32_t thread_id() const;
+
   xe_ppc_state_t* ppc_state();
 
 private:
@@ -37,6 +40,7 @@ private:
 
   uint32_t stack_address_;
   uint32_t thread_state_address_;
+  uint32_t thread_id_;
 
   xe_ppc_state_t  ppc_state_;
 };

src/xenia/cpu/x64/x64_emitter.cc

@@ -616,8 +616,6 @@ void X64Emitter::GenerateBasicBlock(FunctionBlock* block) {
       fflush(stdout);
     }
 
-    TraceInstruction(i);
-
     if (!i.type) {
       XELOGCPU("Invalid instruction %.8X %.8X", ia, i.code);
       TraceInvalidInstruction(i);
@@ -634,6 +632,8 @@ void X64Emitter::GenerateBasicBlock(FunctionBlock* block) {
                ia, i.code, i.type->name);
       TraceInvalidInstruction(i);
     }
+
+    TraceInstruction(i);
   }
 
   // If we fall through, create the branch.

src/xenia/kernel/modules/xboxkrnl/objects/xthread.cc

@@ -31,7 +31,7 @@ XThread::XThread(KernelState* kernel_state,
     thread_id_(++next_xthread_id),
     thread_handle_(0),
     thread_state_address_(0),
-    processor_state_(0) {
+    thread_state_(0) {
   creation_params_.stack_size           = stack_size;
   creation_params_.xapi_thread_startup  = xapi_thread_startup;
   creation_params_.start_address        = start_address;
@@ -47,8 +47,8 @@ XThread::XThread(KernelState* kernel_state,
 XThread::~XThread() {
   PlatformDestroy();
 
-  if (processor_state_) {
-    kernel_state()->processor()->DeallocThread(processor_state_);
+  if (thread_state_) {
+    kernel_state()->processor()->DeallocThread(thread_state_);
   }
   if (tls_address_) {
     xe_memory_heap_free(kernel_state()->memory(), tls_address_, 0);
@@ -125,9 +125,9 @@ X_STATUS XThread::Create() {
 
   // Allocate processor thread state.
   // This is thread safe.
-  processor_state_ = kernel_state()->processor()->AllocThread(
-      creation_params_.stack_size, thread_state_address_);
-  if (!processor_state_) {
+  thread_state_ = kernel_state()->processor()->AllocThread(
+      creation_params_.stack_size, thread_state_address_, thread_id_);
+  if (!thread_state_) {
     XELOGW("Unable to allocate processor thread state");
     return X_STATUS_NO_MEMORY;
   }
@@ -261,7 +261,7 @@ void XThread::Execute() {
 
   // Run user code.
   int exit_code = (int)kernel_state()->processor()->Execute(
-      processor_state_,
+      thread_state_,
       creation_params_.start_address, creation_params_.start_context);
 
   // If we got here it means the execute completed without an exit being called.

src/xenia/kernel/modules/xboxkrnl/objects/xthread.h

@@ -57,7 +57,7 @@ private:
   void*         thread_handle_;
   uint32_t      tls_address_;
   uint32_t      thread_state_address_;
-  cpu::ThreadState* processor_state_;
+  cpu::ThreadState* thread_state_;
 };
 
 

tools/xenia-test/xenia-test.cc

@@ -146,7 +146,7 @@ int run_test(string& src_file_path) {
   XEEXPECTZERO(processor->LoadRawBinary(bin_file_path_str, 0x82010000));
 
   // Simulate a thread.
-  thread_state = processor->AllocThread(256 * 1024, 0);
+  thread_state = processor->AllocThread(256 * 1024, 0, 100);
 
   // Setup test state from annotations.
   XEEXPECTZERO(setup_test_state(memory, processor.get(), thread_state,