From f1cc14d5252b1c799a7960b3cced678eebb6ab2a 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 | 16 +++ editor/debugger/editor_profiler.h | 6 ++ editor/debugger/script_editor_debugger.cpp | 4 + editor/editor_settings.cpp | 1 + modules/gdscript/gdscript.cpp | 71 ++++++++++++- modules/gdscript/gdscript.h | 3 + modules/gdscript/gdscript_function.h | 8 ++ modules/gdscript/gdscript_vm.cpp | 110 +++++++++++---------- modules/mono/csharp_script.h | 1 + servers/debugger/servers_debugger.cpp | 14 ++- servers/debugger/servers_debugger.h | 1 + 16 files changed, 191 insertions(+), 57 deletions(-) diff --git a/core/object/script_language.h b/core/object/script_language.h index 85e64c8d62bd..69da50f0742f 100644 --- a/core/object/script_language.h +++ b/core/object/script_language.h @@ -384,10 +384,12 @@ public: 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 p_enable) = 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 e326baf7eb32..79f39cb62664 100644 --- a/core/object/script_language_extension.cpp +++ b/core/object/script_language_extension.cpp @@ -145,6 +145,7 @@ void ScriptLanguageExtension::_bind_methods() { GDVIRTUAL_BIND(_profiling_start); GDVIRTUAL_BIND(_profiling_stop); + GDVIRTUAL_BIND(_profiling_set_save_native_calls, "enable"); 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 00ab1cd6c01e..852b2aebd882 100644 --- a/core/object/script_language_extension.h +++ b/core/object/script_language_extension.h @@ -607,6 +607,7 @@ public: 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 98b492095339..93d2bb854871 100644 --- a/doc/classes/EditorSettings.xml +++ b/doc/classes/EditorSettings.xml @@ -185,6 +185,9 @@ If [code]true[/code], automatically switches to the [b]Remote[/b] scene tree when running the project from the editor. If [code]false[/code], stays on the [b]Local[/b] scene tree when running the project from the editor. + + 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 1a61618b53a9..b4e2f406127c 100644 --- a/doc/classes/ScriptLanguageExtension.xml +++ b/doc/classes/ScriptLanguageExtension.xml @@ -276,6 +276,12 @@ + + + + + + diff --git a/editor/debugger/editor_profiler.cpp b/editor/debugger/editor_profiler.cpp index f72538e3decb..d54fd62e8cc8 100644 --- a/editor/debugger/editor_profiler.cpp +++ b/editor/debugger/editor_profiler.cpp @@ -97,6 +97,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); @@ -352,6 +353,9 @@ 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]; + if (it.internal == it.total && !display_internal_profiles->is_pressed() && m.categories[i].name == "Script Functions") { + continue; + } TreeItem *item = variables->create_item(category); item->set_cell_mode(0, TreeItem::CELL_MODE_CHECK); item->set_editable(0, true); @@ -363,6 +367,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 (dtime == DISPLAY_SELF_TIME && !display_internal_profiles->is_pressed()) { + time += it.internal; + } item->set_text(1, _get_time_as_text(m, time, it.calls)); @@ -404,6 +411,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: @@ -635,6 +646,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 #:")))); diff --git a/editor/debugger/editor_profiler.h b/editor/debugger/editor_profiler.h index 3f7a0cade575..620d21fe98de 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" @@ -67,6 +68,7 @@ public: int line = 0; float self = 0; float total = 0; + float internal = 0; int calls = 0; }; @@ -105,6 +107,8 @@ private: OptionButton *display_mode = nullptr; OptionButton *display_time = nullptr; + CheckButton *display_internal_profiles = nullptr; + SpinBox *cursor_metric_edit = nullptr; Vector frame_metrics; @@ -130,6 +134,8 @@ private: 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 ab8df824e828..7077bce9f76f 100644 --- a/editor/debugger/script_editor_debugger.cpp +++ b/editor/debugger/script_editor_debugger.cpp @@ -758,6 +758,7 @@ void ScriptEditorDebugger::_parse_message(const String &p_msg, uint64_t p_thread 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)) { @@ -782,6 +783,7 @@ void ScriptEditorDebugger::_parse_message(const String &p_msg, uint64_t p_thread item.calls = calls; item.self = self; item.total = total; + item.internal = internal; funcs.items.write[i] = item; } @@ -1097,7 +1099,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 7fc870d17407..7a2e8a0aae03 100644 --- a/editor/editor_settings.cpp +++ b/editor/editor_settings.cpp @@ -776,6 +776,7 @@ void EditorSettings::_load_defaults(Ref p_extra_config) { EDITOR_SETTING(Variant::INT, PROPERTY_HINT_RANGE, "debugger/profiler_frame_max_functions", 64, "16,512,1") EDITOR_SETTING(Variant::FLOAT, PROPERTY_HINT_RANGE, "debugger/remote_scene_tree_refresh_interval", 1.0, "0.1,10,0.01,or_greater") EDITOR_SETTING(Variant::FLOAT, PROPERTY_HINT_RANGE, "debugger/remote_inspect_refresh_interval", 0.2, "0.02,10,0.01,or_greater") + 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 52235b18549b..a999acd1bd0d 100644 --- a/modules/gdscript/gdscript.cpp +++ b/modules/gdscript/gdscript.cpp @@ -2220,6 +2220,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(); } @@ -2227,6 +2229,13 @@ void GDScriptLanguage::profiling_start() { #endif } +void GDScriptLanguage::profiling_set_save_native_calls(bool p_enable) { +#ifdef DEBUG_ENABLED + MutexLock lock(mutex); + profile_native_calls = p_enable; +#endif +} + void GDScriptLanguage::profiling_stop() { #ifdef DEBUG_ENABLED MutexLock lock(this->mutex); @@ -2241,17 +2250,32 @@ 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.get(); p_info_arr[current].self_time = elem->self()->profile.self_time.get(); p_info_arr[current].total_time = elem->self()->profile.total_time.get(); p_info_arr[current].signature = elem->self()->profile.signature; - elem = elem->next(); current++; + + int nat_time = 0; + HashMap::ConstIterator nat_calls = elem->self()->profile.native_calls.begin(); + while (nat_calls) { + 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 @@ -2264,17 +2288,33 @@ 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 = elem->self()->profile.last_native_calls.begin(); + while (nat_calls) { + 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(); } @@ -2283,6 +2323,33 @@ int GDScriptLanguage::profiling_get_frame_data(ProfilingInfo *p_info_arr, int p_ return current; } +void GDScriptLanguage::profiling_collate_native_call_data(bool p_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 = p_accumulated ? &elem->self()->profile.native_calls : &elem->self()->profile.last_native_calls; + HashMap::Iterator 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) { + 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) bool operator()(const Ref &A, const Ref &B) const { @@ -2482,9 +2549,11 @@ void GDScriptLanguage::frame() { elem->self()->profile.last_frame_call_count = elem->self()->profile.frame_call_count.get(); elem->self()->profile.last_frame_self_time = elem->self()->profile.frame_self_time.get(); elem->self()->profile.last_frame_total_time = elem->self()->profile.frame_total_time.get(); + elem->self()->profile.last_native_calls = elem->self()->profile.native_calls; elem->self()->profile.frame_call_count.set(0); elem->self()->profile.frame_self_time.set(0); elem->self()->profile.frame_total_time.set(0); + elem->self()->profile.native_calls.clear(); elem = elem->next(); } } diff --git a/modules/gdscript/gdscript.h b/modules/gdscript/gdscript.h index 5165ec1b0694..31811bba47a9 100644 --- a/modules/gdscript/gdscript.h +++ b/modules/gdscript/gdscript.h @@ -439,6 +439,7 @@ class GDScriptLanguage : public ScriptLanguage { SelfList::List function_list; bool profiling; + bool profile_native_calls; uint64_t script_frame_time; HashMap orphan_subclasses; @@ -590,6 +591,8 @@ public: virtual void profiling_start() override; virtual void profiling_stop() override; + virtual void profiling_set_save_native_calls(bool p_enable) override; + void profiling_collate_native_call_data(bool p_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 e63fa17cfe8e..177c68533ef6 100644 --- a/modules/gdscript/gdscript_function.h +++ b/modules/gdscript/gdscript_function.h @@ -474,6 +474,13 @@ private: 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 @@ -514,6 +521,7 @@ public: void debug_get_stack_member_state(int p_line, List> *r_stackvars) const; #ifdef DEBUG_ENABLED + void _profile_native_call(uint64_t p_t_taken, const String &p_function_name, const String &p_instance_class_name = String()); void disassemble(const Vector &p_code_lines) const; #endif diff --git a/modules/gdscript/gdscript_vm.cpp b/modules/gdscript/gdscript_vm.cpp index 2c0b8df9ac83..3abfc7f8e302 100644 --- a/modules/gdscript/gdscript_vm.cpp +++ b/modules/gdscript/gdscript_vm.cpp @@ -36,6 +36,18 @@ #include "core/os/os.h" #ifdef DEBUG_ENABLED + +static bool _profile_count_as_native(const Object *p_base_obj, const StringName &p_methodname) { + if (!p_base_obj) { + return false; + } + StringName cname = p_base_obj->get_class_name(); + if ((p_methodname == "new" && cname == "GDScript") || p_methodname == "call") { + return false; + } + return ClassDB::class_exists(cname) && ClassDB::has_method(cname, p_methodname, false); +} + static String _get_element_type(Variant::Type builtin_type, const StringName &native_type, const Ref