diff --git a/byond-extools/src/core/core.cpp b/byond-extools/src/core/core.cpp index 3c697954..6dd5b4bf 100644 --- a/byond-extools/src/core/core.cpp +++ b/byond-extools/src/core/core.cpp @@ -23,6 +23,7 @@ ExecutionContext** Core::parent_context_ptr_hack; ProcSetupEntry** Core::proc_setup_table; unsigned int* Core::some_flags_including_profile; +unsigned int Core::extended_profiling_insanely_hacky_check_if_its_a_new_call_or_resume; std::map Core::opcode_handlers; std::map Core::name_to_opcode; @@ -95,19 +96,19 @@ void Core::disable_profiling() const char* good = "gucci"; const char* bad = "pain"; -extern "C" EXPORT const char* enable_profiling(int n_args, const char* args) +extern "C" EXPORT const char* enable_profiling(int n_args, const char** args) { Core::enable_profiling(); return good; } -extern "C" EXPORT const char* disable_profiling(int n_args, const char* args) +extern "C" EXPORT const char* disable_profiling(int n_args, const char** args) { Core::disable_profiling(); return good; } -extern "C" EXPORT const char* core_initialize(int n_args, const char* args) +extern "C" EXPORT const char* core_initialize(int n_args, const char** args) { if (!Core::initialize()) { @@ -115,18 +116,18 @@ extern "C" EXPORT const char* core_initialize(int n_args, const char* args) return bad; } optimizer_initialize(); - extended_profiling_initialize(); + //extended_profiling_initialize(); return good; } -extern "C" EXPORT const char* tffi_initialize(int n_args, const char* args) +extern "C" EXPORT const char* tffi_initialize(int n_args, const char** args) { if (!(Core::initialize() && TFFI::initialize())) return bad; return good; } -extern "C" EXPORT const char* proxy_initialize(int n_args, const char* args) +extern "C" EXPORT const char* proxy_initialize(int n_args, const char** args) { if (!(Core::initialize() && Proxy::initialize())) return bad; @@ -135,9 +136,29 @@ extern "C" EXPORT const char* proxy_initialize(int n_args, const char* args) void init_testing(); void run_tests(); -extern "C" EXPORT const char* run_tests(int n_args, const char* args) +extern "C" EXPORT const char* run_tests(int n_args, const char** args) { init_testing(); run_tests(); return good; +} + +extern "C" EXPORT const char* extended_profiling_initialize(int n_args, const char** args) +{ + if (!(Core::initialize() && actual_extended_profiling_initialize())) + return bad; + return good; +} + +extern "C" EXPORT const char* enable_extended_profiling(int n_args, const char** args) +{ + //Core::Alert("Enabling logging for " + std::string(args[0])); + Core::get_proc(args[0]).extended_profile(); + return good; +} + +extern "C" EXPORT const char* disable_extended_profiling(int n_args, const char** args) +{ + procs_to_profile.erase(Core::get_proc(args[0]).id); //TODO: improve consistency and reconsider how initialization works + return good; } \ No newline at end of file diff --git a/byond-extools/src/core/core.h b/byond-extools/src/core/core.h index 075d2b0e..1a09419b 100644 --- a/byond-extools/src/core/core.h +++ b/byond-extools/src/core/core.h @@ -24,6 +24,7 @@ namespace Core extern ExecutionContext** parent_context_ptr_hack; extern ProcSetupEntry** proc_setup_table; extern unsigned int* some_flags_including_profile; + extern unsigned int extended_profiling_insanely_hacky_check_if_its_a_new_call_or_resume; ExecutionContext* get_context(); ExecutionContext* _get_parent_context(); unsigned int register_opcode(std::string name, opcode_handler handler); diff --git a/byond-extools/src/core/hooking.cpp b/byond-extools/src/core/hooking.cpp index bd8a7aeb..e19c1f0a 100644 --- a/byond-extools/src/core/hooking.cpp +++ b/byond-extools/src/core/hooking.cpp @@ -18,12 +18,14 @@ CallGlobalProcPtr oCallGlobalProc; trvh __cdecl hCallGlobalProc(char unk1, int unk2, int proc_type, unsigned int proc_id, int const_0, char unk3, int unk4, Value* argList, unsigned int argListLen, int const_0_2, int const_0_3) { + Core::extended_profiling_insanely_hacky_check_if_its_a_new_call_or_resume = proc_id; if (proc_hooks.find(proc_id) != proc_hooks.end()) { trvh result = proc_hooks[proc_id](argList, argListLen); return result; } trvh result = oCallGlobalProc(unk1, unk2, proc_type, proc_id, const_0, unk3, unk4, argList, argListLen, const_0_2, const_0_3); + Core::extended_profiling_insanely_hacky_check_if_its_a_new_call_or_resume = -1; return result; } diff --git a/byond-extools/src/core/various_testing.cpp b/byond-extools/src/core/various_testing.cpp index 93ce50c5..96f91959 100644 --- a/byond-extools/src/core/various_testing.cpp +++ b/byond-extools/src/core/various_testing.cpp @@ -54,7 +54,7 @@ trvh update_light_objects; void init_testing() { Core::enable_profiling(); - Core::get_proc("/datum/explosion/New").extended_profile(); + //Core::get_proc("/datum/explosion/New").extended_profile(); //Core::get_proc("/client/verb/test_reentry").extended_profile(); //Core::get_proc("/client/verb/test_extended_profiling").extended_profile(); //extended_profiling_procs[.id] = true; diff --git a/byond-extools/src/dm/_extools_api.dm b/byond-extools/src/dm/_extools_api.dm index eba47ead..102042c4 100644 --- a/byond-extools/src/dm/_extools_api.dm +++ b/byond-extools/src/dm/_extools_api.dm @@ -50,7 +50,7 @@ */ /proc/tffi_initialize() - call(EXTOOLS, "tffi_initialize")() == EXTOOLS_SUCCESS + return call(EXTOOLS, "tffi_initialize")() == EXTOOLS_SUCCESS var/fallback_alerted = FALSE var/next_promise_id = 0 @@ -108,4 +108,36 @@ var/next_promise_id = 0 P.__resolve_callback() /proc/call_wait() - return call_async(arglist(args)).resolve() \ No newline at end of file + return call_async(arglist(args)).resolve() + +/* + Extended Profiling - High precision in-depth performance profiling. + + Turning on extended profiling for a proc will cause each execution of it to generate a file in the ./profiles directory + containing a breakdown of time spent executing the proc and each sub-proc it calls. Import the file into https://www.speedscope.app/ to + view a good visual representation. + + Be aware that sleeping counts as stopping and restarting the execution of the proc, which will generate multiple files, one between each sleep. + + For large procs the profiles may become unusably large. Optimizations pending. + + Example: + + start_profiling(/datum/explosion/New) + + - Enables profiling for /datum/explosion/New(), which will produce a detailed breakdown of each explosion that occurs afterwards. + + stop_profiling(/datum/explosion/New) + + - Disables profiling for explosions. Any currently running profiles will stop when the proc finishes executing or enters a sleep. + +*/ + +/proc/profiling_initialize() + return call(EXTOOLS, "extended_profiling_initialize")() == EXTOOLS_SUCCESS + +/proc/start_profiling(procpath) + call(EXTOOLS, "enable_extended_profiling")("[procpath]") + +/proc/stop_profiling(procpath) + call(EXTOOLS, "disable_extended_profiling")("[procpath]") \ No newline at end of file diff --git a/byond-extools/src/extended_profiling/extended_profiling.cpp b/byond-extools/src/extended_profiling/extended_profiling.cpp index 173c0839..84b043d8 100644 --- a/byond-extools/src/extended_profiling/extended_profiling.cpp +++ b/byond-extools/src/extended_profiling/extended_profiling.cpp @@ -4,6 +4,8 @@ #include #include +#define STUPID_READOUTS_LIMIT 10000000 + ProcCleanupPtr oProcCleanup; CreateContextPtr oCreateContext; SuspendPtr oSuspend; @@ -14,7 +16,6 @@ std::unordered_map procs_to_profile; unsigned int next_profile_id = 1; std::unordered_map sleeping_profiles; -std::unordered_map profiles_by_id; void output_subcalls(std::string base, std::ofstream& output, ExtendedProfile* profile) { @@ -23,7 +24,16 @@ void output_subcalls(std::string base, std::ofstream& output, ExtendedProfile* p if (!(profile->subcalls.empty())) { - output << base << " " << TOMICROS(profile->subcalls.front()->start_time - profile->start_time) << "\n"; + unsigned long long time = TOMICROS(profile->subcalls.front()->start_time - profile->start_time); + if (time > STUPID_READOUTS_LIMIT) + { + time = 1; + } + if (time) + { + output << base << " " << time << "\n"; + } + for (ExtendedProfile* sub : profile->subcalls) { //Core::Alert( ("End: " + std::to_string(sub->end_time.time_since_epoch().count())).c_str()); @@ -31,37 +41,105 @@ void output_subcalls(std::string base, std::ofstream& output, ExtendedProfile* p output_subcalls(base + ";", output, sub); } ExtendedProfile* last_sub = profile->subcalls.back(); - output << base << " " << TOMICROS(profile->end_time - last_sub->end_time) << "\n"; + time = TOMICROS(profile->end_time - last_sub->end_time); + if (time > STUPID_READOUTS_LIMIT) + { + time = 1; + } + if (time) + { + output << base << " " << time << "\n"; + } + + } + else + { + unsigned long long time = TOMICROS(profile->end_time - profile->start_time); + if (time > STUPID_READOUTS_LIMIT) + { + time = 1; + } + if (time) + { + output << base << " " << time << "\n"; + } } //base.pop_back(); //Core::Alert(std::to_string(profile->end_time.time_since_epoch().count()).c_str()); //Core::Alert(std::to_string(profile->start_time.time_since_epoch().count()).c_str()); - output << base << " " << TOMICROS(profile->end_time - profile->start_time) << "\n"; } void dump_extended_profile(ExtendedProfile* profile) { - std::ofstream output("extended_profile.txt", std::fstream::app); + std::string procname = Core::get_proc(profile->proc_id); + std::replace(procname.begin(), procname.end(), '/', '.'); + CreateDirectoryA("profiling", NULL); + std::string filename = "./profiling/extended_profile" + procname + "." + std::to_string(profile->id) + ".txt"; + std::ofstream output(filename, std::fstream::app); + if (!output.is_open()) + { + Core::Alert("Failed to open file!"); + return; + } output_subcalls("", output, profile); output.flush(); } std::unordered_map profiles; +void recursive_start(ExtendedProfile* profile) +{ + for (ExtendedProfile* subcall : profile->subcalls) + { + subcall->start_timer(); + recursive_start(subcall); + } +} + void hCreateContext(ProcConstants* constants, ExecutionContext* new_context) { + //Core::Alert("HELLO?"); oCreateContext(constants, new_context); new_context = Core::get_context(); - if (procs_to_profile.find(constants->proc_id) != procs_to_profile.end()) + if (profiles.find(constants->proc_id) != profiles.end() || (Core::extended_profiling_insanely_hacky_check_if_its_a_new_call_or_resume == constants->proc_id && sleeping_profiles.find(constants->proc_id) != sleeping_profiles.end())) { + //Core::Alert("Profile already exists for " + Core::get_proc(constants->proc_id).name); + return; + } + if (procs_to_profile.find(constants->proc_id) != procs_to_profile.end() || sleeping_profiles.find(constants->proc_id) != sleeping_profiles.end()) + { + //Core::Alert("Creating profile for: " + Core::get_proc(constants->proc_id).name); int hash = new_context->hash(); + if (sleeping_profiles.find(constants->proc_id) != sleeping_profiles.end()) + { + //Core::Alert("Reusing sleeping profile"); + /*ExtendedProfile* profile = sleeping_profiles[constants->proc_id]; + profile->hash = hash; + profiles[hash] = profile; + sleeping_profiles.erase(constants->proc_id); + profile->start_timer(); + recursive_start(profile);*/ + ExtendedProfile* sleepy = sleeping_profiles[constants->proc_id]; + ExtendedProfile* profile = new ExtendedProfile; + profile->proc_id = constants->proc_id; + profile->id = sleepy->id; + profile->hash = hash; + profile->call_stack.push_back(profile); + profiles[constants->proc_id] = profile; + delete sleepy; + sleeping_profiles.erase(constants->proc_id); + profile->start_timer(); + return; + } ExtendedProfile* profile = new ExtendedProfile; profile->proc_id = constants->proc_id; + profile->id = next_profile_id++; profile->hash = hash; profile->call_stack.push_back(profile); - profiles[hash] = profile; + profiles[constants->proc_id] = profile; profile->start_timer(); + procs_to_profile.erase(constants->proc_id); } else { @@ -78,7 +156,7 @@ void hCreateContext(ProcConstants* constants, ExecutionContext* new_context) for (std::pair& p : profiles) { ExtendedProfile* ep = p.second; - if (ep->call_stack.size() < 15 && ep->call_stack.back()->proc_id == parent_context->constants->proc_id) + if (ep->call_stack.size() < 50 && ep->call_stack.back()->proc_id == parent_context->constants->proc_id) { ExtendedProfile* subprofile = new ExtendedProfile; subprofile->proc_id = constants->proc_id; @@ -92,29 +170,56 @@ void hCreateContext(ProcConstants* constants, ExecutionContext* new_context) } } + +void recursive_suspend(ExtendedProfile* profile) +{ + for (ExtendedProfile* subcall : profile->subcalls) + { + subcall->stop_timer(); + recursive_suspend(subcall); + } +} + void hProcCleanup(ExecutionContext* ctx) { int hash = ctx->hash(); int proc_id = ctx->constants->proc_id; - if (profiles.find(hash) != profiles.end()) + if (sleeping_profiles.find(proc_id) == sleeping_profiles.end()) { - ExtendedProfile* profile = profiles[hash]; - profile->stop_timer(); - //Core::Alert("Destroying profile for: " + Core::get_proc(proc_id).name); - if (profile->call_stack.back() != profile) + if (profiles.find(proc_id) != profiles.end()) { - Core::Alert("Profile call stack not empty!"); - } - dump_extended_profile(profile); - for (ExtendedProfile* sub : profile->subcalls) - { - delete sub; + ExtendedProfile* profile = profiles[proc_id]; + profile->stop_timer(); + //Core::Alert("Destroying profile for: " + Core::get_proc(proc_id).name); + if (profile->call_stack.back() != profile) + { + Core::Alert("Profile call stack not empty!"); + do + { + ExtendedProfile* subprofile = profile->call_stack.back(); + subprofile->stop_timer(); + profile->call_stack.pop_back(); + } while (profile->call_stack.back() != profile); + } + //recursive_suspend(profile); + dump_extended_profile(profile); + for (ExtendedProfile* sub : profile->subcalls) + { + delete sub; + } + delete profile; + profiles.erase(proc_id); + //procs_to_profile.erase(proc_id); + oProcCleanup(ctx); + procs_to_profile[proc_id] = true; + return; } - delete profile; - profiles.erase(hash); - oProcCleanup(ctx); - return; } + else + { + //Core::Alert("Found in sleeping procs, skipped profile destruction"); + } + for (std::pair& p : profiles) { ExtendedProfile* ep = p.second; @@ -130,12 +235,30 @@ void hProcCleanup(ExecutionContext* ctx) oProcCleanup(ctx); } -bool extended_profiling_initialize() +SuspendedProc* hSuspend(ExecutionContext* ctx, int unknown) +{ + int proc_id = ctx->constants->proc_id; + int hash = ctx->hash(); + if (/*procs_to_profile.find(proc_id) != procs_to_profile.end() || */profiles.find(proc_id) != profiles.end()) + { + //profiles[proc_id]->stop_timer(); + //Core::Alert("Marking as sleepy"); + ExtendedProfile* profile = profiles[proc_id]; + sleeping_profiles[proc_id] = profile; + profile->stop_timer(); + //recursive_suspend(profile); + dump_extended_profile(profile); + profiles.erase(proc_id); + } + return oSuspend(ctx, unknown); +} + +bool actual_extended_profiling_initialize() { oCreateContext = (CreateContextPtr)Core::install_hook(CreateContext, hCreateContext); oProcCleanup = (ProcCleanupPtr)Core::install_hook(ProcCleanup, hProcCleanup); - //oSuspend = (SuspendPtr)Core::install_hook(Suspend, hSuspend); - return oCreateContext && oProcCleanup; + oSuspend = (SuspendPtr)Core::install_hook(Suspend, hSuspend); + return oCreateContext && oProcCleanup && oSuspend; return true; } diff --git a/byond-extools/src/extended_profiling/extended_profiling.h b/byond-extools/src/extended_profiling/extended_profiling.h index a6ebbc8e..8fa3e651 100644 --- a/byond-extools/src/extended_profiling/extended_profiling.h +++ b/byond-extools/src/extended_profiling/extended_profiling.h @@ -9,6 +9,8 @@ struct ExtendedProfile { unsigned int proc_id; int hash; + unsigned int id; + unsigned long long total; std::vector subcalls; std::vector call_stack; std::chrono::time_point start_time; @@ -20,4 +22,4 @@ struct ExtendedProfile }; extern std::unordered_map procs_to_profile; -bool extended_profiling_initialize(); \ No newline at end of file +bool actual_extended_profiling_initialize(); \ No newline at end of file