From 28d3ba3ffd8d9f5bb211fc79cb8ab360764c7818 Mon Sep 17 00:00:00 2001 From: msreis Date: Sun, 5 Mar 2023 14:37:11 +0200 Subject: [PATCH] Fix missing time for some script functions in profiler Fixes the issue by adding a mechanism by which the functions that were previously disappearing can be profiled too. This is optional with an editor setting, since collecting more information naturally slows the engine further while profiling. Fixes #23715, #40251, #29049 --- core/object/script_language.h | 2 + core/object/script_language_extension.cpp | 1 + core/object/script_language_extension.h | 1 + doc/classes/EditorSettings.xml | 3 + doc/classes/ScriptLanguageExtension.xml | 6 + editor/debugger/editor_profiler.cpp | 18 ++ editor/debugger/editor_profiler.h | 6 + editor/debugger/script_editor_debugger.cpp | 4 + editor/editor_settings.cpp | 1 + modules/gdscript/gdscript.cpp | 74 +++++++- modules/gdscript/gdscript.h | 3 + modules/gdscript/gdscript_function.h | 8 + modules/gdscript/gdscript_vm.cpp | 190 +++++++++++---------- modules/mono/csharp_script.h | 1 + servers/debugger/servers_debugger.cpp | 14 +- servers/debugger/servers_debugger.h | 1 + 16 files changed, 240 insertions(+), 93 deletions(-) diff --git a/core/object/script_language.h b/core/object/script_language.h index 696c9a94a5f5..52e74dfb247a 100644 --- a/core/object/script_language.h +++ b/core/object/script_language.h @@ -419,10 +419,12 @@ class ScriptLanguage : public Object { uint64_t call_count; uint64_t total_time; uint64_t self_time; + uint64_t internal_time; }; virtual void profiling_start() = 0; virtual void profiling_stop() = 0; + virtual void profiling_set_save_native_calls(bool opt) = 0; virtual int profiling_get_accumulated_data(ProfilingInfo *p_info_arr, int p_info_max) = 0; virtual int profiling_get_frame_data(ProfilingInfo *p_info_arr, int p_info_max) = 0; diff --git a/core/object/script_language_extension.cpp b/core/object/script_language_extension.cpp index 0df9d5833440..50d8095af514 100644 --- a/core/object/script_language_extension.cpp +++ b/core/object/script_language_extension.cpp @@ -139,6 +139,7 @@ void ScriptLanguageExtension::_bind_methods() { GDVIRTUAL_BIND(_profiling_start); GDVIRTUAL_BIND(_profiling_stop); + GDVIRTUAL_BIND(_profiling_set_save_native_calls, "opt"); GDVIRTUAL_BIND(_profiling_get_accumulated_data, "info_array", "info_max"); GDVIRTUAL_BIND(_profiling_get_frame_data, "info_array", "info_max"); diff --git a/core/object/script_language_extension.h b/core/object/script_language_extension.h index 79cf71211961..a51777cbab1b 100644 --- a/core/object/script_language_extension.h +++ b/core/object/script_language_extension.h @@ -578,6 +578,7 @@ class ScriptLanguageExtension : public ScriptLanguage { EXBIND0(profiling_start) EXBIND0(profiling_stop) + EXBIND1(profiling_set_save_native_calls, bool) GDVIRTUAL2R(int, _profiling_get_accumulated_data, GDExtensionPtr, int) diff --git a/doc/classes/EditorSettings.xml b/doc/classes/EditorSettings.xml index 996af71c3b02..0fd2b4708fa1 100644 --- a/doc/classes/EditorSettings.xml +++ b/doc/classes/EditorSettings.xml @@ -182,6 +182,9 @@ + + If [code]true[/code], enables collection of profiling data from non-GDScript Godot functions, such as engine class methods. Enabling this slows execution while profiling further. + The size of the profiler's frame history. The default value (3600) allows seeing up to 60 seconds of profiling if the project renders at a constant 60 FPS. Higher values allow viewing longer periods of profiling in the graphs, especially when the project is running at high framerates. diff --git a/doc/classes/ScriptLanguageExtension.xml b/doc/classes/ScriptLanguageExtension.xml index 52c9ab4e9324..2e5ffe475ba9 100644 --- a/doc/classes/ScriptLanguageExtension.xml +++ b/doc/classes/ScriptLanguageExtension.xml @@ -270,6 +270,12 @@ + + + + + + diff --git a/editor/debugger/editor_profiler.cpp b/editor/debugger/editor_profiler.cpp index b0d6135d522b..0e46e5fe134a 100644 --- a/editor/debugger/editor_profiler.cpp +++ b/editor/debugger/editor_profiler.cpp @@ -95,6 +95,7 @@ void EditorProfiler::clear() { plot_sigs.clear(); plot_sigs.insert("physics_frame_time"); plot_sigs.insert("category_frame_time"); + display_internal_profiles->set_visible(EDITOR_GET("debugger/profile_native_calls")); updating_frame = true; cursor_metric_edit->set_min(0); @@ -350,6 +351,10 @@ void EditorProfiler::_update_frame() { for (int j = m.categories[i].items.size() - 1; j >= 0; j--) { const Metric::Category::Item &it = m.categories[i].items[j]; + bool internal_func = (it.internal == it.total); + if (internal_func && m.categories[i].name == "Script Functions" && !display_internal_profiles->is_pressed()) { + continue; + } TreeItem *item = variables->create_item(category); item->set_cell_mode(0, TreeItem::CELL_MODE_CHECK); item->set_editable(0, true); @@ -361,6 +366,9 @@ void EditorProfiler::_update_frame() { item->set_tooltip_text(0, it.name + "\n" + it.script + ":" + itos(it.line)); float time = dtime == DISPLAY_SELF_TIME ? it.self : it.total; + if (!display_internal_profiles->is_pressed() && dtime == DISPLAY_SELF_TIME) { + time += it.internal; + } item->set_text(1, _get_time_as_text(m, time, it.calls)); @@ -402,6 +410,10 @@ void EditorProfiler::_clear_pressed() { _update_plot(); } +void EditorProfiler::_internal_profiles_pressed() { + _combo_changed(0); +} + void EditorProfiler::_notification(int p_what) { switch (p_what) { case NOTIFICATION_ENTER_TREE: @@ -633,6 +645,11 @@ EditorProfiler::EditorProfiler() { hb->add_child(display_time); + display_internal_profiles = memnew(CheckButton(TTR("Display internal functions"))); + display_internal_profiles->set_pressed(false); + display_internal_profiles->connect("pressed", callable_mp(this, &EditorProfiler::_internal_profiles_pressed)); + hb->add_child(display_internal_profiles); + hb->add_spacer(); hb->add_child(memnew(Label(TTR("Frame #:")))); @@ -685,6 +702,7 @@ EditorProfiler::EditorProfiler() { frame_metrics.resize(metric_size); EDITOR_DEF("debugger/profiler_frame_max_functions", 64); + EDITOR_DEF("debugger/profile_native_calls", false); frame_delay = memnew(Timer); frame_delay->set_wait_time(0.1); diff --git a/editor/debugger/editor_profiler.h b/editor/debugger/editor_profiler.h index eea8ed8365d2..674aeced2f15 100644 --- a/editor/debugger/editor_profiler.h +++ b/editor/debugger/editor_profiler.h @@ -33,6 +33,7 @@ #include "scene/gui/box_container.h" #include "scene/gui/button.h" +#include "scene/gui/check_button.h" #include "scene/gui/label.h" #include "scene/gui/option_button.h" #include "scene/gui/spin_box.h" @@ -65,6 +66,7 @@ class EditorProfiler : public VBoxContainer { int line = 0; float self = 0; float total = 0; + float internal = 0; int calls = 0; }; @@ -103,6 +105,8 @@ class EditorProfiler : public VBoxContainer { OptionButton *display_mode = nullptr; OptionButton *display_time = nullptr; + CheckButton *display_internal_profiles = nullptr; + SpinBox *cursor_metric_edit = nullptr; Vector frame_metrics; @@ -128,6 +132,8 @@ class EditorProfiler : public VBoxContainer { void _activate_pressed(); void _clear_pressed(); + void _internal_profiles_pressed(); + String _get_time_as_text(const Metric &m, float p_time, int p_calls); void _make_metric_ptrs(Metric &m); diff --git a/editor/debugger/script_editor_debugger.cpp b/editor/debugger/script_editor_debugger.cpp index f805a4aecd68..2ebe5d094248 100644 --- a/editor/debugger/script_editor_debugger.cpp +++ b/editor/debugger/script_editor_debugger.cpp @@ -710,6 +710,7 @@ void ScriptEditorDebugger::_parse_message(const String &p_msg, const Array &p_da int calls = frame.script_functions[i].call_count; float total = frame.script_functions[i].total_time; float self = frame.script_functions[i].self_time; + float internal = frame.script_functions[i].internal_time; EditorProfiler::Metric::Category::Item item; if (profiler_signature.has(signature)) { @@ -734,6 +735,7 @@ void ScriptEditorDebugger::_parse_message(const String &p_msg, const Array &p_da item.calls = calls; item.self = self; item.total = total; + item.internal = internal; funcs.items.write[i] = item; } @@ -1032,7 +1034,9 @@ void ScriptEditorDebugger::_profiler_activate(bool p_enable, int p_type) { // Add max funcs options to request. Array opts; int max_funcs = EDITOR_GET("debugger/profiler_frame_max_functions"); + bool include_native = EDITOR_GET("debugger/profile_native_calls"); opts.push_back(CLAMP(max_funcs, 16, 512)); + opts.push_back(include_native); msg_data.push_back(opts); } _put_msg("profiler:servers", msg_data); diff --git a/editor/editor_settings.cpp b/editor/editor_settings.cpp index 25c84e744755..2a3a3652139a 100644 --- a/editor/editor_settings.cpp +++ b/editor/editor_settings.cpp @@ -737,6 +737,7 @@ void EditorSettings::_load_defaults(Ref p_extra_config) { // Profiler EDITOR_SETTING(Variant::INT, PROPERTY_HINT_RANGE, "debugger/profiler_frame_history_size", 3600, "60,10000,1") + EDITOR_SETTING(Variant::BOOL, PROPERTY_HINT_NONE, "debugger/profile_native_calls", false, "") // HTTP Proxy _initial_set("network/http_proxy/host", ""); diff --git a/modules/gdscript/gdscript.cpp b/modules/gdscript/gdscript.cpp index 2646c1ad156d..bef21d8b729c 100644 --- a/modules/gdscript/gdscript.cpp +++ b/modules/gdscript/gdscript.cpp @@ -2083,6 +2083,8 @@ void GDScriptLanguage::profiling_start() { elem->self()->profile.last_frame_call_count = 0; elem->self()->profile.last_frame_self_time = 0; elem->self()->profile.last_frame_total_time = 0; + elem->self()->profile.native_calls.clear(); + elem->self()->profile.last_native_calls.clear(); elem = elem->next(); } @@ -2090,6 +2092,13 @@ void GDScriptLanguage::profiling_start() { #endif } +void GDScriptLanguage::profiling_set_save_native_calls(bool opt) { +#ifdef DEBUG_ENABLED + MutexLock lock(this->mutex); + profile_native_calls = opt; +#endif +} + void GDScriptLanguage::profiling_stop() { #ifdef DEBUG_ENABLED MutexLock lock(this->mutex); @@ -2104,17 +2113,33 @@ int GDScriptLanguage::profiling_get_accumulated_data(ProfilingInfo *p_info_arr, MutexLock lock(this->mutex); + profiling_collate_native_call_data(true); SelfList *elem = function_list.first(); while (elem) { if (current >= p_info_max) { break; } + int last_non_internal = current; p_info_arr[current].call_count = elem->self()->profile.call_count; p_info_arr[current].self_time = elem->self()->profile.self_time; p_info_arr[current].total_time = elem->self()->profile.total_time; p_info_arr[current].signature = elem->self()->profile.signature; - elem = elem->next(); current++; + + int nat_time = 0; + HashMap::ConstIterator nat_calls; + nat_calls = elem->self()->profile.native_calls.begin(); + while (nat_calls != elem->self()->profile.native_calls.end()) { + p_info_arr[current].call_count = nat_calls->value.call_count; + p_info_arr[current].total_time = nat_calls->value.total_time; + p_info_arr[current].self_time = nat_calls->value.total_time; + p_info_arr[current].signature = nat_calls->value.signature; + nat_time += nat_calls->value.total_time; + current++; + ++nat_calls; + } + p_info_arr[last_non_internal].internal_time = nat_time; + elem = elem->next(); } #endif @@ -2127,17 +2152,34 @@ int GDScriptLanguage::profiling_get_frame_data(ProfilingInfo *p_info_arr, int p_ #ifdef DEBUG_ENABLED MutexLock lock(this->mutex); + profiling_collate_native_call_data(false); SelfList *elem = function_list.first(); while (elem) { if (current >= p_info_max) { break; } if (elem->self()->profile.last_frame_call_count > 0) { + int last_non_internal = current; p_info_arr[current].call_count = elem->self()->profile.last_frame_call_count; p_info_arr[current].self_time = elem->self()->profile.last_frame_self_time; p_info_arr[current].total_time = elem->self()->profile.last_frame_total_time; p_info_arr[current].signature = elem->self()->profile.signature; current++; + + int nat_time = 0; + HashMap::ConstIterator nat_calls; + nat_calls = elem->self()->profile.last_native_calls.begin(); + while (nat_calls != elem->self()->profile.last_native_calls.end()) { + p_info_arr[current].call_count = nat_calls->value.call_count; + p_info_arr[current].total_time = nat_calls->value.total_time; + p_info_arr[current].self_time = nat_calls->value.total_time; + p_info_arr[current].internal_time = nat_calls->value.total_time; + p_info_arr[current].signature = nat_calls->value.signature; + nat_time += nat_calls->value.total_time; + current++; + ++nat_calls; + } + p_info_arr[last_non_internal].internal_time = nat_time; } elem = elem->next(); } @@ -2145,6 +2187,34 @@ int GDScriptLanguage::profiling_get_frame_data(ProfilingInfo *p_info_arr, int p_ return current; } +void GDScriptLanguage::profiling_collate_native_call_data(bool accumulated) { +#ifdef DEBUG_ENABLED + // The same native call can be called from multiple functions, so join them together here + // Only use the name of the function (ie signature.split[2]) + HashMap seen_nat_calls; + SelfList *elem = function_list.first(); + while (elem) { + HashMap *nat_calls; + HashMap::Iterator it; + nat_calls = accumulated ? &elem->self()->profile.native_calls : &elem->self()->profile.last_native_calls; + + it = nat_calls->begin(); + while (it != nat_calls->end()) { + Vector sig = it->value.signature.split("::"); + HashMap::ConstIterator already_found = seen_nat_calls.find(sig[2]); + if (already_found != seen_nat_calls.end()) { + already_found->value->total_time += it->value.total_time; + already_found->value->call_count += it->value.call_count; + elem->self()->profile.last_native_calls.remove(it); + } else { + seen_nat_calls.insert(sig[2], &it->value); + } + ++it; + } + elem = elem->next(); + } +#endif +} struct GDScriptDepSort { //must support sorting so inheritance works properly (parent must be reloaded first) @@ -2332,9 +2402,11 @@ void GDScriptLanguage::frame() { elem->self()->profile.last_frame_call_count = elem->self()->profile.frame_call_count; elem->self()->profile.last_frame_self_time = elem->self()->profile.frame_self_time; elem->self()->profile.last_frame_total_time = elem->self()->profile.frame_total_time; + elem->self()->profile.last_native_calls = elem->self()->profile.native_calls; elem->self()->profile.frame_call_count = 0; elem->self()->profile.frame_self_time = 0; elem->self()->profile.frame_total_time = 0; + elem->self()->profile.native_calls.clear(); elem = elem->next(); } } diff --git a/modules/gdscript/gdscript.h b/modules/gdscript/gdscript.h index 0117ed40ab24..f961c31e67ad 100644 --- a/modules/gdscript/gdscript.h +++ b/modules/gdscript/gdscript.h @@ -376,6 +376,7 @@ class GDScriptLanguage : public ScriptLanguage { SelfList::List function_list; bool profiling; + bool profile_native_calls; uint64_t script_frame_time; HashMap orphan_subclasses; @@ -525,6 +526,8 @@ class GDScriptLanguage : public ScriptLanguage { virtual void profiling_start() override; virtual void profiling_stop() override; + virtual void profiling_set_save_native_calls(bool opt) override; + void profiling_collate_native_call_data(bool accumulated); virtual int profiling_get_accumulated_data(ProfilingInfo *p_info_arr, int p_info_max) override; virtual int profiling_get_frame_data(ProfilingInfo *p_info_arr, int p_info_max) override; diff --git a/modules/gdscript/gdscript_function.h b/modules/gdscript/gdscript_function.h index 1a5e9eef53f9..556f2cd7dce0 100644 --- a/modules/gdscript/gdscript_function.h +++ b/modules/gdscript/gdscript_function.h @@ -543,6 +543,13 @@ class GDScriptFunction { uint64_t last_frame_call_count = 0; uint64_t last_frame_self_time = 0; uint64_t last_frame_total_time = 0; + typedef struct NativeProfile { + uint64_t call_count; + uint64_t total_time; + String signature; + } NativeProfile; + HashMap native_calls{}; + HashMap last_native_calls{}; } profile; #endif @@ -607,6 +614,7 @@ class GDScriptFunction { Variant call(GDScriptInstance *p_instance, const Variant **p_args, int p_argcount, Callable::CallError &r_err, CallState *p_state = nullptr); #ifdef DEBUG_ENABLED + void _profile_native_call(uint64_t t_taken, String function_name, String instance_class_name); void disassemble(const Vector &p_code_lines) const; #endif diff --git a/modules/gdscript/gdscript_vm.cpp b/modules/gdscript/gdscript_vm.cpp index 83d2ed6010f3..61d9102a1436 100644 --- a/modules/gdscript/gdscript_vm.cpp +++ b/modules/gdscript/gdscript_vm.cpp @@ -36,6 +36,7 @@ #include "gdscript_lambda_callable.h" #ifdef DEBUG_ENABLED + static String _get_script_name(const Ref