Tracing support for the IR Interpreter

CMakeLists.txt

@@ -2342,6 +2342,8 @@ add_library(${CoreLibName} ${CoreLinkType}
 	Core/MIPS/MIPSVFPUFallbacks.h
 	Core/MIPS/MIPSAsm.cpp
 	Core/MIPS/MIPSAsm.h
+	Core/MIPS/MIPSTracer.cpp
+	Core/MIPS/MIPSTracer.h
 	Core/MemFault.cpp
 	Core/MemFault.h
 	Core/MemMap.cpp

Core/Core.cpp

@@ -43,6 +43,7 @@
 #include "Core/MIPS/MIPS.h"
 #include "Core/HLE/sceNetAdhoc.h"
 #include "GPU/Debugger/Stepping.h"
+#include "Core/MIPS/MIPSTracer.h"
 
 #ifdef _WIN32
 #include "Common/CommonWindows.h"
@@ -334,6 +335,9 @@ bool Core_Run(GraphicsContext *ctx) {
 
 void Core_EnableStepping(bool step, const char *reason, u32 relatedAddress) {
 	if (step) {
+		// Stop the tracer
+		mipsTracer.stop_tracing();
+
 		Core_UpdateState(CORE_STEPPING);
 		steppingCounter++;
 		_assert_msg_(reason != nullptr, "No reason specified for break");

Core/Core.vcxproj

@@ -992,6 +992,7 @@
     <ClCompile Include="MIPS\MIPSIntVFPU.cpp" />
     <ClCompile Include="MIPS\MIPSTables.cpp" />
     <ClCompile Include="MIPS\MIPSVFPUUtils.cpp" />
+    <ClCompile Include="MIPS\MIPSTracer.cpp" />
     <ClCompile Include="MIPS\MIPS\MipsJit.cpp">
       <ExcludedFromBuild Condition="'$(Configuration)|$(Platform)'=='Debug|Win32'">true</ExcludedFromBuild>
       <ExcludedFromBuild Condition="'$(Configuration)|$(Platform)'=='Release|Win32'">true</ExcludedFromBuild>
@@ -1406,6 +1407,7 @@
     <ClInclude Include="MIPS\MIPSIntVFPU.h" />
     <ClInclude Include="MIPS\MIPSTables.h" />
     <ClInclude Include="MIPS\MIPSVFPUUtils.h" />
+    <ClInclude Include="MIPS\MIPSTracer.h" />
     <ClInclude Include="MIPS\MIPS\MipsJit.h">
       <ExcludedFromBuild Condition="'$(Configuration)|$(Platform)'=='Debug|Win32'">true</ExcludedFromBuild>
       <ExcludedFromBuild Condition="'$(Configuration)|$(Platform)'=='Release|Win32'">true</ExcludedFromBuild>

Core/Core.vcxproj.filters

@@ -123,6 +123,9 @@
     <ClCompile Include="MIPS\MIPSVFPUUtils.cpp">
       <Filter>MIPS</Filter>
     </ClCompile>
+    <ClCompile Include="MIPS\MIPSTracer.cpp">
+      <Filter>MIPS</Filter>
+    </ClCompile>
     <ClCompile Include="MIPS\MIPSAnalyst.cpp">
       <Filter>MIPS</Filter>
     </ClCompile>
@@ -1347,6 +1350,9 @@
     <ClInclude Include="MIPS\MIPSVFPUUtils.h">
       <Filter>MIPS</Filter>
     </ClInclude>
+    <ClInclude Include="MIPS\MIPSTracer.h">
+      <Filter>MIPS</Filter>
+    </ClInclude>
     <ClInclude Include="MIPS\MIPSAnalyst.h">
       <Filter>MIPS</Filter>
     </ClInclude>

Core/MIPS/IR/IRFrontend.cpp

@@ -28,6 +28,9 @@
 #include "Core/MIPS/IR/IRRegCache.h"
 #include "Core/MIPS/IR/IRPassSimplify.h"
 #include "Core/MIPS/IR/IRInterpreter.h"
+#include "Core/MIPS/MIPSTracer.h"
+
+#include <iterator>
 
 namespace MIPSComp {
 
@@ -299,7 +302,17 @@ void IRFrontend::DoJit(u32 em_address, std::vector<IRInst> &instructions, u32 &m
 		//	logBlocks = 1;
 	}
 
-	instructions = code->GetInstructions();
+	if (!mipsTracer.tracing_enabled) {
+		instructions = code->GetInstructions();
+	}
+	else {
+		std::vector<IRInst> block_instructions = code->GetInstructions();
+		instructions.reserve(block_instructions.capacity());
+		// The first instruction is "Downcount"
+		instructions.push_back(block_instructions.front());
+		instructions.push_back({ IROp::LogIRBlock, 0, 0, 0, 0 });
+		std::copy(block_instructions.begin() + 1, block_instructions.end(), std::back_inserter(instructions));
+	}
 
 	if (logBlocks > 0 && dontLogBlocks == 0) {
 		char temp2[256];

Core/MIPS/IR/IRInst.cpp

@@ -189,6 +189,8 @@ static const IRMeta irMeta[] = {
 	{ IROp::RestoreRoundingMode, "RestoreRoundingMode", "" },
 	{ IROp::ApplyRoundingMode, "ApplyRoundingMode", "" },
 	{ IROp::UpdateRoundingMode, "UpdateRoundingMode", "" },
+
+	{IROp::LogIRBlock, "LogIRBlock", ""}
 };
 
 const IRMeta *metaIndex[256];

Core/MIPS/IR/IRInst.h

@@ -237,6 +237,9 @@ enum class IROp : uint8_t {
 	ValidateAddress32,
 	ValidateAddress128,
 
+	// Tracing support.
+	LogIRBlock,
+
 	Nop,
 	Bad,
 };

Core/MIPS/IR/IRInterpreter.cpp

@@ -32,6 +32,7 @@
 #include "Core/MIPS/IR/IRInst.h"
 #include "Core/MIPS/IR/IRInterpreter.h"
 #include "Core/System.h"
+#include "Core/MIPS/MIPSTracer.h"
 
 #ifdef mips
 // Why do MIPS compilers define something so generic?  Try to keep defined, at least...
@@ -1236,6 +1237,11 @@ u32 IRInterpret(MIPSState *mips, const IRInst *inst) {
 				return mips->pc;
 			}
 			break;
+		case IROp::LogIRBlock:
+			if (mipsTracer.tracing_enabled) {
+				mipsTracer.executed_blocks.push_back(inst->constant);
+			}
+			break;
 
 		case IROp::Nop: // TODO: This shouldn't crash, but for now we should not emit nops, so...
 		case IROp::Bad:

Core/MIPS/IR/IRJit.cpp

@@ -42,6 +42,8 @@
 #include "Core/MIPS/JitCommon/JitCommon.h"
 #include "Core/Reporting.h"
 #include "Common/TimeUtil.h"
+#include "Core/MIPS/MIPSTracer.h"
+
 
 namespace MIPSComp {
 
@@ -165,14 +167,20 @@ bool IRJit::CompileBlock(u32 em_address, std::vector<IRInst> &instructions, u32
 	}
 
 	IRBlock *b = blocks_.GetBlock(block_num);
-	if (preload) {
+	if (preload || mipsTracer.tracing_enabled) {
 		// Hash, then only update page stats, don't link yet.
 		// TODO: Should we always hash?  Then we can reuse blocks.
 		b->UpdateHash();
 	}
+
 	if (!CompileNativeBlock(&blocks_, block_num, preload))
 		return false;
-	// Overwrites the first instruction, and also updates stats.
+
+	if (mipsTracer.tracing_enabled) {
+		mipsTracer.prepare_block(b, blocks_);
+	}
+
+	// Updates stats, also patches the first MIPS instruction into an emuhack if 'preload == false'
 	blocks_.FinalizeBlock(block_num, preload);
 	if (!preload)
 		FinalizeNativeBlock(&blocks_, block_num);

Core/MIPS/IR/IRJit.h

@@ -91,6 +91,9 @@ class IRBlock {
 	u32 GetOriginalStart() const {
 		return origAddr_;
 	}
+	u64 GetHash() const {
+		return hash_;
+	}
 
 	void Finalize(int number);
 	void Destroy(int number);

Core/MIPS/MIPSTracer.cpp

@@ -0,0 +1,207 @@
+// Copyright (c) 2024- PPSSPP Project.
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, version 2.0 or later versions.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+// GNU General Public License 2.0 for more details.
+
+// A copy of the GPL 2.0 should have been included with the program.
+// If not, see http://www.gnu.org/licenses/
+
+// Official git repository and contact information can be found at
+// https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/.
+
+#include "Core/MIPS/MIPSTracer.h"
+
+#include <cstring> // for std::memcpy
+#include "Core/MIPS/MIPSTables.h" // for MIPSDisAsm
+#include "Core/MemMap.h" // for Memory::GetPointerUnchecked
+#include "Common/File/FileUtil.h" // for the File::OpenCFile
+
+
+bool TraceBlockStorage::save_block(const u32* instructions, u32 size) {
+	// 'size' is measured in bytes
+	const auto indexes_count = size / 4;
+
+	if (cur_index + 1 + indexes_count >= raw_instructions.size()) {
+		return false;
+	}
+
+	// Save the size first
+	*cur_data_ptr = size;
+	++cur_data_ptr;
+
+	// Now save the MIPS instructions
+	std::memcpy(cur_data_ptr, instructions, size);
+	cur_data_ptr += indexes_count;
+
+	cur_index += 1 + indexes_count;
+	return true;
+}
+
+void TraceBlockStorage::initialize(u32 capacity) {
+	raw_instructions.resize(capacity);
+	cur_index = 0;
+	cur_data_ptr = raw_instructions.data();
+	INFO_LOG(Log::JIT, "TraceBlockStorage initialized: capacity=0x%x", capacity);
+}
+
+void TraceBlockStorage::clear() {
+	raw_instructions.clear();
+	cur_index = 0;
+	cur_data_ptr = nullptr;
+	INFO_LOG(Log::JIT, "TraceBlockStorage cleared");
+}
+
+void MIPSTracer::prepare_block(MIPSComp::IRBlock* block, MIPSComp::IRBlockCache& blocks) {
+	u32 virt_addr, size;
+	block->GetRange(&virt_addr, &size);
+
+	u64 hash = block->GetHash();
+	auto it = hash_to_storage_index.find(hash);
+
+	u32 storage_index;
+	if (it != hash_to_storage_index.end()) {
+		// We've seen this one before => it's saved in our storage
+		storage_index = it->second;
+	}
+	else {
+		// We haven't seen a block like that before, let's save it
+		auto mips_instructions_ptr = (const u32*)Memory::GetPointerUnchecked(virt_addr);
+
+		storage_index = storage.cur_index;
+		if (!storage.save_block(mips_instructions_ptr, size)) {
+			// We ran out of storage!
+			WARN_LOG(Log::JIT, "The MIPSTracer ran out of storage for the blocks, cannot proceed!");
+			stop_tracing();
+			return;
+		}
+		// Successfully inserted the block at index 'storage_index'!
+
+		hash_to_storage_index.emplace(hash, storage_index);
+	}
+
+	// NB!
+	// If for some reason the blocks get invalidated while tracing, PPSSPP will be forced to recompile
+	// the same code again => the 'trace_info' will be filled with duplicates, because we can't detect that...
+	// If we store the TraceBlockInfo instances in an unordered_map, we won't be able to reference the entries
+	// by using the 4 byte IRInst field 'constant' (the iterators won't fit there).
+	// And, of course, doing a linear search in the vector is not worth the conserved space.
+	trace_info.push_back({ virt_addr, storage_index });
+
+
+	u32 index = trace_info.size() - 1;
+	auto ir_ptr = (IRInst*)blocks.GetBlockInstructionPtr(*block);
+	ir_ptr[1].constant = index;
+}
+
+bool MIPSTracer::flush_to_file() {
+	INFO_LOG(Log::JIT, "Flushing the trace to a file...");
+	output = File::OpenCFile(logging_path, "w");
+
+	if (!output) {
+		WARN_LOG(Log::JIT, "MIPSTracer failed to open the file '%s'", logging_path.c_str());
+		return false;
+	}
+	auto trace = executed_blocks.get_content();
+	for (auto index : trace) {
+		auto& block_info = trace_info[index];
+		flush_block_to_file(block_info);
+	}
+
+	INFO_LOG(Log::JIT, "Trace flushed, closing the file...");
+	std::fclose(output);
+
+	clear();
+	return true;
+}
+
+void MIPSTracer::flush_block_to_file(TraceBlockInfo& block_info) {
+	char buffer[512];
+
+	// The log format is '{prefix}{disassembled line}', where 'prefix' is '0x{8 hex digits of the address}: '
+	const auto prefix_size = 2 + 8 + 2;
+
+	u32 addr = block_info.virt_address;
+	u32 index = block_info.storage_index;
+
+	u32 size = storage[index];
+	++index;
+
+	u32 end_addr = addr + size;
+
+
+	for (; addr < end_addr; addr += 4, ++index) {
+		snprintf(buffer, sizeof(buffer), "0x%08x: ", addr);
+		MIPSDisAsm(storage.read_asm(index), addr, buffer + prefix_size, sizeof(buffer) - prefix_size, true);
+
+		std::fprintf(output, "%s\n", buffer);
+	}
+}
+
+void MIPSTracer::start_tracing() {
+	if (!tracing_enabled) {
+		INFO_LOG(Log::JIT, "MIPSTracer enabled");
+		tracing_enabled = true;
+	}
+}
+
+void MIPSTracer::stop_tracing() {
+	if (tracing_enabled) {
+		INFO_LOG(Log::JIT, "MIPSTracer disabled");
+		tracing_enabled = false;
+
+#ifdef _DEBUG
+		print_stats();
+#endif
+	}
+}
+
+inline void MIPSTracer::print_stats() const {
+	// First, the storage
+	INFO_LOG(Log::JIT, "=============== MIPSTracer storage ===============");
+	INFO_LOG(Log::JIT, "Current index = %d, storage size = %d", storage.cur_index, storage.raw_instructions.size());
+
+	// Then the cyclic buffer
+	if (executed_blocks.overflow) {
+		INFO_LOG(Log::JIT, "=============== MIPSTracer cyclic buffer (overflow) ===============");
+		INFO_LOG(Log::JIT, "Trace size = %d, starts from index %d", executed_blocks.buffer.size(), executed_blocks.current_index);
+	}
+	else {
+		INFO_LOG(Log::JIT, "=============== MIPSTracer cyclic buffer (no overflow) ===============");
+		INFO_LOG(Log::JIT, "Trace size = %d, starts from index 0", executed_blocks.current_index);
+	}
+	// Next, the hash-to-index mapping
+	INFO_LOG(Log::JIT, "=============== MIPSTracer hashes ===============");
+	INFO_LOG(Log::JIT, "Number of unique hashes = %d", hash_to_storage_index.size());
+
+	// Finally, the basic block list
+	INFO_LOG(Log::JIT, "=============== MIPSTracer basic block list ===============");
+	INFO_LOG(Log::JIT, "Number of processed basic blocks = %d", trace_info.size());
+
+	INFO_LOG(Log::JIT, "=============== MIPSTracer stats end ===============");
+}
+
+void MIPSTracer::initialize(u32 storage_capacity, u32 max_trace_size) {
+	executed_blocks.resize(max_trace_size);
+	hash_to_storage_index.reserve(max_trace_size);
+	storage.initialize(storage_capacity);
+	trace_info.reserve(max_trace_size);
+	INFO_LOG(Log::JIT, "MIPSTracer initialized: storage_capacity=0x%x, max_trace_size=%d", storage_capacity, max_trace_size);
+}
+
+void MIPSTracer::clear() {
+	executed_blocks.clear();
+	hash_to_storage_index.clear();
+	storage.clear();
+	trace_info.clear();
+	INFO_LOG(Log::JIT, "MIPSTracer cleared");
+}
+
+MIPSTracer mipsTracer;
+
+