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 godotengine#23715, godotengine#40251, godotengine#29049

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;

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");

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<ScriptLanguageExtensionProfilingInfo>, int)
 

doc/classes/EditorSettings.xml

@@ -182,6 +182,9 @@
 		</method>
 	</methods>
 	<members>
+		<member name="debugger/profile_native_calls" type="bool" setter="" getter="">
+			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.
+		</member>
 		<member name="debugger/profiler_frame_history_size" type="int" setter="" getter="">
 			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.
 		</member>

doc/classes/ScriptLanguageExtension.xml

@@ -270,6 +270,12 @@
 			<description>
 			</description>
 		</method>
+		<method name="_profiling_set_save_native_calls" qualifiers="virtual">
+			<return type="void" />
+			<param index="0" name="opt" type="bool" />
+			<description>
+			</description>
+		</method>
 		<method name="_profiling_start" qualifiers="virtual">
 			<return type="void" />
 			<description>

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);

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<Metric> 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);

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);

editor/editor_settings.cpp

@@ -737,6 +737,7 @@ void EditorSettings::_load_defaults(Ref<ConfigFile> 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", "");

modules/gdscript/gdscript.cpp

@@ -2083,13 +2083,22 @@ 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();
 	}
 
 	profiling = true;
 #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<GDScriptFunction> *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<String, GDScriptFunction::Profile::NativeProfile>::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,24 +2152,69 @@ 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<GDScriptFunction> *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<String, GDScriptFunction::Profile::NativeProfile>::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();
 	}
 #endif
 
 	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<String, GDScriptFunction::Profile::NativeProfile *> seen_nat_calls;
+	SelfList<GDScriptFunction> *elem = function_list.first();
+	while (elem) {
+		HashMap<String, GDScriptFunction::Profile::NativeProfile> *nat_calls;
+		HashMap<String, GDScriptFunction::Profile::NativeProfile>::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<String> sig = it->value.signature.split("::");
+			HashMap<String, GDScriptFunction::Profile::NativeProfile *>::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();
 		}
 	}

modules/gdscript/gdscript.h

@@ -376,6 +376,7 @@ class GDScriptLanguage : public ScriptLanguage {
 
 	SelfList<GDScriptFunction>::List function_list;
 	bool profiling;
+	bool profile_native_calls;
 	uint64_t script_frame_time;
 
 	HashMap<String, ObjectID> 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;

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<String, NativeProfile> native_calls{};
+		HashMap<String, NativeProfile> 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<String> &p_code_lines) const;
 #endif