[Debugging] Slightly optimize iw4 reading log

This commit is contained in:
momo5502 2016-12-22 12:37:09 +01:00
parent 19730f1760
commit 403974b9cc
11 changed files with 87 additions and 107 deletions

View File

@ -6,6 +6,8 @@ namespace Components
symmetric_CTR FastFiles::CurrentCTR; symmetric_CTR FastFiles::CurrentCTR;
std::vector<std::string> FastFiles::ZonePaths; std::vector<std::string> FastFiles::ZonePaths;
bool FastFiles::StreamRead = false;
unsigned int FastFiles::CurrentZone; unsigned int FastFiles::CurrentZone;
unsigned int FastFiles::MaxZones; unsigned int FastFiles::MaxZones;
@ -381,6 +383,20 @@ namespace Components
Utils::Hook::Call<void(Game::XZoneInfo*, unsigned int)>(0x5BBAC0)(zoneInfo, zoneCount); Utils::Hook::Call<void(Game::XZoneInfo*, unsigned int)>(0x5BBAC0)(zoneInfo, zoneCount);
} }
#ifdef DEBUG
void FastFiles::LogStreamRead(int len)
{
*Game::g_streamPos += len;
if (FastFiles::StreamRead)
{
std::string data = fmt::sprintf("%d\n", len);
if (*Game::g_streamPosIndex == 2) data = fmt::sprintf("(%d)\n", len);
Utils::IO::WriteFile("userraw/logs/iw4_reads.log", data, true);
}
}
#endif
FastFiles::FastFiles() FastFiles::FastFiles()
{ {
Dvar::Register<bool>("ui_zoneDebug", false, Game::dvar_flag::DVAR_FLAG_SAVED, "Display current loaded zone."); Dvar::Register<bool>("ui_zoneDebug", false, Game::dvar_flag::DVAR_FLAG_SAVED, "Display current loaded zone.");
@ -465,6 +481,18 @@ namespace Components
Game::DB_LoadXAssets(&info, 1, true); Game::DB_LoadXAssets(&info, 1, true);
}); });
#ifdef DEBUG
// ZoneBuilder debugging
Utils::IO::WriteFile("userraw/logs/iw4_reads.log", "", false);
Utils::Hook(0x4A8FA0, FastFiles::LogStreamRead, HOOK_JUMP).install()->quick();
Utils::Hook(0x4BCB62, []()
{
FastFiles::StreamRead = true;
Utils::Hook::Call<void(bool)>(0x4B8DB0)(true); // currently set to Load_GfxWorld
FastFiles::StreamRead = false;
}, HOOK_CALL).install()->quick();
#endif
} }
FastFiles::~FastFiles() FastFiles::~FastFiles()

View File

@ -36,6 +36,8 @@ namespace Components
static unsigned int CurrentZone; static unsigned int CurrentZone;
static unsigned int MaxZones; static unsigned int MaxZones;
static bool StreamRead;
static Key CurrentKey; static Key CurrentKey;
static symmetric_CTR CurrentCTR; static symmetric_CTR CurrentCTR;
static std::vector<std::string> ZonePaths; static std::vector<std::string> ZonePaths;
@ -53,5 +55,7 @@ namespace Components
static int InflateInitDecrypt(z_streamp strm, const char *version, int stream_size); static int InflateInitDecrypt(z_streamp strm, const char *version, int stream_size);
static void LoadZonesStub(Game::XZoneInfo *zoneInfo, unsigned int zoneCount); static void LoadZonesStub(Game::XZoneInfo *zoneInfo, unsigned int zoneCount);
static void LogStreamRead(int len);
}; };
} }

View File

@ -104,9 +104,16 @@ namespace Components
} }
} }
void FileSystem::FileWriter::open() void FileSystem::FileWriter::open(bool append)
{ {
this->handle = Game::FS_FOpenFileWrite(this->filePath.data()); if (append)
{
this->handle = Game::FS_FOpenFileAppend(this->filePath.data());
}
else
{
this->handle = Game::FS_FOpenFileWrite(this->filePath.data());
}
} }
void FileSystem::FileWriter::close() void FileSystem::FileWriter::close()

View File

@ -70,7 +70,7 @@ namespace Components
class FileWriter class FileWriter
{ {
public: public:
FileWriter(std::string file) : filePath(file), handle(0) { this->open(); }; FileWriter(std::string file, bool append = false) : filePath(file), handle(0) { this->open(append); };
~FileWriter() { this->close(); }; ~FileWriter() { this->close(); };
void write(std::string data); void write(std::string data);
@ -79,7 +79,7 @@ namespace Components
int handle; int handle;
std::string filePath; std::string filePath;
void open(); void open(bool append = false);
void close(); void close();
}; };

View File

@ -141,54 +141,6 @@ namespace Components
Game::CL_SelectStringTableEntryInDvar_f(); Game::CL_SelectStringTableEntryInDvar_f();
} }
#ifdef DEBUG
FILE* QuickPatch::readLog = nullptr;
Utils::Hook QuickPatch::beginLoggingHook;
int* QuickPatch::g_streamPos = (int*)0x16E5554;
void QuickPatch::logReads(bool /*flush*/)
{
fopen_s(&readLog, "userraw/logs/iw4_reads.log", "w");
// call the original load func
__asm
{
push 1
call beginLoggingHook.original
add esp, 4
}
if(readLog)
{
fclose(readLog);
readLog = nullptr;
}
}
void QuickPatch::logXAssetRead(int len)
{
*g_streamPos = *g_streamPos + len;
if(!readLog) return;
fprintf(readLog, "%d\n", len);
fflush(readLog);
// manually flush file because otherwie when ZB crashes it wont get flushed
}
void QuickPatch::logXAssetVirtualRead(int len)
{
*g_streamPos = *g_streamPos + len;
if(!readLog) return;
fprintf(readLog, "(%d)\n", len);
fflush(readLog);
// manually flush file because otherwie when ZB crashes it wont get flushed
}
#endif
QuickPatch::QuickPatch() QuickPatch::QuickPatch()
{ {
// protocol version (workaround for hacks) // protocol version (workaround for hacks)
@ -481,12 +433,6 @@ namespace Components
Game::Con_DrawMiniConsole(0, 2, 4, (Game::CL_IsCgameInitialized() ? 1.0f : 0.4f)); Game::Con_DrawMiniConsole(0, 2, 4, (Game::CL_IsCgameInitialized() ? 1.0f : 0.4f));
} }
}); });
beginLoggingHook.initialize(0x4BCB62, QuickPatch::logReads, HOOK_CALL); // currently set to Load_GfxWorld
beginLoggingHook.install()->quick();
Utils::Hook(0x470E75, QuickPatch::logXAssetRead, HOOK_CALL).install()->quick();
Utils::Hook(0x4E0E0B, QuickPatch::logXAssetRead, HOOK_CALL).install()->quick();
Utils::Hook(0x470E5A, QuickPatch::logXAssetVirtualRead, HOOK_CALL).install()->quick();
#endif #endif
} }

View File

@ -31,14 +31,5 @@ namespace Components
static int MsgReadBitsCompressCheckSV(const char *from, char *to, int size); static int MsgReadBitsCompressCheckSV(const char *from, char *to, int size);
static int MsgReadBitsCompressCheckCL(const char *from, char *to, int size); static int MsgReadBitsCompressCheckCL(const char *from, char *to, int size);
static void CL_HandleRelayPacketCheck(Game::msg_t* msg, int client); static void CL_HandleRelayPacketCheck(Game::msg_t* msg, int client);
#ifdef DEBUG
static FILE* readLog;
static Utils::Hook beginLoggingHook;
static int* g_streamPos;
static void logReads(bool flush);
static void logXAssetRead(int len);
static void logXAssetVirtualRead(int len);
#endif
}; };
} }

View File

@ -278,6 +278,8 @@ namespace Game
searchpath_t* fs_searchpaths = (searchpath_t*)0x63D96E0; searchpath_t* fs_searchpaths = (searchpath_t*)0x63D96E0;
XBlock** g_streamBlocks = (XBlock**)0x16E554C; XBlock** g_streamBlocks = (XBlock**)0x16E554C;
int* g_streamPos = (int*)0x16E5554;
int* g_streamPosIndex = (int*)0x16E5578;
bool* g_lobbyCreateInProgress = (bool*)0x66C9BC2; bool* g_lobbyCreateInProgress = (bool*)0x66C9BC2;
party_t** partyIngame = (party_t**)0x1081C00; party_t** partyIngame = (party_t**)0x1081C00;

View File

@ -614,6 +614,8 @@ namespace Game
extern searchpath_t* fs_searchpaths; extern searchpath_t* fs_searchpaths;
extern XBlock** g_streamBlocks; extern XBlock** g_streamBlocks;
extern int* g_streamPos;
extern int* g_streamPosIndex;
extern bool* g_lobbyCreateInProgress; extern bool* g_lobbyCreateInProgress;
extern party_t** partyIngame; extern party_t** partyIngame;

View File

@ -9,7 +9,7 @@ namespace Utils
return std::ifstream(file).good(); return std::ifstream(file).good();
} }
void WriteFile(std::string file, std::string data) void WriteFile(std::string file, std::string data, bool append)
{ {
auto pos = file.find_last_of("/\\"); auto pos = file.find_last_of("/\\");
if (pos != std::string::npos) if (pos != std::string::npos)
@ -17,7 +17,7 @@ namespace Utils
CreateDirectory(file.substr(0, pos)); CreateDirectory(file.substr(0, pos));
} }
std::ofstream stream(file, std::ios::binary); std::ofstream stream(file, std::ios::binary | std::ofstream::out | (append ? std::ofstream::app : std::ofstream::out));
if (stream.is_open()) if (stream.is_open())
{ {

View File

@ -3,7 +3,7 @@ namespace Utils
namespace IO namespace IO
{ {
bool FileExists(std::string file); bool FileExists(std::string file);
void WriteFile(std::string file, std::string data); void WriteFile(std::string file, std::string data, bool append = false);
std::string ReadFile(std::string file); std::string ReadFile(std::string file);
bool CreateDirectory(std::string dir); bool CreateDirectory(std::string dir);
std::vector<std::string> ListFiles(std::string dir); std::vector<std::string> ListFiles(std::string dir);

View File

@ -64,11 +64,11 @@ namespace Utils
memset(this->blockSize, 0, sizeof(this->blockSize)); memset(this->blockSize, 0, sizeof(this->blockSize));
#ifdef DEBUG #ifdef DEBUG
if(this->writeLog) return; if (this->writeLog) return;
if(fopen_s(&this->writeLog, "userraw/logs/zb_writes.log", "w")) if (fopen_s(&this->writeLog, "userraw/logs/zb_writes.log", "w"))
{ {
Components::Logger::Print("WARNING: Couldn't open write log. Writes from ZoneBuilder will not be logged.\n"); Components::Logger::Print("WARNING: Couldn't open write log. Writes from ZoneBuilder will not be logged.\n");
} }
#endif #endif
} }
@ -87,10 +87,10 @@ namespace Utils
} }
#ifdef DEBUG #ifdef DEBUG
if(this->writeLog) if (this->writeLog)
{ {
fclose(this->writeLog); fclose(this->writeLog);
} }
#endif #endif
}; };
@ -112,8 +112,8 @@ namespace Utils
char* Stream::save(Game::XFILE_BLOCK_TYPES stream, const void * _str, size_t size, size_t count) char* Stream::save(Game::XFILE_BLOCK_TYPES stream, const void * _str, size_t size, size_t count)
{ {
// Only those seem to actually write data. // Only those seem to actually write data.
// everything else is allocated at runtime but XFILE_BLOCK_RUNTIME is the only one that actually allocates anything // everything else is allocated at runtime but XFILE_BLOCK_RUNTIME is the only one that actually allocates anything
// clearly half of this stuff is unused // clearly half of this stuff is unused
if (stream != Game::XFILE_BLOCK_TEMP && stream != Game::XFILE_BLOCK_VIRTUAL && stream != Game::XFILE_BLOCK_PHYSICAL && stream != Game::XFILE_BLOCK_INVALID) if (stream != Game::XFILE_BLOCK_TEMP && stream != Game::XFILE_BLOCK_VIRTUAL && stream != Game::XFILE_BLOCK_PHYSICAL && stream != Game::XFILE_BLOCK_INVALID)
{ {
this->increaseBlockSize(stream, size * count); this->increaseBlockSize(stream, size * count);
@ -130,8 +130,8 @@ namespace Utils
this->buffer.append(static_cast<const char*>(_str), size * count); this->buffer.append(static_cast<const char*>(_str), size * count);
// log the write for zonebuilder debugging // log the write for zonebuilder debugging
SAVE_LOG_WRITE(size * count); SAVE_LOG_WRITE(size * count);
if (this->data() != data && this->isCriticalSection()) if (this->data() != data && this->isCriticalSection())
{ {
@ -330,35 +330,35 @@ namespace Utils
#ifdef DEBUG #ifdef DEBUG
FILE* Stream::writeLog = nullptr; FILE* Stream::writeLog = nullptr;
int Stream::structLevel = 0; int Stream::structLevel = 0;
void Stream::enterStruct(const char* structName) void Stream::enterStruct(const char* structName)
{ {
if(!this->writeLog) return; if (!this->writeLog) return;
fprintf(this->writeLog, "%*s%s\n", this->structLevel++, "", structName); fprintf(this->writeLog, "%*s%s\n", this->structLevel++, "", structName);
} }
void Stream::leaveStruct() void Stream::leaveStruct()
{ {
if(!this->writeLog) return; if (!this->writeLog) return;
this->structLevel--; this->structLevel--;
if(this->structLevel < 0) { if (this->structLevel < 0) {
Components::Logger::Print("Stream::exitStruct underflow! All following writes will not be logged!\n"); Components::Logger::Print("Stream::exitStruct underflow! All following writes will not be logged!\n");
fclose(this->writeLog); fclose(this->writeLog);
this->writeLog = nullptr; this->writeLog = nullptr;
return; return;
} }
fprintf(this->writeLog, "%*s-----\n", this->structLevel, ""); fprintf(this->writeLog, "%*s-----\n", this->structLevel, "");
} }
void Stream::logWrite(int writeLen) void Stream::logWrite(int writeLen)
{ {
if(!this->writeLog) return; if (!this->writeLog) return;
fprintf(this->writeLog, "%*s%d\n", this->structLevel, "", writeLen); fprintf(this->writeLog, "%*s%d\n", this->structLevel, "", writeLen);
} }
#endif #endif
} }