Skip to content

Commit

Permalink
Merge pull request #19457 from Nemoumbra/ir-mipslogger
Browse files Browse the repository at this point in the history
Tracing support for the IR Interpreter
  • Loading branch information
hrydgard authored Sep 16, 2024
2 parents a05bf2d + dcf98fe commit 94f0e7a
Show file tree
Hide file tree
Showing 18 changed files with 552 additions and 3 deletions.
2 changes: 2 additions & 0 deletions CMakeLists.txt
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 4 additions & 0 deletions Core/Core.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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");
Expand Down
2 changes: 2 additions & 0 deletions Core/Core.vcxproj
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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>
Expand Down
6 changes: 6 additions & 0 deletions Core/Core.vcxproj.filters
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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>
Expand Down
15 changes: 14 additions & 1 deletion Core/MIPS/IR/IRFrontend.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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 {

Expand Down Expand Up @@ -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];
Expand Down
2 changes: 2 additions & 0 deletions Core/MIPS/IR/IRInst.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -189,6 +189,8 @@ static const IRMeta irMeta[] = {
{ IROp::RestoreRoundingMode, "RestoreRoundingMode", "" },
{ IROp::ApplyRoundingMode, "ApplyRoundingMode", "" },
{ IROp::UpdateRoundingMode, "UpdateRoundingMode", "" },

{ IROp::LogIRBlock, "LogIRBlock", "" },
};

const IRMeta *metaIndex[256];
Expand Down
3 changes: 3 additions & 0 deletions Core/MIPS/IR/IRInst.h
Original file line number Diff line number Diff line change
Expand Up @@ -237,6 +237,9 @@ enum class IROp : uint8_t {
ValidateAddress32,
ValidateAddress128,

// Tracing support.
LogIRBlock,

Nop,
Bad,
};
Expand Down
6 changes: 6 additions & 0 deletions Core/MIPS/IR/IRInterpreter.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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...
Expand Down Expand Up @@ -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:
Expand Down
12 changes: 10 additions & 2 deletions Core/MIPS/IR/IRJit.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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 {

Expand Down Expand Up @@ -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);
Expand Down
3 changes: 3 additions & 0 deletions Core/MIPS/IR/IRJit.h
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,9 @@ class IRBlock {
u32 GetOriginalStart() const {
return origAddr_;
}
u64 GetHash() const {
return hash_;
}

void Finalize(int number);
void Destroy(int number);
Expand Down
207 changes: 207 additions & 0 deletions Core/MIPS/MIPSTracer.cpp
Original file line number Diff line number Diff line change
@@ -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(const 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(const 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;


Loading

0 comments on commit 94f0e7a

Please sign in to comment.