Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix missing script time for some functions in profiler #75623

Merged
merged 1 commit into from
Dec 19, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions core/object/script_language.h
Original file line number Diff line number Diff line change
Expand Up @@ -384,10 +384,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 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;
Expand Down
1 change: 1 addition & 0 deletions core/object/script_language_extension.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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");
Expand Down
1 change: 1 addition & 0 deletions core/object/script_language_extension.h
Original file line number Diff line number Diff line change
Expand Up @@ -607,6 +607,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)

Expand Down
3 changes: 3 additions & 0 deletions doc/classes/EditorSettings.xml
Original file line number Diff line number Diff line change
Expand Up @@ -185,6 +185,9 @@
<member name="debugger/auto_switch_to_remote_scene_tree" type="bool" setter="" getter="">
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.
</member>
<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>
Expand Down
6 changes: 6 additions & 0 deletions doc/classes/ScriptLanguageExtension.xml
Original file line number Diff line number Diff line change
Expand Up @@ -276,6 +276,12 @@
<description>
</description>
</method>
<method name="_profiling_set_save_native_calls" qualifiers="virtual">
<return type="void" />
<param index="0" name="enable" type="bool" />
<description>
</description>
</method>
<method name="_profiling_start" qualifiers="virtual">
<return type="void" />
<description>
Expand Down
16 changes: 16 additions & 0 deletions editor/debugger/editor_profiler.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand All @@ -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));

Expand Down Expand Up @@ -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:
Expand Down Expand Up @@ -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 #:"))));
Expand Down
6 changes: 6 additions & 0 deletions editor/debugger/editor_profiler.h
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -67,6 +68,7 @@ class EditorProfiler : public VBoxContainer {
int line = 0;
float self = 0;
float total = 0;
float internal = 0;
int calls = 0;
};

Expand Down Expand Up @@ -105,6 +107,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;
Expand All @@ -130,6 +134,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);
Expand Down
4 changes: 4 additions & 0 deletions editor/debugger/script_editor_debugger.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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)) {
Expand All @@ -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;
}

Expand Down Expand Up @@ -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);
Expand Down
1 change: 1 addition & 0 deletions editor/editor_settings.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -776,6 +776,7 @@ void EditorSettings::_load_defaults(Ref<ConfigFile> 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", "");
Expand Down
71 changes: 70 additions & 1 deletion modules/gdscript/gdscript.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -2220,13 +2220,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 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);
Expand All @@ -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<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.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<String, GDScriptFunction::Profile::NativeProfile>::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

Expand All @@ -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<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 = 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();
}
Expand All @@ -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) {
AThousandShips marked this conversation as resolved.
Show resolved Hide resolved
#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 = p_accumulated ? &elem->self()->profile.native_calls : &elem->self()->profile.last_native_calls;
HashMap<String, GDScriptFunction::Profile::NativeProfile>::Iterator 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) {
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<GDScript> &A, const Ref<GDScript> &B) const {
Expand Down Expand Up @@ -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();
}
}
Expand Down
3 changes: 3 additions & 0 deletions modules/gdscript/gdscript.h
Original file line number Diff line number Diff line change
Expand Up @@ -439,6 +439,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;
Expand Down Expand Up @@ -590,6 +591,8 @@ class GDScriptLanguage : public ScriptLanguage {

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;
Expand Down
8 changes: 8 additions & 0 deletions modules/gdscript/gdscript_function.h
Original file line number Diff line number Diff line change
Expand Up @@ -474,6 +474,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

Expand Down Expand Up @@ -514,6 +521,7 @@ class GDScriptFunction {
void debug_get_stack_member_state(int p_line, List<Pair<StringName, int>> *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<String> &p_code_lines) const;
#endif

Expand Down
Loading
Loading