diff options
35 files changed, 2244 insertions, 179 deletions
diff --git a/bin/tests/test_gdscript.cpp b/bin/tests/test_gdscript.cpp index 4578f5aa02..4457d70b38 100644 --- a/bin/tests/test_gdscript.cpp +++ b/bin/tests/test_gdscript.cpp @@ -487,12 +487,12 @@ static String _disassemble_addr(const Ref<GDScript>& p_script,const GDFunction& static void _disassemble_class(const Ref<GDScript>& p_class,const Vector<String>& p_code) { - const Map<StringName,GDFunction>& mf = p_class->debug_get_member_functions(); + const Map<StringName,GDFunction*>& mf = p_class->debug_get_member_functions(); - for(const Map<StringName,GDFunction>::Element *E=mf.front();E;E=E->next()) { + for(const Map<StringName,GDFunction*>::Element *E=mf.front();E;E=E->next()) { - const GDFunction &func=E->get(); + const GDFunction &func=*E->get(); const int *code = func.get_code(); int codelen=func.get_code_size(); String defargs; diff --git a/core/globals.cpp b/core/globals.cpp index 020e05fb8f..9e7b357d73 100644 --- a/core/globals.cpp +++ b/core/globals.cpp @@ -1528,6 +1528,7 @@ Globals::Globals() { custom_prop_info["render/thread_model"]=PropertyInfo(Variant::INT,"render/thread_model",PROPERTY_HINT_ENUM,"Single-Unsafe,Single-Safe,Multi-Threaded"); custom_prop_info["physics_2d/thread_model"]=PropertyInfo(Variant::INT,"physics_2d/thread_model",PROPERTY_HINT_ENUM,"Single-Unsafe,Single-Safe,Multi-Threaded"); + set("debug/profiler_max_functions",16384); using_datapack=false; } diff --git a/core/math/math_defs.h b/core/math/math_defs.h index eb85039ca3..e6a56c5e45 100644 --- a/core/math/math_defs.h +++ b/core/math/math_defs.h @@ -34,6 +34,7 @@ #define CMP_NORMALIZE_TOLERANCE 0.000001 #define CMP_POINT_IN_PLANE_EPSILON 0.00001 +#define USEC_TO_SEC(m_usec) ((m_usec)/1000000.0) /** * "Real" is a type that will be translated to either floats or fixed depending * on the compilation setting diff --git a/core/object.cpp b/core/object.cpp index ee4b5e288c..7f4db7c8b5 100644 --- a/core/object.cpp +++ b/core/object.cpp @@ -1249,6 +1249,7 @@ void Object::emit_signal(const StringName& p_name,VARIANT_ARG_DECLARE) { argc++; } + emit_signal(p_name,argptr,argc); } diff --git a/core/print_string.cpp b/core/print_string.cpp index e364388b7b..6e57822e94 100644 --- a/core/print_string.cpp +++ b/core/print_string.cpp @@ -66,7 +66,7 @@ void remove_print_handler(PrintHandlerList *p_handler) { l=l->next; } - OS::get_singleton()->print("print handler list is %p\n",print_handler_list); + //OS::get_singleton()->print("print handler list is %p\n",print_handler_list); ERR_FAIL_COND(l==NULL); _global_unlock(); diff --git a/core/profile_clock.cpp b/core/profile_clock.cpp new file mode 100644 index 0000000000..0806275463 --- /dev/null +++ b/core/profile_clock.cpp @@ -0,0 +1,3 @@ +#include "profile_clock.h" + + diff --git a/core/profile_clock.h b/core/profile_clock.h new file mode 100644 index 0000000000..e254580249 --- /dev/null +++ b/core/profile_clock.h @@ -0,0 +1,7 @@ +#ifndef PROFILE_CLOCK_H +#define PROFILE_CLOCK_H + + + + +#endif // PROFILE_CLOCK_H diff --git a/core/script_debugger_local.cpp b/core/script_debugger_local.cpp index 3e442f7f59..dfff54378a 100644 --- a/core/script_debugger_local.cpp +++ b/core/script_debugger_local.cpp @@ -179,6 +179,125 @@ void ScriptDebuggerLocal::debug(ScriptLanguage *p_script,bool p_can_continue) { } } +struct _ScriptDebuggerLocalProfileInfoSort { + + bool operator()(const ScriptLanguage::ProfilingInfo &A,const ScriptLanguage::ProfilingInfo &B) const { + return A.total_time > B.total_time; + } +}; + +void ScriptDebuggerLocal::profiling_set_frame_times(float p_frame_time,float p_idle_time,float p_fixed_time,float p_fixed_frame_time) { + + + frame_time=p_frame_time; + idle_time=p_idle_time; + fixed_time=p_fixed_time; + fixed_frame_time=p_fixed_frame_time; + + +} + +void ScriptDebuggerLocal::idle_poll() { + + if (!profiling) + return; + + uint64_t diff = OS::get_singleton()->get_ticks_usec() - idle_accum; + + if (diff<1000000) //show every one second + return; + + idle_accum = OS::get_singleton()->get_ticks_usec(); + + int ofs=0; + for(int i=0;i<ScriptServer::get_language_count();i++) { + ofs+=ScriptServer::get_language(i)->profiling_get_frame_data(&pinfo[ofs],pinfo.size()-ofs); + } + + SortArray<ScriptLanguage::ProfilingInfo,_ScriptDebuggerLocalProfileInfoSort> sort; + sort.sort(pinfo.ptr(),ofs); + + //falta el frame time + + uint64_t script_time_us=0; + + for(int i=0;i<ofs;i++) { + + script_time_us+=pinfo[i].self_time; + } + + + float script_time=USEC_TO_SEC(script_time_us); + + float total_time=frame_time; + + //print script total + + print_line("FRAME: total: "+rtos(frame_time)+" script: "+rtos(script_time)+"/"+itos(script_time*100/total_time)+" %"); + + for(int i=0;i<ofs;i++) { + + print_line(itos(i)+":"+pinfo[i].signature); + float tt=USEC_TO_SEC(pinfo[i].total_time); + float st=USEC_TO_SEC(pinfo[i].self_time); + print_line("\ttotal: "+rtos(tt)+"/"+itos(tt*100/total_time)+" % \tself: "+rtos(st)+"/"+itos(st*100/total_time)+" % tcalls: "+itos(pinfo[i].call_count)); + } + + + +} + +void ScriptDebuggerLocal::profiling_start() { + + for(int i=0;i<ScriptServer::get_language_count();i++) { + ScriptServer::get_language(i)->profiling_start(); + } + + + print_line("BEGIN PROFILING"); + profiling=true; + pinfo.resize(32768); + frame_time=0; + fixed_time=0; + idle_time=0; + fixed_frame_time=0; + +} + + +void ScriptDebuggerLocal::profiling_end() { + + int ofs=0; + + for(int i=0;i<ScriptServer::get_language_count();i++) { + ofs+=ScriptServer::get_language(i)->profiling_get_accumulated_data(&pinfo[ofs],pinfo.size()-ofs); + } + + SortArray<ScriptLanguage::ProfilingInfo,_ScriptDebuggerLocalProfileInfoSort> sort; + sort.sort(pinfo.ptr(),ofs); + + uint64_t total_us=0; + for(int i=0;i<ofs;i++) { + total_us+=pinfo[i].self_time; + } + + float total_time=total_us/1000000.0; + + for(int i=0;i<ofs;i++) { + + print_line(itos(i)+":"+pinfo[i].signature); + float tt=USEC_TO_SEC(pinfo[i].total_time);; + float st=USEC_TO_SEC(pinfo[i].self_time); + print_line("\ttotal_ms: "+rtos(tt)+"\tself_ms: "+rtos(st)+"total%: "+itos(tt*100/total_time)+"\tself%: "+itos(st*100/total_time)+"\tcalls: "+itos(pinfo[i].call_count)); + } + + for(int i=0;i<ScriptServer::get_language_count();i++) { + ScriptServer::get_language(i)->profiling_stop(); + } + + profiling=false; +} + void ScriptDebuggerLocal::send_message(const String& p_message, const Array &p_args) { print_line("MESSAGE: '"+p_message+"' - "+String(Variant(p_args))); @@ -186,4 +305,6 @@ void ScriptDebuggerLocal::send_message(const String& p_message, const Array &p_a ScriptDebuggerLocal::ScriptDebuggerLocal() { + profiling=false; + idle_accum=OS::get_singleton()->get_ticks_usec(); } diff --git a/core/script_debugger_local.h b/core/script_debugger_local.h index 4abacfc519..ffe8dce445 100644 --- a/core/script_debugger_local.h +++ b/core/script_debugger_local.h @@ -32,10 +32,29 @@ #include "script_language.h" class ScriptDebuggerLocal : public ScriptDebugger { + + bool profiling; + float frame_time,idle_time,fixed_time,fixed_frame_time; + uint64_t idle_accum; + + Vector<ScriptLanguage::ProfilingInfo> pinfo; + + public: void debug(ScriptLanguage *p_script,bool p_can_continue); virtual void send_message(const String& p_message, const Array& p_args); + + virtual bool is_profiling() const { return profiling; } + virtual void add_profiling_frame_data(const StringName& p_name,const Array& p_data) {} + + virtual void idle_poll(); + + virtual void profiling_start(); + virtual void profiling_end(); + virtual void profiling_set_frame_times(float p_frame_time,float p_idle_time,float p_fixed_time,float p_fixed_frame_time); + + ScriptDebuggerLocal(); }; diff --git a/core/script_debugger_remote.cpp b/core/script_debugger_remote.cpp index b56ff4c0e1..10e1b65cf3 100644 --- a/core/script_debugger_remote.cpp +++ b/core/script_debugger_remote.cpp @@ -125,6 +125,10 @@ static ObjectID safe_get_instance_id(const Variant& p_v) { void ScriptDebuggerRemote::debug(ScriptLanguage *p_script,bool p_can_continue) { + //this function is called when there is a debugger break (bug on script) + //or when execution is paused from editor + + if (!tcp_client->is_connected()) { ERR_EXPLAIN("Script Debugger failed to connect, but being used anyway."); ERR_FAIL(); @@ -135,6 +139,8 @@ void ScriptDebuggerRemote::debug(ScriptLanguage *p_script,bool p_can_continue) { packet_peer_stream->put_var(p_can_continue); packet_peer_stream->put_var(p_script->debug_get_error()); + skip_profile_frame=true; // to avoid super long frame time for the frame + Input::MouseMode mouse_mode=Input::get_singleton()->get_mouse_mode(); if (mouse_mode!=Input::MOUSE_MODE_VISIBLE) Input::get_singleton()->set_mouse_mode(Input::MOUSE_MODE_VISIBLE); @@ -372,7 +378,7 @@ void ScriptDebuggerRemote::line_poll() { //the purpose of this is just processing events every now and then when the script might get too busy //otherwise bugs like infinite loops cant be catched - if (poll_every%512==0) + if (poll_every%2048==0) _poll_events(); poll_every++; @@ -535,6 +541,9 @@ bool ScriptDebuggerRemote::_parse_live_edit(const Array& cmd) { void ScriptDebuggerRemote::_poll_events() { + //this si called from ::idle_poll, happens only when running the game, + //does not get called while on debug break + while(packet_peer_stream->get_available_packet_count()>0) { _get_output(); @@ -566,6 +575,31 @@ void ScriptDebuggerRemote::_poll_events() { } else if (command=="request_video_mem") { _send_video_memory(); + } else if (command=="start_profiling") { + + for(int i=0;i<ScriptServer::get_language_count();i++) { + ScriptServer::get_language(i)->profiling_start(); + } + + max_frame_functions=cmd[1]; + profiler_function_signature_map.clear(); + profiling=true; + frame_time=0; + idle_time=0; + fixed_time=0; + fixed_frame_time=0; + + print_line("PROFILING ALRIGHT!"); + + } else if (command=="stop_profiling") { + + for(int i=0;i<ScriptServer::get_language_count();i++) { + ScriptServer::get_language(i)->profiling_stop(); + } + profiling=false; + _send_profiling_data(false); + print_line("PROFILING END!"); + } else if (command=="breakpoint") { bool set = cmd[3]; @@ -582,8 +616,113 @@ void ScriptDebuggerRemote::_poll_events() { } +void ScriptDebuggerRemote::_send_profiling_data(bool p_for_frame) { + + + + + int ofs=0; + + for(int i=0;i<ScriptServer::get_language_count();i++) { + if (p_for_frame) + ofs+=ScriptServer::get_language(i)->profiling_get_frame_data(&profile_info[ofs],profile_info.size()-ofs); + else + ofs+=ScriptServer::get_language(i)->profiling_get_accumulated_data(&profile_info[ofs],profile_info.size()-ofs); + } + + for(int i=0;i<ofs;i++) { + profile_info_ptrs[i]=&profile_info[i]; + } + + SortArray<ScriptLanguage::ProfilingInfo*,ProfileInfoSort> sa; + sa.sort(profile_info_ptrs.ptr(),ofs); + + int to_send=MIN(ofs,max_frame_functions); + + //check signatures first + uint64_t total_script_time=0; + + for(int i=0;i<to_send;i++) { + + if (!profiler_function_signature_map.has(profile_info_ptrs[i]->signature)) { + + int idx = profiler_function_signature_map.size(); + packet_peer_stream->put_var("profile_sig"); + packet_peer_stream->put_var(2); + packet_peer_stream->put_var(profile_info_ptrs[i]->signature); + packet_peer_stream->put_var(idx); + + profiler_function_signature_map[profile_info_ptrs[i]->signature]=idx; + + + } + + total_script_time+=profile_info_ptrs[i]->self_time; + } + + //send frames then + + if (p_for_frame) { + packet_peer_stream->put_var("profile_frame"); + packet_peer_stream->put_var(8+profile_frame_data.size()*2+to_send*4); + } else { + packet_peer_stream->put_var("profile_total"); + packet_peer_stream->put_var(8+to_send*4); + } + + + packet_peer_stream->put_var(OS::get_singleton()->get_frames_drawn()); //total frame time + packet_peer_stream->put_var(frame_time); //total frame time + packet_peer_stream->put_var(idle_time); //idle frame time + packet_peer_stream->put_var(fixed_time); //fixed frame time + packet_peer_stream->put_var(fixed_frame_time); //fixed frame time + + packet_peer_stream->put_var(USEC_TO_SEC(total_script_time)); //total script execution time + + if (p_for_frame) { + + packet_peer_stream->put_var(profile_frame_data.size()); //how many profile framedatas to send + packet_peer_stream->put_var(to_send); //how many script functions to send + for (int i=0;i<profile_frame_data.size();i++) { + + + packet_peer_stream->put_var(profile_frame_data[i].name); + packet_peer_stream->put_var(profile_frame_data[i].data); + } + } else { + packet_peer_stream->put_var(0); //how many script functions to send + packet_peer_stream->put_var(to_send); //how many script functions to send + } + + + + for(int i=0;i<to_send;i++) { + + int sig_id=-1; + + if (profiler_function_signature_map.has(profile_info_ptrs[i]->signature)) { + sig_id=profiler_function_signature_map[profile_info_ptrs[i]->signature]; + } + + + + packet_peer_stream->put_var(sig_id); + packet_peer_stream->put_var(profile_info_ptrs[i]->call_count); + packet_peer_stream->put_var(profile_info_ptrs[i]->total_time/1000000.0); + packet_peer_stream->put_var(profile_info_ptrs[i]->self_time/1000000.0); + } + + if (p_for_frame) { + profile_frame_data.clear(); + } + +} + void ScriptDebuggerRemote::idle_poll() { + // this function is called every frame, except when there is a debugger break (::debug() in this class) + // execution stops and remains in the ::debug function + _get_output(); @@ -615,6 +754,16 @@ void ScriptDebuggerRemote::idle_poll() { } } + if (profiling) { + + if (skip_profile_frame) { + skip_profile_frame=false; + } else { + //send profiling info normally + _send_profiling_data(true); + } + } + _poll_events(); } @@ -687,6 +836,50 @@ void ScriptDebuggerRemote::set_live_edit_funcs(LiveEditFuncs *p_funcs) { live_edit_funcs=p_funcs; } +bool ScriptDebuggerRemote::is_profiling() const { + + return profiling; +} +void ScriptDebuggerRemote::add_profiling_frame_data(const StringName& p_name,const Array& p_data){ + + int idx=-1; + for(int i=0;i<profile_frame_data.size();i++) { + if (profile_frame_data[i].name==p_name) { + idx=i; + break; + } + } + + FrameData fd; + fd.name=p_name; + fd.data=p_data; + + if (idx==-1) { + profile_frame_data.push_back(fd); + } else { + profile_frame_data[idx]=fd; + } +} + +void ScriptDebuggerRemote::profiling_start() { + //ignores this, uses it via connnection +} + +void ScriptDebuggerRemote::profiling_end() { + //ignores this, uses it via connnection +} + +void ScriptDebuggerRemote::profiling_set_frame_times(float p_frame_time, float p_idle_time, float p_fixed_time, float p_fixed_frame_time) { + + frame_time=p_frame_time; + idle_time=p_idle_time; + fixed_time=p_fixed_time; + fixed_frame_time=p_fixed_frame_time; + + +} + + ScriptDebuggerRemote::ResourceUsageFunc ScriptDebuggerRemote::resource_usage_func=NULL; ScriptDebuggerRemote::ScriptDebuggerRemote() { @@ -710,11 +903,17 @@ ScriptDebuggerRemote::ScriptDebuggerRemote() { char_count=0; msec_count=0; last_msec=0; + skip_profile_frame=false; eh.errfunc=_err_handler; eh.userdata=this; add_error_handler(&eh); + profile_info.resize(CLAMP(int(Globals::get_singleton()->get("debug/profiler_max_functions")),128,65535)); + profile_info_ptrs.resize(profile_info.size()); + profiling=false; + max_frame_functions=16; + } ScriptDebuggerRemote::~ScriptDebuggerRemote() { @@ -723,4 +922,5 @@ ScriptDebuggerRemote::~ScriptDebuggerRemote() { remove_error_handler(&eh); memdelete(mutex); + } diff --git a/core/script_debugger_remote.h b/core/script_debugger_remote.h index f18e212236..a19b4ed2bd 100644 --- a/core/script_debugger_remote.h +++ b/core/script_debugger_remote.h @@ -44,6 +44,23 @@ class ScriptDebuggerRemote : public ScriptDebugger { }; + struct ProfileInfoSort { + + bool operator()(ScriptLanguage::ProfilingInfo*A,ScriptLanguage::ProfilingInfo*B) const { + return A->total_time < B->total_time; + } + }; + + Vector<ScriptLanguage::ProfilingInfo> profile_info; + Vector<ScriptLanguage::ProfilingInfo*> profile_info_ptrs; + + Map<StringName,int> profiler_function_signature_map; + float frame_time,idle_time,fixed_time,fixed_frame_time; + + bool profiling; + int max_frame_functions; + bool skip_profile_frame; + Ref<StreamPeerTCP> tcp_client; Ref<PacketPeerStream> packet_peer_stream; @@ -88,6 +105,7 @@ class ScriptDebuggerRemote : public ScriptDebugger { uint32_t poll_every; + bool _parse_live_edit(const Array &p_command); RequestSceneTreeMessageFunc request_scene_tree; @@ -99,6 +117,17 @@ class ScriptDebuggerRemote : public ScriptDebugger { ErrorHandlerList eh; static void _err_handler(void*,const char*,const char*,int p_line,const char *, const char *,ErrorHandlerType p_type); + void _send_profiling_data(bool p_for_frame); + + + struct FrameData { + + StringName name; + Array data; + }; + + Vector<FrameData> profile_frame_data; + public: @@ -129,6 +158,13 @@ public: virtual void set_request_scene_tree_message_func(RequestSceneTreeMessageFunc p_func, void *p_udata); virtual void set_live_edit_funcs(LiveEditFuncs *p_funcs); + virtual bool is_profiling() const; + virtual void add_profiling_frame_data(const StringName& p_name,const Array& p_data); + + virtual void profiling_start(); + virtual void profiling_end(); + virtual void profiling_set_frame_times(float p_frame_time,float p_idle_time,float p_fixed_time,float p_fixed_frame_time); + ScriptDebuggerRemote(); ~ScriptDebuggerRemote(); }; diff --git a/core/script_language.h b/core/script_language.h index 1be1aabdab..bd76107acf 100644 --- a/core/script_language.h +++ b/core/script_language.h @@ -195,6 +195,21 @@ public: virtual void get_public_functions(List<MethodInfo> *p_functions) const=0; virtual void get_public_constants(List<Pair<String,Variant> > *p_constants) const=0; + struct ProfilingInfo { + StringName signature; + uint64_t call_count; + uint64_t total_time; + uint64_t self_time; + + }; + + virtual void profiling_start()=0; + virtual void profiling_stop()=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; + + virtual void frame(); virtual ~ScriptLanguage() {}; @@ -309,6 +324,13 @@ public: virtual void set_request_scene_tree_message_func(RequestSceneTreeMessageFunc p_func, void *p_udata) {} virtual void set_live_edit_funcs(LiveEditFuncs *p_funcs) {} + virtual bool is_profiling() const=0; + virtual void add_profiling_frame_data(const StringName& p_name,const Array& p_data)=0; + virtual void profiling_start()=0; + virtual void profiling_end()=0; + virtual void profiling_set_frame_times(float p_frame_time,float p_idle_time,float p_fixed_time,float p_fixed_frame_time)=0; + + ScriptDebugger(); virtual ~ScriptDebugger() {singleton=NULL;} diff --git a/main/main.cpp b/main/main.cpp index 532e8708a6..9352055246 100644 --- a/main/main.cpp +++ b/main/main.cpp @@ -105,7 +105,7 @@ static Vector2 init_custom_pos; static int video_driver_idx=-1; static int audio_driver_idx=-1; static String locale; - +static bool use_debug_profiler=false; static int init_screen=-1; @@ -257,6 +257,7 @@ Error Main::setup(const char *execpath,int argc, char *argv[],bool p_second_phas Vector<String> breakpoints; bool use_custom_res=true; bool force_res=false; + bool profile=false; I=args.front(); @@ -360,6 +361,9 @@ Error Main::setup(const char *execpath,int argc, char *argv[],bool p_second_phas } else if (I->get()=="-w") { // video driver init_windowed=true; + } else if (I->get()=="-profile") { // video driver + + use_debug_profiler=true; } else if (I->get()=="-vd") { // video driver if (I->next()) { @@ -588,11 +592,11 @@ Error Main::setup(const char *execpath,int argc, char *argv[],bool p_second_phas memdelete(sdr); } else { script_debugger=sdr; - } } else if (debug_mode=="local") { script_debugger = memnew( ScriptDebuggerLocal ); + } @@ -987,6 +991,9 @@ Error Main::setup2() { + if (use_debug_profiler && script_debugger) { + script_debugger->profiling_start(); + } _start_success=true; locale=String(); @@ -1494,6 +1501,7 @@ uint32_t Main::frames=0; uint32_t Main::frame=0; bool Main::force_redraw_requested = false; +//for performance metrics static uint64_t fixed_process_max=0; static uint64_t idle_process_max=0; @@ -1509,6 +1517,10 @@ bool Main::iteration() { // if (time_accum+step < frame_slice) // return false; + + uint64_t fixed_process_ticks=0; + uint64_t idle_process_ticks=0; + frame+=ticks_elapsed; last_ticks=ticks; @@ -1551,6 +1563,7 @@ bool Main::iteration() { //if (AudioServer::get_singleton()) // AudioServer::get_singleton()->update(); + fixed_process_ticks=MAX(fixed_process_ticks,OS::get_singleton()->get_ticks_usec()-fixed_begin); // keep the largest one for reference fixed_process_max=MAX(OS::get_singleton()->get_ticks_usec()-fixed_begin,fixed_process_max); iters++; } @@ -1585,14 +1598,20 @@ bool Main::iteration() { if (AudioServer::get_singleton()) AudioServer::get_singleton()->update(); + idle_process_ticks=OS::get_singleton()->get_ticks_usec()-idle_begin; + idle_process_max=MAX(idle_process_ticks,idle_process_max); + uint64_t frame_time = OS::get_singleton()->get_ticks_usec() - ticks; + for(int i=0;i<ScriptServer::get_language_count();i++) { ScriptServer::get_language(i)->frame(); } - idle_process_max=MAX(OS::get_singleton()->get_ticks_usec()-idle_begin,idle_process_max); - - if (script_debugger) + if (script_debugger) { + if (script_debugger->is_profiling()) { + script_debugger->profiling_set_frame_times(USEC_TO_SEC(frame_time),USEC_TO_SEC(idle_process_ticks),USEC_TO_SEC(fixed_process_ticks),frame_slice); + } script_debugger->idle_poll(); + } // x11_delay_usec(10000); @@ -1605,8 +1624,8 @@ bool Main::iteration() { }; OS::get_singleton()->_fps=frames; - performance->set_process_time(idle_process_max/1000000.0); - performance->set_fixed_process_time(fixed_process_max/1000000.0); + performance->set_process_time(USEC_TO_SEC(idle_process_max)); + performance->set_fixed_process_time(USEC_TO_SEC(fixed_process_max)); idle_process_max=0; fixed_process_max=0; @@ -1650,8 +1669,13 @@ void Main::cleanup() { ERR_FAIL_COND(!_start_success); - if (script_debugger) + if (script_debugger) { + if (use_debug_profiler) { + script_debugger->profiling_end(); + } + memdelete(script_debugger); + } OS::get_singleton()->delete_main_loop(); diff --git a/modules/gdscript/gd_compiler.cpp b/modules/gdscript/gd_compiler.cpp index d38f5f3e35..5a6299bcf8 100644 --- a/modules/gdscript/gd_compiler.cpp +++ b/modules/gdscript/gd_compiler.cpp @@ -1290,8 +1290,8 @@ Error GDCompiler::_parse_function(GDScript *p_script,const GDParser::ClassNode * // gdfunc = &p_script->initializer; //} else { //regular func - p_script->member_functions[func_name]=GDFunction(); - gdfunc = &p_script->member_functions[func_name]; + p_script->member_functions[func_name]=memnew(GDFunction); + gdfunc = p_script->member_functions[func_name]; //} if (p_func) @@ -1358,6 +1358,32 @@ Error GDCompiler::_parse_function(GDScript *p_script,const GDParser::ClassNode * gdfunc->_stack_size=codegen.stack_max; gdfunc->_call_size=codegen.call_max; gdfunc->name=func_name; +#ifdef DEBUG_ENABLED + if (ScriptDebugger::get_singleton()){ + String signature; + //path + if (p_script->get_path()!=String()) + signature+=p_script->get_path(); + //loc + if (p_func) { + signature+="::"+itos(p_func->body->line); + } else { + signature+="::0"; + } + + //funciton and class + + if (p_class->name) { + signature+="::"+String(p_class->name)+"."+String(func_name);; + } else { + signature+="::"+String(func_name); + } + + + + gdfunc->profile.signature=signature; + } +#endif gdfunc->_script=p_script; gdfunc->source=source; @@ -1396,6 +1422,9 @@ Error GDCompiler::_parse_class(GDScript *p_script,GDScript *p_owner,const GDPars p_script->_base=NULL; p_script->members.clear(); p_script->constants.clear(); + for (Map<StringName,GDFunction*>::Element *E=p_script->member_functions.front();E;E=E->next()) { + memdelete(E->get()); + } p_script->member_functions.clear(); p_script->member_indices.clear(); p_script->member_info.clear(); @@ -1690,7 +1719,7 @@ Error GDCompiler::_parse_class(GDScript *p_script,GDScript *p_owner,const GDPars for(int i=0;i<p_class->variables.size();i++) { if (p_class->variables[i].setter) { - const Map<StringName,GDFunction>::Element *E=p_script->get_member_functions().find(p_class->variables[i].setter); + const Map<StringName,GDFunction*>::Element *E=p_script->get_member_functions().find(p_class->variables[i].setter); if (!E) { _set_error("Setter function '"+String(p_class->variables[i].setter)+"' not found in class.",NULL); err_line=p_class->variables[i].line; @@ -1698,7 +1727,7 @@ Error GDCompiler::_parse_class(GDScript *p_script,GDScript *p_owner,const GDPars return ERR_PARSE_ERROR; } - if (E->get().is_static()) { + if (E->get()->is_static()) { _set_error("Setter function '"+String(p_class->variables[i].setter)+"' is static.",NULL); err_line=p_class->variables[i].line; @@ -1708,7 +1737,7 @@ Error GDCompiler::_parse_class(GDScript *p_script,GDScript *p_owner,const GDPars } if (p_class->variables[i].getter) { - const Map<StringName,GDFunction>::Element *E=p_script->get_member_functions().find(p_class->variables[i].getter); + const Map<StringName,GDFunction*>::Element *E=p_script->get_member_functions().find(p_class->variables[i].getter); if (!E) { _set_error("Getter function '"+String(p_class->variables[i].getter)+"' not found in class.",NULL); err_line=p_class->variables[i].line; @@ -1716,7 +1745,7 @@ Error GDCompiler::_parse_class(GDScript *p_script,GDScript *p_owner,const GDPars return ERR_PARSE_ERROR; } - if (E->get().is_static()) { + if (E->get()->is_static()) { _set_error("Getter function '"+String(p_class->variables[i].getter)+"' is static.",NULL); err_line=p_class->variables[i].line; diff --git a/modules/gdscript/gd_editor.cpp b/modules/gdscript/gd_editor.cpp index ff19518ad5..7e5ff620c9 100644 --- a/modules/gdscript/gd_editor.cpp +++ b/modules/gdscript/gd_editor.cpp @@ -1310,9 +1310,9 @@ static void _find_identifiers_in_class(GDCompletionContext& context,bool p_stati } } - for (const Map<StringName,GDFunction>::Element *E=script->get_member_functions().front();E;E=E->next()) { - if (!p_static || E->get().is_static()) { - if (E->get().get_argument_count()) + for (const Map<StringName,GDFunction*>::Element *E=script->get_member_functions().front();E;E=E->next()) { + if (!p_static || E->get()->is_static()) { + if (E->get()->get_argument_count()) result.insert(E->key().operator String()+"("); else result.insert(E->key().operator String()+"()"); @@ -1536,10 +1536,10 @@ static void _find_type_arguments(const GDParser::Node*p_node,int p_line,const St if (scr) { while (scr) { - for (const Map<StringName,GDFunction>::Element *E=scr->get_member_functions().front();E;E=E->next()) { - if (E->get().is_static() && p_method==E->get().get_name()) { + for (const Map<StringName,GDFunction*>::Element *E=scr->get_member_functions().front();E;E=E->next()) { + if (E->get()->is_static() && p_method==E->get()->get_name()) { arghint="static func "+String(p_method)+"("; - for(int i=0;i<E->get().get_argument_count();i++) { + for(int i=0;i<E->get()->get_argument_count();i++) { if (i>0) arghint+=", "; else @@ -1547,12 +1547,12 @@ static void _find_type_arguments(const GDParser::Node*p_node,int p_line,const St if (i==p_argidx) { arghint+=String::chr(0xFFFF); } - arghint+="var "+E->get().get_argument_name(i); - int deffrom = E->get().get_argument_count()-E->get().get_default_argument_count(); + arghint+="var "+E->get()->get_argument_name(i); + int deffrom = E->get()->get_argument_count()-E->get()->get_default_argument_count(); if (i>=deffrom) { int defidx = deffrom-i; - if (defidx>=0 && defidx<E->get().get_default_argument_count()) { - arghint+="="+E->get().get_default_argument(defidx).get_construct_string(); + if (defidx>=0 && defidx<E->get()->get_default_argument_count()) { + arghint+="="+E->get()->get_default_argument(defidx).get_construct_string(); } } if (i==p_argidx) { @@ -1670,10 +1670,10 @@ static void _find_type_arguments(const GDParser::Node*p_node,int p_line,const St if (code=="") { - for (const Map<StringName,GDFunction>::Element *E=scr->get_member_functions().front();E;E=E->next()) { - if (p_method==E->get().get_name()) { + for (const Map<StringName,GDFunction*>::Element *E=scr->get_member_functions().front();E;E=E->next()) { + if (p_method==E->get()->get_name()) { arghint="func "+String(p_method)+"("; - for(int i=0;i<E->get().get_argument_count();i++) { + for(int i=0;i<E->get()->get_argument_count();i++) { if (i>0) arghint+=", "; else @@ -1681,12 +1681,12 @@ static void _find_type_arguments(const GDParser::Node*p_node,int p_line,const St if (i==p_argidx) { arghint+=String::chr(0xFFFF); } - arghint+="var "+E->get().get_argument_name(i); - int deffrom = E->get().get_argument_count()-E->get().get_default_argument_count(); + arghint+="var "+E->get()->get_argument_name(i); + int deffrom = E->get()->get_argument_count()-E->get()->get_default_argument_count(); if (i>=deffrom) { int defidx = deffrom-i; - if (defidx>=0 && defidx<E->get().get_default_argument_count()) { - arghint+="="+E->get().get_default_argument(defidx).get_construct_string(); + if (defidx>=0 && defidx<E->get()->get_default_argument_count()) { + arghint+="="+E->get()->get_default_argument(defidx).get_construct_string(); } } if (i==p_argidx) { @@ -1926,16 +1926,16 @@ static void _find_call_arguments(GDCompletionContext& context,const GDParser::No if (script.is_valid()) { - for (const Map<StringName,GDFunction>::Element *E=script->get_member_functions().front();E;E=E->next()) { + for (const Map<StringName,GDFunction*>::Element *E=script->get_member_functions().front();E;E=E->next()) { if (E->key()==id->name) { - if (context.function && context.function->_static && !E->get().is_static()) + if (context.function && context.function->_static && !E->get()->is_static()) continue; arghint = "func "+id->name.operator String()+String("("); - for(int i=0;i<E->get().get_argument_count();i++) { + for(int i=0;i<E->get()->get_argument_count();i++) { if (i>0) arghint+=", "; else @@ -1943,12 +1943,12 @@ static void _find_call_arguments(GDCompletionContext& context,const GDParser::No if (i==p_argidx) { arghint+=String::chr(0xFFFF); } - arghint+=E->get().get_argument_name(i); - int deffrom = E->get().get_argument_count()-E->get().get_default_argument_count(); + arghint+=E->get()->get_argument_name(i); + int deffrom = E->get()->get_argument_count()-E->get()->get_default_argument_count(); if (i>=deffrom) { int defidx = deffrom-i; - if (defidx>=0 && defidx<E->get().get_default_argument_count()) { - arghint+="="+E->get().get_default_argument(defidx).get_construct_string(); + if (defidx>=0 && defidx<E->get()->get_default_argument_count()) { + arghint+="="+E->get()->get_default_argument(defidx).get_construct_string(); } } if (i==p_argidx) { @@ -1956,7 +1956,7 @@ static void _find_call_arguments(GDCompletionContext& context,const GDParser::No } } - if (E->get().get_argument_count()>0) + if (E->get()->get_argument_count()>0) arghint+=" "; arghint+=")"; return; @@ -2178,8 +2178,8 @@ Error GDScriptLanguage::complete_code(const String& p_code, const String& p_base options.insert(E->key()); } } - for (const Map<StringName,GDFunction>::Element *E=scr->get_member_functions().front();E;E=E->next()) { - if (E->get().is_static()) + for (const Map<StringName,GDFunction*>::Element *E=scr->get_member_functions().front();E;E=E->next()) { + if (E->get()->is_static()) options.insert(E->key()); } @@ -2266,8 +2266,8 @@ Error GDScriptLanguage::complete_code(const String& p_code, const String& p_base options.insert(E->key()); } } - for (const Map<StringName,GDFunction>::Element *E=scr->get_member_functions().front();E;E=E->next()) { - if (E->get().get_argument_count()) + for (const Map<StringName,GDFunction*>::Element *E=scr->get_member_functions().front();E;E=E->next()) { + if (E->get()->get_argument_count()) options.insert(String(E->key())+"()"); else options.insert(String(E->key())+"("); diff --git a/modules/gdscript/gd_script.cpp b/modules/gdscript/gd_script.cpp index beec314e44..cd5e35db31 100644 --- a/modules/gdscript/gd_script.cpp +++ b/modules/gdscript/gd_script.cpp @@ -32,7 +32,7 @@ #include "gd_compiler.h" #include "os/file_access.h" #include "io/file_access_encrypted.h" - +#include "os/os.h" @@ -199,6 +199,8 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a int ip=0; int line=_initial_line; + + if (p_state) { //use existing (supplied) state (yielded) stack=(Variant*)p_state->stack.ptr(); @@ -282,8 +284,8 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a #ifdef DEBUG_ENABLED - if (ScriptDebugger::get_singleton()) - GDScriptLanguage::get_singleton()->enter_function(p_instance,this,stack,&ip,&line); + if (ScriptDebugger::get_singleton()) + GDScriptLanguage::get_singleton()->enter_function(p_instance,this,stack,&ip,&line); #define CHECK_SPACE(m_space)\ ERR_BREAK((ip+m_space)>_code_size) @@ -292,7 +294,7 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a Variant *m_v; \ m_v = _get_variant(_code_ptr[ip+m_code_ofs],p_instance,_class,self,stack,err_text);\ if (!m_v)\ - break; + break; #else @@ -304,7 +306,18 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a #endif +#ifdef DEBUG_ENABLED + + uint64_t function_start_time; + uint64_t function_call_time; + if (GDScriptLanguage::get_singleton()->profiling) { + function_start_time=OS::get_singleton()->get_ticks_usec(); + function_call_time=0; + profile.call_count++; + profile.frame_call_count++; + } +#endif bool exit_ok=false; while(ip<_code_size) { @@ -461,7 +474,7 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a bool valid; #ifdef DEBUG_ENABLED -//allow better error message in cases where src and dst are the same stack position + //allow better error message in cases where src and dst are the same stack position Variant ret = src->get(*index,&valid); #else *dst = src->get(*index,&valid); @@ -520,7 +533,7 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a bool valid; #ifdef DEBUG_ENABLED -//allow better error message in cases where src and dst are the same stack position + //allow better error message in cases where src and dst are the same stack position Variant ret = src->get_named(*index,&valid); #else @@ -662,6 +675,14 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a argptrs[i]=v; } +#ifdef DEBUG_ENABLED + uint64_t call_time; + + if (GDScriptLanguage::get_singleton()->profiling) { + call_time=OS::get_singleton()->get_ticks_usec(); + } + +#endif Variant::CallError err; if (call_ret) { @@ -671,6 +692,11 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a base->call(*methodname,(const Variant**)argptrs,argc,err); } +#ifdef DEBUG_ENABLED + if (GDScriptLanguage::get_singleton()->profiling) { + function_call_time+=OS::get_singleton()->get_ticks_usec() - call_time; + } +#endif if (err.error!=Variant::CallError::CALL_OK) { @@ -774,7 +800,7 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a const GDScript *gds = _script; - const Map<StringName,GDFunction>::Element *E=NULL; + const Map<StringName,GDFunction*>::Element *E=NULL; while (gds->base.ptr()) { gds=gds->base.ptr(); E=gds->member_functions.find(*methodname); @@ -1082,7 +1108,7 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a ip+=2; if (ScriptDebugger::get_singleton()) { - // line + // line bool do_break=false; if (ScriptDebugger::get_singleton()->get_lines_left()>0) { @@ -1136,18 +1162,30 @@ Variant GDFunction::call(GDInstance *p_instance, const Variant **p_args, int p_a err_text="Internal Script Error! - opcode #"+itos(last_opcode)+" (report please)."; } - if (!GDScriptLanguage::get_singleton()->debug_break(err_text,false)) { - // debugger break did not happen + if (!GDScriptLanguage::get_singleton()->debug_break(err_text,false)) { + // debugger break did not happen - _err_print_error(err_func.utf8().get_data(),err_file.utf8().get_data(),err_line,err_text.utf8().get_data(),ERR_HANDLER_SCRIPT); - } + _err_print_error(err_func.utf8().get_data(),err_file.utf8().get_data(),err_line,err_text.utf8().get_data(),ERR_HANDLER_SCRIPT); + } break; } - if (ScriptDebugger::get_singleton()) - GDScriptLanguage::get_singleton()->exit_function(); +#ifdef DEBUG_ENABLED + if (GDScriptLanguage::get_singleton()->profiling) { + uint64_t time_taken = OS::get_singleton()->get_ticks_usec() - function_start_time; + profile.total_time+=time_taken; + profile.self_time+=time_taken-function_call_time; + profile.frame_total_time+=time_taken; + profile.frame_self_time+=time_taken-function_call_time; + GDScriptLanguage::get_singleton()->script_frame_time+=time_taken-function_call_time; + + } + +#endif + if (ScriptDebugger::get_singleton()) + GDScriptLanguage::get_singleton()->exit_function(); if (_stack_size) { @@ -1204,76 +1242,76 @@ int GDFunction::get_max_stack_size() const { struct _GDFKC { - int order; - List<int> pos; + int order; + List<int> pos; }; struct _GDFKCS { - int order; - StringName id; - int pos; + int order; + StringName id; + int pos; - bool operator<(const _GDFKCS &p_r) const { + bool operator<(const _GDFKCS &p_r) const { - return order<p_r.order; - } + return order<p_r.order; + } }; void GDFunction::debug_get_stack_member_state(int p_line,List<Pair<StringName,int> > *r_stackvars) const { - int oc=0; - Map<StringName,_GDFKC> sdmap; - for( const List<StackDebug>::Element *E=stack_debug.front();E;E=E->next()) { + int oc=0; + Map<StringName,_GDFKC> sdmap; + for( const List<StackDebug>::Element *E=stack_debug.front();E;E=E->next()) { - const StackDebug &sd=E->get(); - if (sd.line>p_line) - break; + const StackDebug &sd=E->get(); + if (sd.line>p_line) + break; - if (sd.added) { + if (sd.added) { - if (!sdmap.has(sd.identifier)) { - _GDFKC d; - d.order=oc++; - d.pos.push_back(sd.pos); - sdmap[sd.identifier]=d; + if (!sdmap.has(sd.identifier)) { + _GDFKC d; + d.order=oc++; + d.pos.push_back(sd.pos); + sdmap[sd.identifier]=d; - } else { - sdmap[sd.identifier].pos.push_back(sd.pos); - } - } else { + } else { + sdmap[sd.identifier].pos.push_back(sd.pos); + } + } else { - ERR_CONTINUE(!sdmap.has(sd.identifier)); + ERR_CONTINUE(!sdmap.has(sd.identifier)); - sdmap[sd.identifier].pos.pop_back(); - if (sdmap[sd.identifier].pos.empty()) - sdmap.erase(sd.identifier); - } + sdmap[sd.identifier].pos.pop_back(); + if (sdmap[sd.identifier].pos.empty()) + sdmap.erase(sd.identifier); + } - } + } - List<_GDFKCS> stackpositions; - for(Map<StringName,_GDFKC>::Element *E=sdmap.front();E;E=E->next() ) { + List<_GDFKCS> stackpositions; + for(Map<StringName,_GDFKC>::Element *E=sdmap.front();E;E=E->next() ) { - _GDFKCS spp; - spp.id=E->key(); - spp.order=E->get().order; - spp.pos=E->get().pos.back()->get(); - stackpositions.push_back(spp); - } + _GDFKCS spp; + spp.id=E->key(); + spp.order=E->get().order; + spp.pos=E->get().pos.back()->get(); + stackpositions.push_back(spp); + } - stackpositions.sort(); + stackpositions.sort(); - for(List<_GDFKCS>::Element *E=stackpositions.front();E;E=E->next()) { + for(List<_GDFKCS>::Element *E=stackpositions.front();E;E=E->next()) { - Pair<StringName,int> p; - p.first=E->get().id; - p.second=E->get().pos; - r_stackvars->push_back(p); - } + Pair<StringName,int> p; + p.first=E->get().id; + p.second=E->get().pos; + r_stackvars->push_back(p); + } } @@ -1294,15 +1332,47 @@ void GDFunction::clear() { } #endif -GDFunction::GDFunction() { +GDFunction::GDFunction() : function_list(this) { _stack_size=0; _call_size=0; name="<anonymous>"; #ifdef DEBUG_ENABLED _func_cname=NULL; + + if (GDScriptLanguage::get_singleton()->lock) { + GDScriptLanguage::get_singleton()->lock->lock(); + } + GDScriptLanguage::get_singleton()->function_list.add(&function_list); + + if (GDScriptLanguage::get_singleton()->lock) { + GDScriptLanguage::get_singleton()->lock->unlock(); + } + + profile.call_count=0; + profile.self_time=0; + profile.total_time=0; + profile.frame_call_count=0; + profile.frame_self_time=0; + profile.frame_total_time=0; + profile.last_frame_call_count=0; + profile.last_frame_self_time=0; + profile.last_frame_total_time=0; + #endif +} + +GDFunction::~GDFunction() { +#ifdef DEBUG_ENABLED + if (GDScriptLanguage::get_singleton()->lock) { + GDScriptLanguage::get_singleton()->lock->lock(); + } + GDScriptLanguage::get_singleton()->function_list.remove(&function_list); + if (GDScriptLanguage::get_singleton()->lock) { + GDScriptLanguage::get_singleton()->lock->unlock(); + } +#endif } ///////////////////// @@ -1935,14 +2005,14 @@ Variant GDScript::call(const StringName& p_method,const Variant** p_args,int p_a GDScript *top=this; while(top) { - Map<StringName,GDFunction>::Element *E=top->member_functions.find(p_method); + Map<StringName,GDFunction*>::Element *E=top->member_functions.find(p_method); if (E) { - if (!E->get().is_static()) { + if (!E->get()->is_static()) { WARN_PRINT(String("Can't call non-static function: '"+String(p_method)+"' in script.").utf8().get_data()); } - return E->get().call(NULL,p_args,p_argcount,r_error); + return E->get()->call(NULL,p_args,p_argcount,r_error); } top=top->_base; } @@ -2127,7 +2197,7 @@ Error GDScript::load_source_code(const String& p_path) { } -const Map<StringName,GDFunction>& GDScript::debug_get_member_functions() const { +const Map<StringName,GDFunction*>& GDScript::debug_get_member_functions() const { return member_functions; } @@ -2209,6 +2279,12 @@ GDScript::GDScript() { } +GDScript::~GDScript() { + for (Map<StringName,GDFunction*>::Element *E=member_functions.front();E;E=E->next()) { + memdelete( E->get() ); + } +} + @@ -2242,14 +2318,14 @@ bool GDInstance::set(const StringName& p_name, const Variant& p_value) { while(sptr) { - Map<StringName,GDFunction>::Element *E = sptr->member_functions.find(GDScriptLanguage::get_singleton()->strings._set); + Map<StringName,GDFunction*>::Element *E = sptr->member_functions.find(GDScriptLanguage::get_singleton()->strings._set); if (E) { Variant name=p_name; const Variant *args[2]={&name,&p_value}; Variant::CallError err; - Variant ret = E->get().call(this,(const Variant**)args,2,err); + Variant ret = E->get()->call(this,(const Variant**)args,2,err); if (err.error==Variant::CallError::CALL_OK && ret.get_type()==Variant::BOOL && ret.operator bool()) return true; } @@ -2292,14 +2368,14 @@ bool GDInstance::get(const StringName& p_name, Variant &r_ret) const { } { - const Map<StringName,GDFunction>::Element *E = sptr->member_functions.find(GDScriptLanguage::get_singleton()->strings._get); + const Map<StringName,GDFunction*>::Element *E = sptr->member_functions.find(GDScriptLanguage::get_singleton()->strings._get); if (E) { Variant name=p_name; const Variant *args[1]={&name}; Variant::CallError err; - Variant ret = const_cast<GDFunction*>(&E->get())->call(const_cast<GDInstance*>(this),(const Variant**)args,1,err); + Variant ret = const_cast<GDFunction*>(E->get())->call(const_cast<GDInstance*>(this),(const Variant**)args,1,err); if (err.error==Variant::CallError::CALL_OK && ret.get_type()!=Variant::NIL) { r_ret=ret; return true; @@ -2341,12 +2417,12 @@ void GDInstance::get_property_list(List<PropertyInfo> *p_properties) const { while(sptr) { - const Map<StringName,GDFunction>::Element *E = sptr->member_functions.find(GDScriptLanguage::get_singleton()->strings._get_property_list); + const Map<StringName,GDFunction*>::Element *E = sptr->member_functions.find(GDScriptLanguage::get_singleton()->strings._get_property_list); if (E) { Variant::CallError err; - Variant ret = const_cast<GDFunction*>(&E->get())->call(const_cast<GDInstance*>(this),NULL,0,err); + Variant ret = const_cast<GDFunction*>(E->get())->call(const_cast<GDInstance*>(this),NULL,0,err); if (err.error==Variant::CallError::CALL_OK) { if (ret.get_type()!=Variant::ARRAY) { @@ -2403,7 +2479,7 @@ void GDInstance::get_property_list(List<PropertyInfo> *p_properties) const { if (sptr->member_functions.has("_get_property_list")) { Variant::CallError err; - GDFunction *f = const_cast<GDFunction*>(&sptr->member_functions["_get_property_list"]); + GDFunction *f = const_cast<GDFunction*>(sptr->member_functions["_get_property_list"]); Variant plv = f->call(const_cast<GDInstance*>(this),NULL,0,err); if (plv.get_type()!=Variant::ARRAY) { @@ -2419,11 +2495,11 @@ void GDInstance::get_property_list(List<PropertyInfo> *p_properties) const { PropertyInfo pinfo; if (!p.has("name")) { ERR_PRINT("_get_property_list: expected 'name' key of type string.") - continue; + continue; } if (!p.has("type")) { ERR_PRINT("_get_property_list: expected 'type' key of type integer.") - continue; + continue; } pinfo.name=p["name"]; pinfo.type=Variant::Type(int(p["type"])); @@ -2457,12 +2533,12 @@ void GDInstance::get_method_list(List<MethodInfo> *p_list) const { const GDScript *sptr=script.ptr(); while(sptr) { - for (Map<StringName,GDFunction>::Element *E = sptr->member_functions.front();E;E=E->next()) { + for (Map<StringName,GDFunction*>::Element *E = sptr->member_functions.front();E;E=E->next()) { MethodInfo mi; mi.name=E->key(); mi.flags|=METHOD_FLAG_FROM_SCRIPT; - for(int i=0;i<E->get().get_argument_count();i++) + for(int i=0;i<E->get()->get_argument_count();i++) mi.arguments.push_back(PropertyInfo(Variant::NIL,"arg"+itos(i))); p_list->push_back(mi); } @@ -2475,7 +2551,7 @@ bool GDInstance::has_method(const StringName& p_method) const { const GDScript *sptr=script.ptr(); while(sptr) { - const Map<StringName,GDFunction>::Element *E = sptr->member_functions.find(p_method); + const Map<StringName,GDFunction*>::Element *E = sptr->member_functions.find(p_method); if (E) return true; sptr = sptr->_base; @@ -2489,9 +2565,9 @@ Variant GDInstance::call(const StringName& p_method,const Variant** p_args,int p GDScript *sptr=script.ptr(); while(sptr) { - Map<StringName,GDFunction>::Element *E = sptr->member_functions.find(p_method); + Map<StringName,GDFunction*>::Element *E = sptr->member_functions.find(p_method); if (E) { - return E->get().call(this,p_args,p_argcount,r_error); + return E->get()->call(this,p_args,p_argcount,r_error); } sptr = sptr->_base; } @@ -2505,9 +2581,9 @@ void GDInstance::call_multilevel(const StringName& p_method,const Variant** p_ar Variant::CallError ce; while(sptr) { - Map<StringName,GDFunction>::Element *E = sptr->member_functions.find(p_method); + Map<StringName,GDFunction*>::Element *E = sptr->member_functions.find(p_method); if (E) { - E->get().call(this,p_args,p_argcount,ce); + E->get()->call(this,p_args,p_argcount,ce); } sptr = sptr->_base; } @@ -2522,9 +2598,9 @@ void GDInstance::_ml_call_reversed(GDScript *sptr,const StringName& p_method,con Variant::CallError ce; - Map<StringName,GDFunction>::Element *E = sptr->member_functions.find(p_method); + Map<StringName,GDFunction*>::Element *E = sptr->member_functions.find(p_method); if (E) { - E->get().call(this,p_args,p_argcount,ce); + E->get()->call(this,p_args,p_argcount,ce); } } @@ -2544,10 +2620,10 @@ void GDInstance::notification(int p_notification) { GDScript *sptr=script.ptr(); while(sptr) { - Map<StringName,GDFunction>::Element *E = sptr->member_functions.find(GDScriptLanguage::get_singleton()->strings._notification); + Map<StringName,GDFunction*>::Element *E = sptr->member_functions.find(GDScriptLanguage::get_singleton()->strings._notification); if (E) { Variant::CallError err; - E->get().call(this,args,1,err); + E->get()->call(this,args,1,err); if (err.error!=Variant::CallError::CALL_OK) { //print error about notification call @@ -2672,11 +2748,154 @@ void GDScriptLanguage::finish() { } +void GDScriptLanguage::profiling_start() { + +#ifdef DEBUG_ENABLED + if (lock) { + lock->lock(); + } + + SelfList<GDFunction> *elem=function_list.first(); + while(elem) { + elem->self()->profile.call_count=0; + elem->self()->profile.self_time=0; + elem->self()->profile.total_time=0; + elem->self()->profile.frame_call_count=0; + elem->self()->profile.frame_self_time=0; + elem->self()->profile.frame_total_time=0; + 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=elem->next(); + } + + profiling=true; + if (lock) { + lock->unlock(); + } + +#endif + +} + +void GDScriptLanguage::profiling_stop() { + +#ifdef DEBUG_ENABLED + if (lock) { + lock->lock(); + } + + profiling=false; + if (lock) { + lock->unlock(); + } + +#endif +} + +int GDScriptLanguage::profiling_get_accumulated_data(ProfilingInfo *p_info_arr,int p_info_max) { + + int current=0; +#ifdef DEBUG_ENABLED + if (lock) { + lock->lock(); + } + + + SelfList<GDFunction> *elem=function_list.first(); + while(elem) { + if (current>=p_info_max) + break; + 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++; + } + + + + if (lock) { + lock->unlock(); + } + + +#endif + + return current; + + +} + +int GDScriptLanguage::profiling_get_frame_data(ProfilingInfo *p_info_arr,int p_info_max) { + + int current=0; + +#ifdef DEBUG_ENABLED + if (lock) { + lock->lock(); + } + + + SelfList<GDFunction> *elem=function_list.first(); + while(elem) { + if (current>=p_info_max) + break; + if (elem->self()->profile.last_frame_call_count>0) { + 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; + //print_line(String(elem->self()->profile.signature)+": "+itos(elem->self()->profile.last_frame_call_count)); + current++; + } + elem=elem->next(); + + } + + + if (lock) { + lock->unlock(); + } + + +#endif + + return current; + +} + void GDScriptLanguage::frame() { -// print_line("calls: "+itos(calls)); + // print_line("calls: "+itos(calls)); calls=0; + +#ifdef DEBUG_ENABLED + if (profiling) { + if (lock) { + lock->lock(); + } + + SelfList<GDFunction> *elem=function_list.first(); + while(elem) { + 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.frame_call_count=0; + elem->self()->profile.frame_self_time=0; + elem->self()->profile.frame_total_time=0; + elem=elem->next(); + } + + + if (lock) { + lock->unlock(); + } + } + +#endif } /* EDITOR FUNCTIONS */ @@ -2724,7 +2943,7 @@ void GDScriptLanguage::get_reserved_words(List<String> *p_words) const { "pass", "return", "while", - 0}; + 0}; const char **w=_reserved_words; @@ -2756,30 +2975,43 @@ GDScriptLanguage::GDScriptLanguage() { _debug_parse_err_line=-1; _debug_parse_err_file=""; - _debug_call_stack_pos=0; - int dmcs=GLOBAL_DEF("debug/script_max_call_stack",1024); - if (ScriptDebugger::get_singleton()) { - //debugging enabled! +#ifdef NO_THREADS + lock=NULL; +#else + lock = Mutex::create(); +#endif + profiling=false; + script_frame_time=0; + + _debug_call_stack_pos=0; + int dmcs=GLOBAL_DEF("debug/script_max_call_stack",1024); + if (ScriptDebugger::get_singleton()) { + //debugging enabled! - _debug_max_call_stack = dmcs; - if (_debug_max_call_stack<1024) - _debug_max_call_stack=1024; - _call_stack = memnew_arr( CallLevel, _debug_max_call_stack+1 ); + _debug_max_call_stack = dmcs; + if (_debug_max_call_stack<1024) + _debug_max_call_stack=1024; + _call_stack = memnew_arr( CallLevel, _debug_max_call_stack+1 ); - } else { - _debug_max_call_stack=0; - _call_stack=NULL; - } + } else { + _debug_max_call_stack=0; + _call_stack=NULL; + } } GDScriptLanguage::~GDScriptLanguage() { - if (_call_stack) { - memdelete_arr(_call_stack); - } - singleton=NULL; + + if (lock) { + memdelete(lock); + lock=NULL; + } + if (_call_stack) { + memdelete_arr(_call_stack); + } + singleton=NULL; } /*************** RESOURCE ***************/ diff --git a/modules/gdscript/gd_script.h b/modules/gdscript/gd_script.h index 663fc985a7..5f6cd012d7 100644 --- a/modules/gdscript/gd_script.h +++ b/modules/gdscript/gd_script.h @@ -34,6 +34,8 @@ #include "io/resource_saver.h" #include "os/thread.h" #include "pair.h" +#include "self_list.h" + class GDInstance; class GDScript; @@ -125,10 +127,6 @@ friend class GDCompiler; Vector<StringName> global_names; Vector<int> default_arguments; Vector<int> code; -#ifdef DEBUG_ENABLED - CharString func_cname; - const char*_func_cname; -#endif #ifdef TOOLS_ENABLED Vector<StringName> arg_names; @@ -139,9 +137,32 @@ friend class GDCompiler; _FORCE_INLINE_ Variant *_get_variant(int p_address,GDInstance *p_instance,GDScript *p_script,Variant &self,Variant *p_stack,String& r_error) const; _FORCE_INLINE_ String _get_call_error(const Variant::CallError& p_err, const String& p_where,const Variant**argptrs) const; +friend class GDScriptLanguage; + + SelfList<GDFunction> function_list; +#ifdef DEBUG_ENABLED + CharString func_cname; + const char*_func_cname; + + struct Profile { + StringName signature; + uint64_t call_count; + uint64_t self_time; + uint64_t total_time; + uint64_t frame_call_count; + uint64_t frame_self_time; + uint64_t frame_total_time; + uint64_t last_frame_call_count; + uint64_t last_frame_self_time; + uint64_t last_frame_total_time; + } profile; + +#endif public: + + struct CallState { GDInstance *instance; @@ -190,6 +211,7 @@ public: Variant call(GDInstance *p_instance,const Variant **p_args, int p_argcount,Variant::CallError& r_err,CallState *p_state=NULL); GDFunction(); + ~GDFunction(); }; @@ -258,7 +280,7 @@ friend class GDScriptLanguage; Set<StringName> members; //members are just indices to the instanced script. Map<StringName,Variant> constants; - Map<StringName,GDFunction> member_functions; + Map<StringName,GDFunction*> member_functions; Map<StringName,MemberInfo> member_indices; //members are just indices to the instanced script. Map<StringName,Ref<GDScript> > subclasses; Map<StringName,Vector<StringName> > _signals; @@ -317,7 +339,7 @@ public: const Map<StringName,Ref<GDScript> >& get_subclasses() const { return subclasses; } const Map<StringName,Variant >& get_constants() const { return constants; } const Set<StringName>& get_members() const { return members; } - const Map<StringName,GDFunction>& get_member_functions() const { return member_functions; } + const Map<StringName,GDFunction*>& get_member_functions() const { return member_functions; } const Ref<GDNativeClass>& get_native() const { return native; } virtual bool has_script_signal(const StringName& p_signal) const; @@ -328,7 +350,7 @@ public: Ref<GDScript> get_base() const; const Map<StringName,MemberInfo>& debug_get_member_indices() const { return member_indices; } - const Map<StringName,GDFunction>& debug_get_member_functions() const; //this is debug only + const Map<StringName,GDFunction*>& debug_get_member_functions() const; //this is debug only StringName debug_get_member_by_index(int p_idx) const; Variant _new(const Variant** p_args,int p_argcount,Variant::CallError& r_error); @@ -357,6 +379,7 @@ public: virtual ScriptLanguage *get_language() const; GDScript(); + ~GDScript(); }; class GDInstance : public ScriptInstance { @@ -369,6 +392,7 @@ friend class GDFunctions; Vector<Variant> members; bool base_ref; + void _ml_call_reversed(GDScript *sptr,const StringName& p_method,const Variant** p_args,int p_argcount); public: @@ -431,8 +455,15 @@ class GDScriptLanguage : public ScriptLanguage { void _add_global(const StringName& p_name,const Variant& p_value); + Mutex *lock; +friend class GDFunction; + + SelfList<GDFunction>::List function_list; + bool profiling; + uint64_t script_frame_time; public: + int calls; bool debug_break(const String& p_error,bool p_allow_continue=true); @@ -552,6 +583,12 @@ public: virtual void get_public_functions(List<MethodInfo> *p_functions) const; virtual void get_public_constants(List<Pair<String,Variant> > *p_constants) const; + virtual void profiling_start(); + virtual void profiling_stop(); + + virtual int profiling_get_accumulated_data(ProfilingInfo *p_info_arr,int p_info_max); + virtual int profiling_get_frame_data(ProfilingInfo *p_info_arr,int p_info_max); + /* LOADER FUNCTIONS */ virtual void get_recognized_extensions(List<String> *p_extensions) const; diff --git a/scene/gui/video_player.cpp b/scene/gui/video_player.cpp index 89dacc6577..26227d6389 100644 --- a/scene/gui/video_player.cpp +++ b/scene/gui/video_player.cpp @@ -131,7 +131,7 @@ void VideoPlayer::_notification(int p_notification) { if (!playback->is_playing()) return; - double audio_time = OS::get_singleton()->get_ticks_usec()/1000000.0; //AudioServer::get_singleton()->get_mix_time(); + double audio_time = USEC_TO_SEC(OS::get_singleton()->get_ticks_usec()); //AudioServer::get_singleton()->get_mix_time(); double delta = last_audio_time==0?0:audio_time-last_audio_time; last_audio_time=audio_time; diff --git a/scene/io/resource_format_image.cpp b/scene/io/resource_format_image.cpp index 6174d134a3..f3a0eaa8c4 100644 --- a/scene/io/resource_format_image.cpp +++ b/scene/io/resource_format_image.cpp @@ -108,7 +108,7 @@ RES ResourceFormatLoaderImage::load(const String &p_path, const String& p_origin Error err = ImageLoader::load_image(p_path,&image); if (!err && debug_load_times) { - double total=(double)(OS::get_singleton()->get_ticks_usec()-begtime)/1000000.0; + double total=USEC_TO_SEC((OS::get_singleton()->get_ticks_usec()-begtime)); print_line("IMAGE: "+itos(image.get_width())+"x"+itos(image.get_height())); print_line(" -load: "+rtos(total)); } @@ -201,7 +201,7 @@ RES ResourceFormatLoaderImage::load(const String &p_path, const String& p_origin if (debug_load_times) { - total=(double)(OS::get_singleton()->get_ticks_usec()-begtime)/1000000.0; + total=USEC_TO_SEC(OS::get_singleton()->get_ticks_usec()-begtime); print_line(" -make texture: "+rtos(total)); } diff --git a/servers/physics/physics_server_sw.cpp b/servers/physics/physics_server_sw.cpp index 5307f1ce88..6c098a6df2 100644 --- a/servers/physics/physics_server_sw.cpp +++ b/servers/physics/physics_server_sw.cpp @@ -34,7 +34,8 @@ #include "joints/slider_joint_sw.h" #include "joints/cone_twist_joint_sw.h" #include "joints/generic_6dof_joint_sw.h" - +#include "script_language.h" +#include "os/os.h" RID PhysicsServerSW::shape_create(ShapeType p_shape) { @@ -1509,12 +1510,51 @@ void PhysicsServerSW::flush_queries() { return; doing_sync=true; + + uint64_t time_beg = OS::get_singleton()->get_ticks_usec(); + for( Set<const SpaceSW*>::Element *E=active_spaces.front();E;E=E->next()) { SpaceSW *space=(SpaceSW *)E->get(); space->call_queries(); } + + if (ScriptDebugger::get_singleton() && ScriptDebugger::get_singleton()->is_profiling()) { + + uint64_t total_time[SpaceSW::ELAPSED_TIME_MAX]; + static const char* time_name[SpaceSW::ELAPSED_TIME_MAX]={ + "integrate_forces", + "generate_islands", + "setup_constraints", + "solve_constraints", + "integrate_velocities" + }; + + for(int i=0;i<SpaceSW::ELAPSED_TIME_MAX;i++) { + total_time[i]=0; + } + + for( Set<const SpaceSW*>::Element *E=active_spaces.front();E;E=E->next()) { + + for(int i=0;i<SpaceSW::ELAPSED_TIME_MAX;i++) { + total_time[i]+=E->get()->get_elapsed_time(SpaceSW::ElapsedTime(i)); + } + + } + + Array values; + values.resize(SpaceSW::ELAPSED_TIME_MAX*2); + for(int i=0;i<SpaceSW::ELAPSED_TIME_MAX;i++) { + values[i*2+0]=time_name[i]; + values[i*2+1]=USEC_TO_SEC(total_time[i]); + } + values.push_back("flush_queries"); + values.push_back(USEC_TO_SEC(OS::get_singleton()->get_ticks_usec()-time_beg)); + + ScriptDebugger::get_singleton()->add_profiling_frame_data("physics",values); + + } }; diff --git a/servers/physics/space_sw.cpp b/servers/physics/space_sw.cpp index 4cf7729b09..1e6f42aa02 100644 --- a/servers/physics/space_sw.cpp +++ b/servers/physics/space_sw.cpp @@ -736,6 +736,10 @@ SpaceSW::SpaceSW() { direct_access = memnew( PhysicsDirectSpaceStateSW ); direct_access->space=this; + + for(int i=0;i<ELAPSED_TIME_MAX;i++) + elapsed_time[i]=0; + } SpaceSW::~SpaceSW() { diff --git a/servers/physics/space_sw.h b/servers/physics/space_sw.h index 6300c206d8..3fdef7e62b 100644 --- a/servers/physics/space_sw.h +++ b/servers/physics/space_sw.h @@ -59,6 +59,20 @@ public: class SpaceSW { +public: + + enum ElapsedTime { + ELAPSED_TIME_INTEGRATE_FORCES, + ELAPSED_TIME_GENERATE_ISLANDS, + ELAPSED_TIME_SETUP_CONSTRAINTS, + ELAPSED_TIME_SOLVE_CONSTRAINTS, + ELAPSED_TIME_INTEGRATE_VELOCITIES, + ELAPSED_TIME_MAX + + }; +private: + + uint64_t elapsed_time[ELAPSED_TIME_MAX]; PhysicsDirectSpaceStateSW *direct_access; RID self; @@ -178,6 +192,8 @@ public: void set_static_global_body(RID p_body) { static_global_body=p_body; } RID get_static_global_body() { return static_global_body; } + void set_elapsed_time(ElapsedTime p_time,uint64_t p_msec) { elapsed_time[p_time]=p_msec; } + uint64_t get_elapsed_time(ElapsedTime p_time) const { return elapsed_time[p_time]; } SpaceSW(); ~SpaceSW(); diff --git a/servers/physics/step_sw.cpp b/servers/physics/step_sw.cpp index f10dadf81a..5b7ebce817 100644 --- a/servers/physics/step_sw.cpp +++ b/servers/physics/step_sw.cpp @@ -29,6 +29,8 @@ #include "step_sw.h" #include "joints_sw.h" +#include "os/os.h" + void StepSW::_populate_island(BodySW* p_body,BodySW** p_island,ConstraintSW **p_constraint_island) { p_body->set_island_step(_step); @@ -152,6 +154,10 @@ void StepSW::step(SpaceSW* p_space,float p_delta,int p_iterations) { const SelfList<BodySW>::List * body_list = &p_space->get_active_body_list(); /* INTEGRATE FORCES */ + + uint64_t profile_begtime = OS::get_singleton()->get_ticks_usec(); + uint64_t profile_endtime=0; + int active_count=0; const SelfList<BodySW>*b = body_list->first(); @@ -165,6 +171,12 @@ void StepSW::step(SpaceSW* p_space,float p_delta,int p_iterations) { p_space->set_active_objects(active_count); + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(SpaceSW::ELAPSED_TIME_INTEGRATE_FORCES,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + /* GENERATE CONSTRAINT ISLANDS */ BodySW *island_list=NULL; @@ -214,6 +226,13 @@ void StepSW::step(SpaceSW* p_space,float p_delta,int p_iterations) { p_space->area_remove_from_moved_list((SelfList<AreaSW>*)aml.first()); //faster to remove here } + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(SpaceSW::ELAPSED_TIME_GENERATE_ISLANDS,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + + // print_line("island count: "+itos(island_count)+" active count: "+itos(active_count)); /* SETUP CONSTRAINT ISLANDS */ @@ -226,6 +245,12 @@ void StepSW::step(SpaceSW* p_space,float p_delta,int p_iterations) { } } + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(SpaceSW::ELAPSED_TIME_SETUP_CONSTRAINTS,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + /* SOLVE CONSTRAINT ISLANDS */ { @@ -237,6 +262,13 @@ void StepSW::step(SpaceSW* p_space,float p_delta,int p_iterations) { } } + + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(SpaceSW::ELAPSED_TIME_SOLVE_CONSTRAINTS,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + /* INTEGRATE VELOCITIES */ b = body_list->first(); @@ -257,6 +289,12 @@ void StepSW::step(SpaceSW* p_space,float p_delta,int p_iterations) { } } + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(SpaceSW::ELAPSED_TIME_INTEGRATE_VELOCITIES,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + p_space->update(); p_space->unlock(); _step++; diff --git a/servers/physics_2d/physics_2d_server_sw.cpp b/servers/physics_2d/physics_2d_server_sw.cpp index 3796ddd961..54cd929c2f 100644 --- a/servers/physics_2d/physics_2d_server_sw.cpp +++ b/servers/physics_2d/physics_2d_server_sw.cpp @@ -31,6 +31,9 @@ #include "broad_phase_2d_hash_grid.h" #include "collision_solver_2d_sw.h" #include "globals.h" +#include "script_language.h" +#include "os/os.h" + RID Physics2DServerSW::shape_create(ShapeType p_shape) { Shape2DSW *shape=NULL; @@ -1276,6 +1279,8 @@ void Physics2DServerSW::step(float p_step) { active_objects+=E->get()->get_active_objects(); collision_pairs+=E->get()->get_collision_pairs(); } + + }; void Physics2DServerSW::sync() { @@ -1288,6 +1293,7 @@ void Physics2DServerSW::flush_queries() { if (!active) return; + uint64_t time_beg = OS::get_singleton()->get_ticks_usec(); for( Set<const Space2DSW*>::Element *E=active_spaces.front();E;E=E->next()) { @@ -1295,7 +1301,44 @@ void Physics2DServerSW::flush_queries() { space->call_queries(); } -}; + + if (ScriptDebugger::get_singleton() && ScriptDebugger::get_singleton()->is_profiling()) { + + uint64_t total_time[Space2DSW::ELAPSED_TIME_MAX]; + static const char* time_name[Space2DSW::ELAPSED_TIME_MAX]={ + "integrate_forces", + "generate_islands", + "setup_constraints", + "solve_constraints", + "integrate_velocities" + }; + + for(int i=0;i<Space2DSW::ELAPSED_TIME_MAX;i++) { + total_time[i]=0; + } + + for( Set<const Space2DSW*>::Element *E=active_spaces.front();E;E=E->next()) { + + for(int i=0;i<Space2DSW::ELAPSED_TIME_MAX;i++) { + total_time[i]+=E->get()->get_elapsed_time(Space2DSW::ElapsedTime(i)); + } + + } + + Array values; + values.resize(Space2DSW::ELAPSED_TIME_MAX*2); + for(int i=0;i<Space2DSW::ELAPSED_TIME_MAX;i++) { + values[i*2+0]=time_name[i]; + values[i*2+1]=USEC_TO_SEC(total_time[i]); + } + values.push_back("flush_queries"); + values.push_back(USEC_TO_SEC(OS::get_singleton()->get_ticks_usec()-time_beg)); + + ScriptDebugger::get_singleton()->add_profiling_frame_data("physics_2d",values); + + } + +} void Physics2DServerSW::end_sync() { doing_sync=false; diff --git a/servers/physics_2d/physics_2d_server_sw.h b/servers/physics_2d/physics_2d_server_sw.h index 6415786803..d557688b91 100644 --- a/servers/physics_2d/physics_2d_server_sw.h +++ b/servers/physics_2d/physics_2d_server_sw.h @@ -55,6 +55,7 @@ friend class Physics2DDirectBodyStateSW; bool using_threads; + Step2DSW *stepper; Set<const Space2DSW*> active_spaces; diff --git a/servers/physics_2d/space_2d_sw.cpp b/servers/physics_2d/space_2d_sw.cpp index d83efeea9c..ddef5fc86b 100644 --- a/servers/physics_2d/space_2d_sw.cpp +++ b/servers/physics_2d/space_2d_sw.cpp @@ -1325,7 +1325,8 @@ Space2DSW::Space2DSW() { direct_access->space=this; - + for(int i=0;i<ELAPSED_TIME_MAX;i++) + elapsed_time[i]=0; } diff --git a/servers/physics_2d/space_2d_sw.h b/servers/physics_2d/space_2d_sw.h index 5f35f224b2..f8e1f32838 100644 --- a/servers/physics_2d/space_2d_sw.h +++ b/servers/physics_2d/space_2d_sw.h @@ -60,6 +60,20 @@ public: class Space2DSW { +public: + + enum ElapsedTime { + ELAPSED_TIME_INTEGRATE_FORCES, + ELAPSED_TIME_GENERATE_ISLANDS, + ELAPSED_TIME_SETUP_CONSTRAINTS, + ELAPSED_TIME_SOLVE_CONSTRAINTS, + ELAPSED_TIME_INTEGRATE_VELOCITIES, + ELAPSED_TIME_MAX + + }; +private: + + uint64_t elapsed_time[ELAPSED_TIME_MAX]; Physics2DDirectSpaceStateSW *direct_access; RID self; @@ -182,6 +196,9 @@ public: Physics2DDirectSpaceStateSW *get_direct_state(); + void set_elapsed_time(ElapsedTime p_time,uint64_t p_msec) { elapsed_time[p_time]=p_msec; } + uint64_t get_elapsed_time(ElapsedTime p_time) const { return elapsed_time[p_time]; } + Space2DSW(); ~Space2DSW(); }; diff --git a/servers/physics_2d/step_2d_sw.cpp b/servers/physics_2d/step_2d_sw.cpp index 4f9d06ee96..4f86168c1e 100644 --- a/servers/physics_2d/step_2d_sw.cpp +++ b/servers/physics_2d/step_2d_sw.cpp @@ -27,7 +27,7 @@ /* SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ /*************************************************************************/ #include "step_2d_sw.h" - +#include "os/os.h" void Step2DSW::_populate_island(Body2DSW* p_body,Body2DSW** p_island,Constraint2DSW **p_constraint_island) { @@ -142,6 +142,11 @@ void Step2DSW::step(Space2DSW* p_space,float p_delta,int p_iterations) { const SelfList<Body2DSW>::List * body_list = &p_space->get_active_body_list(); /* INTEGRATE FORCES */ + + uint64_t profile_begtime = OS::get_singleton()->get_ticks_usec(); + uint64_t profile_endtime=0; + + int active_count=0; const SelfList<Body2DSW>*b = body_list->first(); @@ -154,6 +159,13 @@ void Step2DSW::step(Space2DSW* p_space,float p_delta,int p_iterations) { p_space->set_active_objects(active_count); + + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(Space2DSW::ELAPSED_TIME_INTEGRATE_FORCES,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + /* GENERATE CONSTRAINT ISLANDS */ Body2DSW *island_list=NULL; @@ -190,7 +202,6 @@ void Step2DSW::step(Space2DSW* p_space,float p_delta,int p_iterations) { const SelfList<Area2DSW>::List &aml = p_space->get_moved_area_list(); - while(aml.first()) { for(const Set<Constraint2DSW*>::Element *E=aml.first()->self()->get_constraints().front();E;E=E->next()) { @@ -206,6 +217,13 @@ void Step2DSW::step(Space2DSW* p_space,float p_delta,int p_iterations) { } // print_line("island count: "+itos(island_count)+" active count: "+itos(active_count)); + + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(Space2DSW::ELAPSED_TIME_GENERATE_ISLANDS,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + /* SETUP CONSTRAINT ISLANDS */ { @@ -248,6 +266,12 @@ void Step2DSW::step(Space2DSW* p_space,float p_delta,int p_iterations) { } } + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(Space2DSW::ELAPSED_TIME_SETUP_CONSTRAINTS,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + /* SOLVE CONSTRAINT ISLANDS */ { @@ -259,6 +283,12 @@ void Step2DSW::step(Space2DSW* p_space,float p_delta,int p_iterations) { } } + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(Space2DSW::ELAPSED_TIME_SOLVE_CONSTRAINTS,profile_endtime-profile_begtime); + profile_begtime=profile_endtime; + } + /* INTEGRATE VELOCITIES */ b = body_list->first(); @@ -280,6 +310,12 @@ void Step2DSW::step(Space2DSW* p_space,float p_delta,int p_iterations) { } } + { //profile + profile_endtime=OS::get_singleton()->get_ticks_usec(); + p_space->set_elapsed_time(Space2DSW::ELAPSED_TIME_INTEGRATE_VELOCITIES,profile_endtime-profile_begtime); + //profile_begtime=profile_endtime; + } + p_space->update(); p_space->unlock(); _step++; diff --git a/servers/physics_2d_server.h b/servers/physics_2d_server.h index dd04f0f6b8..53c5a9ecc0 100644 --- a/servers/physics_2d_server.h +++ b/servers/physics_2d_server.h @@ -562,7 +562,9 @@ public: INFO_ACTIVE_OBJECTS, INFO_COLLISION_PAIRS, - INFO_ISLAND_COUNT + INFO_ISLAND_COUNT, + INFO_STEP_TIME, + INFO_BROAD_PHASE_TIME }; virtual int get_process_info(ProcessInfo p_info)=0; diff --git a/tools/editor/editor_node.cpp b/tools/editor/editor_node.cpp index fc676bda7e..25c854ce56 100644 --- a/tools/editor/editor_node.cpp +++ b/tools/editor/editor_node.cpp @@ -187,7 +187,7 @@ void EditorNode::_unhandled_input(const InputEvent& p_event) { break; case KEY_F5: _menu_option_confirm((p_event.key.mod.control&&p_event.key.mod.shift)?RUN_PLAY_CUSTOM_SCENE:RUN_PLAY,true); break; case KEY_F6: _menu_option_confirm(RUN_PLAY_SCENE,true); break; - case KEY_F7: _menu_option_confirm(RUN_PAUSE,true); break; + //case KEY_F7: _menu_option_confirm(RUN_PAUSE,true); break; case KEY_F8: _menu_option_confirm(RUN_STOP,true); break; } @@ -2636,11 +2636,6 @@ void EditorNode::_menu_option_confirm(int p_option,bool p_confirmed) { } } break; - case RUN_PAUSE: { - - emit_signal("pause_pressed"); - - } break; case RUN_STOP: { if (editor_run.get_status()==EditorRun::STATUS_STOP) @@ -5597,14 +5592,16 @@ EditorNode::EditorNode() { - /*pause_button = memnew( ToolButton ); + pause_button = memnew( ToolButton ); //menu_panel->add_child(pause_button); - not needed for now? pause_button->set_toggle_mode(true); pause_button->set_icon(gui_base->get_icon("Pause","EditorIcons")); pause_button->set_focus_mode(Control::FOCUS_NONE); - pause_button->connect("pressed", this,"_menu_option",make_binds(RUN_PAUSE)); - pause_button->set_tooltip(TTR("Pause the scene (F7).")); -*/ + //pause_button->connect("pressed", this,"_menu_option",make_binds(RUN_PAUSE)); + pause_button->set_tooltip(TTR("Pause the scene")); + pause_button->set_disabled(true); + play_hb->add_child(pause_button); + stop_button = memnew( ToolButton ); play_hb->add_child(stop_button); //stop_button->set_toggle_mode(true); diff --git a/tools/editor/editor_node.h b/tools/editor/editor_node.h index 8fa6cfefcf..5bd6ef0bdf 100644 --- a/tools/editor/editor_node.h +++ b/tools/editor/editor_node.h @@ -159,7 +159,7 @@ private: OBJECT_CALL_METHOD, OBJECT_REQUEST_HELP, RUN_PLAY, - RUN_PAUSE, + RUN_STOP, RUN_PLAY_SCENE, RUN_PLAY_NATIVE, @@ -692,6 +692,8 @@ public: void update_keying(); + ToolButton *get_pause_button() { return pause_button; } + ToolButton* add_bottom_panel_item(String p_text,Control *p_item); bool are_bottom_panels_hidden() const; diff --git a/tools/editor/editor_profiler.cpp b/tools/editor/editor_profiler.cpp new file mode 100644 index 0000000000..955af6b603 --- /dev/null +++ b/tools/editor/editor_profiler.cpp @@ -0,0 +1,753 @@ +#include "editor_profiler.h" +#include "editor_settings.h" +#include "os/os.h" + +void EditorProfiler::_make_metric_ptrs(Metric& m) { + + for(int i=0;i<m.categories.size();i++) { + m.category_ptrs[m.categories[i].signature]=&m.categories[i]; + for(int j=0;j<m.categories[i].items.size();j++) { + m.item_ptrs[m.categories[i].items[j].signature]=&m.categories[i].items[j]; + } + } +} + +void EditorProfiler::add_frame_metric(const Metric& p_metric,bool p_final) { + + ++last_metric; + if (last_metric>=frame_metrics.size()) + last_metric=0; + + + frame_metrics[last_metric]=p_metric; + _make_metric_ptrs(frame_metrics[last_metric]); + + updating_frame=true; + cursor_metric_edit->set_max(frame_metrics[last_metric].frame_number); + cursor_metric_edit->set_min(MAX(frame_metrics[last_metric].frame_number-frame_metrics.size(),0)); + + + if (!seeking) { + cursor_metric_edit->set_val(frame_metrics[last_metric].frame_number); + if (hover_metric!=-1) { + hover_metric++; + if (hover_metric>=frame_metrics.size()) { + hover_metric=0; + } + } + + } + updating_frame=false; + + if (!frame_delay->is_processing()) { + + frame_delay->set_wait_time(p_final?0.1:1); + frame_delay->start(); + } + + if (!plot_delay->is_processing()) { + plot_delay->set_wait_time(0.1); + plot_delay->start(); + } + +} + + + +void EditorProfiler::clear() { + + int metric_size=EditorSettings::get_singleton()->get("debugger/profiler_frame_history_size"); + metric_size = CLAMP(metric_size,60,1024); + frame_metrics.clear(); + frame_metrics.resize(metric_size); + last_metric=-1; + variables->clear(); + //activate->set_pressed(false); + plot_sigs.clear(); + plot_sigs.insert("fixed_frame_time"); + plot_sigs.insert("category_frame_time"); + + updating_frame=true; + cursor_metric_edit->set_min(0); + cursor_metric_edit->set_max(0); + cursor_metric_edit->set_val(0); + updating_frame=false; + hover_metric=-1; + seeking=false; +} + +static String _get_percent_txt(float p_value,float p_total) { + if (p_total==0) + p_total=0.00001; + return String::num((p_value/p_total)*100,1)+"%"; +} + + +String EditorProfiler::_get_time_as_text(Metric &m,float p_time,int p_calls) { + + int dmode = display_mode->get_selected(); + + + if (dmode==DISPLAY_FRAME_TIME) { + return rtos(p_time); + } else if (dmode==DISPLAY_AVERAGE_TIME) { + if (p_calls==0) + return "0"; + else + return rtos(p_time/p_calls); + } else if (dmode==DISPLAY_FRAME_PERCENT) { + return _get_percent_txt(p_time,m.frame_time); + } else if (dmode==DISPLAY_FIXED_FRAME_PERCENT) { + + return _get_percent_txt(p_time,m.fixed_frame_time); + } + + return "err"; +} + +Color EditorProfiler::_get_color_from_signature(const StringName& p_signature) const { + + double rot = ABS(double(p_signature.hash())/double(0x7FFFFFFF)); + Color c; + c.set_hsv(rot,1,1); + return c; + +} + +void EditorProfiler::_item_edited() { + + if (updating_frame) + return; + + TreeItem *item=variables->get_edited(); + if (!item) + return; + StringName signature=item->get_metadata(0); + bool checked=item->is_checked(0); + + + if (checked) + plot_sigs.insert(signature); + else + plot_sigs.erase(signature); + + if (!frame_delay->is_processing()) { + frame_delay->set_wait_time(0.1); + frame_delay->start(); + } +} + +void EditorProfiler::_update_plot() { + + int w = graph->get_size().width; + int h = graph->get_size().height; + + bool reset_texture=false; + + int desired_len = w * h * 4; + + if (graph_image.size()!=desired_len) { + reset_texture=true; + graph_image.resize(desired_len); + } + + + DVector<uint8_t>::Write wr = graph_image.write(); + + + + //clear + for(int i=0;i<desired_len;i+=4) { + wr[i+0]=0; + wr[i+1]=0; + wr[i+2]=0; + wr[i+3]=255; + } + + + //find highest value + + bool use_self = display_time->get_selected()==DISPLAY_SELF_TIME; + float highest=0; + + for(int i=0;i<frame_metrics.size();i++) { + Metric &m = frame_metrics[i]; + if (!m.valid) + continue; + + for (Set<StringName>::Element *E=plot_sigs.front();E;E=E->next()) { + + Map<StringName,Metric::Category*>::Element *F=m.category_ptrs.find(E->get()); + if (F) { + highest=MAX(F->get()->total_time,highest); + } + + Map<StringName,Metric::Category::Item*>::Element *G=m.item_ptrs.find(E->get()); + if (G) { + if (use_self) { + highest=MAX(G->get()->self,highest); + } else { + highest=MAX(G->get()->total,highest); + } + } + } + } + + if (highest>0) { + //means some data exists.. + highest*=1.2; //leave some upper room + graph_height=highest; + + Vector<int> columnv; + columnv.resize(h*4); + + int *column = columnv.ptr(); + + Map<StringName,int> plot_prev; + //Map<StringName,int> plot_max; + + uint64_t time = OS::get_singleton()->get_ticks_usec(); + + for(int i=0;i<w;i++) { + + + for(int j=0;j<h*4;j++) { + column[j]=0; + } + + int current = i*frame_metrics.size()/w; + int next = (i+1)*frame_metrics.size()/w; + if (next>frame_metrics.size()) { + next=frame_metrics.size(); + } + if (next==current) + next=current+1; //just because for loop must work + + for (Set<StringName>::Element *E=plot_sigs.front();E;E=E->next()) { + + int plot_pos=-1; + + for(int j=current;j<next;j++) { + + //wrap + int idx = last_metric+1+j; + while( idx >= frame_metrics.size() ) { + idx-=frame_metrics.size(); + } + + //get + Metric &m = frame_metrics[idx]; + if (m.valid==false) + continue; //skip because invalid + + + float value=0; + + Map<StringName,Metric::Category*>::Element *F=m.category_ptrs.find(E->get()); + if (F) { + value=F->get()->total_time; + } + + Map<StringName,Metric::Category::Item*>::Element *G=m.item_ptrs.find(E->get()); + if (G) { + if (use_self) { + value=G->get()->self; + } else { + value=G->get()->total; + } + } + + + plot_pos = MAX( CLAMP(int(value*h/highest),0,h-1), plot_pos ); + + + } + + int prev_plot=plot_pos; + Map<StringName,int>::Element *H=plot_prev.find(E->get()); + if (H) { + prev_plot=H->get(); + H->get()=plot_pos; + } else { + plot_prev[E->get()]=plot_pos; + } + + if (plot_pos==-1 && prev_plot==-1) { + //don't bother drawing + continue; + } + + if (prev_plot!=-1 && plot_pos==-1) { + + plot_pos=prev_plot; + } + + if (prev_plot==-1 && plot_pos!=-1) { + prev_plot=plot_pos; + } + + plot_pos = h- plot_pos -1; + prev_plot = h- prev_plot -1; + + if (prev_plot > plot_pos) { + SWAP(prev_plot,plot_pos); + } + + Color col = _get_color_from_signature(E->get()); + + for(int j=prev_plot;j<=plot_pos;j++) { + + column[j*4+0]+=Math::fast_ftoi(CLAMP(col.r*255,0,255)); + column[j*4+1]+=Math::fast_ftoi(CLAMP(col.g*255,0,255)); + column[j*4+2]+=Math::fast_ftoi(CLAMP(col.b*255,0,255)); + column[j*4+3]+=1; + + } + } + + + for(int j=0;j<h*4;j+=4) { + + int a = column[j+3]; + if (a>0) { + column[j+0]/=a; + column[j+1]/=a; + column[j+2]/=a; + + } + + uint8_t r = uint8_t(column[j+0]); + uint8_t g = uint8_t(column[j+1]); + uint8_t b = uint8_t(column[j+2]); + + int widx = ((j>>2)*w+i)*4; + wr[widx+0]=r; + wr[widx+1]=g; + wr[widx+2]=b; + wr[widx+3]=255; + } + } + + time = OS::get_singleton()->get_ticks_usec() - time; + //print_line("Taken: "+rtos(USEC_TO_SEC(time))); + + } + + + wr = DVector<uint8_t>::Write(); + + Image img(w,h,0,Image::FORMAT_RGBA,graph_image); + + if (reset_texture) { + + if (graph_texture.is_null()) { + graph_texture.instance(); + } + graph_texture->create(img.get_width(),img.get_height(),img.get_format(),Texture::FLAG_VIDEO_SURFACE); + + } + + graph_texture->set_data(img);; + + + graph->set_texture(graph_texture); + graph->update(); + +} + +void EditorProfiler::_update_frame() { + + int cursor_metric = _get_cursor_index(); + + + ERR_FAIL_INDEX(cursor_metric,frame_metrics.size()); + + updating_frame=true; + variables->clear(); + + TreeItem* root = variables->create_item(); + Metric &m = frame_metrics[cursor_metric]; + + + int dtime = display_time->get_selected(); + + + for(int i=0;i<m.categories.size();i++) { + + TreeItem *category = variables->create_item(root); + category->set_cell_mode(0,TreeItem::CELL_MODE_CHECK); + category->set_editable(0,true); + category->set_metadata(0,m.categories[i].signature); + category->set_text(0,String(m.categories[i].name)); + category->set_text(1,_get_time_as_text(m,m.categories[i].total_time,1)); + + if (plot_sigs.has(m.categories[i].signature)) { + category->set_checked(0,true); + category->set_custom_bg_color(0,Color(0,0,0)); + category->set_custom_color(0,_get_color_from_signature(m.categories[i].signature)); + } + + + for(int j=0;j<m.categories[i].items.size();j++) { + Metric::Category::Item &it = m.categories[i].items[j]; + + TreeItem *item = variables->create_item(category); + item->set_cell_mode(0,TreeItem::CELL_MODE_CHECK); + item->set_editable(0,true); + item->set_text(0,it.name); + item->set_metadata(0,it.signature); + item->set_metadata(1,it.script); + item->set_metadata(2,it.line); + item->set_tooltip(0,it.script+":"+itos(it.line)); + + float time = dtime == DISPLAY_SELF_TIME ? it.self : it.total; + + item->set_text(1,_get_time_as_text(m,time,it.calls)); + + item->set_text(2,itos(it.calls)); + + if (plot_sigs.has(it.signature)) { + item->set_checked(0,true); + item->set_custom_bg_color(0,Color(0,0,0)); + item->set_custom_color(0,_get_color_from_signature(it.signature)); + } + + } + } + + updating_frame=false; + +} + + +void EditorProfiler::_activate_pressed() { + + if (activate->is_pressed()) { + clear(); + activate->set_icon(get_icon("Stop","EditorIcons")); + activate->set_text(TTR("Stop Profilinng")); + } else { + activate->set_icon(get_icon("Play","EditorIcons")); + activate->set_text(TTR("Start Profilinng")); + + + } + emit_signal("enable_profiling",activate->is_pressed()); + +} + + +void EditorProfiler::_notification(int p_what) { + + if (p_what==NOTIFICATION_ENTER_TREE) { + activate->set_icon(get_icon("Play","EditorIcons")); + } +} + +void EditorProfiler::_graph_tex_draw() { + + if (last_metric<0) + return; + if (seeking) { + + int max_frames = frame_metrics.size(); + int frame = cursor_metric_edit->get_val() - (frame_metrics[last_metric].frame_number-max_frames+1); + if (frame<0) + frame=0; + + int cur_x = frame * graph->get_size().x / max_frames; + + + graph->draw_line(Vector2(cur_x,0),Vector2(cur_x,graph->get_size().y),Color(1,1,1,0.8)); + } + + + if (hover_metric!=-1 && frame_metrics[hover_metric].valid) { + + + + int max_frames = frame_metrics.size(); + int frame = frame_metrics[hover_metric].frame_number - (frame_metrics[last_metric].frame_number-max_frames+1); + if (frame<0) + frame=0; + + int cur_x = frame * graph->get_size().x / max_frames; + + graph->draw_line(Vector2(cur_x,0),Vector2(cur_x,graph->get_size().y),Color(1,1,1,0.4)); + + + } + +} + +void EditorProfiler::_graph_tex_mouse_exit() { + + hover_metric=-1; + graph->update(); +} + + +void EditorProfiler::_cursor_metric_changed(double) { + if (updating_frame) + return; + + + graph->update(); + _update_frame(); + +} + +void EditorProfiler::_graph_tex_input(const InputEvent& p_ev){ + + if (last_metric<0) + return; + + if ( + (p_ev.type==InputEvent::MOUSE_BUTTON && p_ev.mouse_button.button_index==BUTTON_LEFT && p_ev.mouse_button.pressed) || + (p_ev.type==InputEvent::MOUSE_MOTION) ) { + + int x = p_ev.mouse_button.x; + x=x*frame_metrics.size()/graph->get_size().width; + + bool show_hover = x>=0 && x<frame_metrics.size(); + + if (x<0) { + x=0; + } + + if (x>=frame_metrics.size()) { + x=frame_metrics.size()-1; + } + + + + int metric=frame_metrics.size()-x-1; + metric = last_metric-metric; + while(metric<0) { + metric+=frame_metrics.size(); + } + + + + if (show_hover) { + + hover_metric=metric; + + } else { + hover_metric=-1; + } + + + if (p_ev.type==InputEvent::MOUSE_BUTTON || p_ev.mouse_motion.button_mask&BUTTON_MASK_LEFT) { + //cursor_metric=x; + updating_frame=true; + + //metric may be invalid, so look for closest metric that is valid, this makes snap feel better + bool valid=false; + for(int i=0;i<frame_metrics.size();i++) { + + if (frame_metrics[metric].valid) { + valid=true; + break; + } + + metric++; + if (metric>=frame_metrics.size()) + metric=0; + } + + if (valid) + cursor_metric_edit->set_val(frame_metrics[metric].frame_number); + + updating_frame=false; + + if (activate->is_pressed()) { + if (!seeking) { + emit_signal("break_request"); + } + } + + seeking=true; + + if (!frame_delay->is_processing()) { + frame_delay->set_wait_time(0.1); + frame_delay->start(); + } + } + + graph->update(); + + } + +} + +int EditorProfiler::_get_cursor_index() const { + + if (last_metric<0) + return 0; + if (!frame_metrics[last_metric].valid) + return 0; + + int diff = (frame_metrics[last_metric].frame_number-cursor_metric_edit->get_val()); + + int idx = last_metric - diff; + while (idx<0) { + idx+=frame_metrics.size(); + } + + + return idx; + +} + +void EditorProfiler::disable_seeking() { + + seeking=false; + graph->update(); + +} + +void EditorProfiler::_combo_changed(int) { + + _update_frame(); + _update_plot(); +} + +void EditorProfiler::_bind_methods() { + + ObjectTypeDB::bind_method(_MD("_update_frame"),&EditorProfiler::_update_frame); + ObjectTypeDB::bind_method(_MD("_update_plot"),&EditorProfiler::_update_plot); + ObjectTypeDB::bind_method(_MD("_activate_pressed"),&EditorProfiler::_activate_pressed); + ObjectTypeDB::bind_method(_MD("_graph_tex_draw"),&EditorProfiler::_graph_tex_draw); + ObjectTypeDB::bind_method(_MD("_graph_tex_input"),&EditorProfiler::_graph_tex_input); + ObjectTypeDB::bind_method(_MD("_graph_tex_mouse_exit"),&EditorProfiler::_graph_tex_mouse_exit); + ObjectTypeDB::bind_method(_MD("_cursor_metric_changed"),&EditorProfiler::_cursor_metric_changed); + ObjectTypeDB::bind_method(_MD("_combo_changed"),&EditorProfiler::_combo_changed); + + ObjectTypeDB::bind_method(_MD("_item_edited"),&EditorProfiler::_item_edited); + ADD_SIGNAL( MethodInfo("enable_profiling",PropertyInfo(Variant::BOOL,"enable"))); + ADD_SIGNAL( MethodInfo("break_request")); + +} + +void EditorProfiler::set_enabled(bool p_enable) { + + activate->set_disabled(!p_enable); +} + +bool EditorProfiler::is_profiling() { + return activate->is_pressed(); +} + +EditorProfiler::EditorProfiler() +{ + + HBoxContainer *hb = memnew( HBoxContainer ); + add_child(hb); + activate = memnew( Button ); + activate->set_toggle_mode(true); + activate->set_text(TTR("Start Profiling")); + activate->connect("pressed",this,"_activate_pressed"); + hb->add_child(activate); + + hb->add_child( memnew( Label(TTR("Measure:") ) ) ); + + display_mode = memnew( OptionButton ); + display_mode->add_item(TTR("Frame Time (sec)")); + display_mode->add_item(TTR("Average Time (sec)")); + display_mode->add_item(TTR("Frame %")); + display_mode->add_item(TTR("Fixed Frame %")); + display_mode->connect("item_selected",this,"_combo_changed"); + + hb->add_child( display_mode ); + + hb->add_child( memnew( Label(TTR("Time:") ) ) ); + + display_time = memnew( OptionButton ); + display_time->add_item(TTR("Inclusive")); + display_time->add_item(TTR("Self")); + display_time->connect("item_selected",this,"_combo_changed"); + + hb->add_child(display_time); + + hb->add_spacer(); + + hb->add_child( memnew( Label(TTR("Frame#:") ) ) ); + + cursor_metric_edit = memnew( SpinBox ); + cursor_metric_edit->set_h_size_flags(SIZE_FILL); + hb->add_child(cursor_metric_edit); + cursor_metric_edit->connect("value_changed",this,"_cursor_metric_changed"); + + hb->add_constant_override("separation",8); + + + + h_split = memnew( HSplitContainer ); + add_child(h_split); + h_split->set_v_size_flags(SIZE_EXPAND_FILL); + + variables = memnew( Tree ); + variables->set_custom_minimum_size(Size2(300,0)); + variables->set_hide_folding(true); + h_split->add_child(variables); + variables->set_hide_root(true); + variables->set_columns(3); + variables->set_column_titles_visible(true); + variables->set_column_title(0,"Name"); + variables->set_column_expand(0,true); + variables->set_column_min_width(0,60); + variables->set_column_title(1,"Time"); + variables->set_column_expand(1,false); + variables->set_column_min_width(1,60); + variables->set_column_title(2,"Calls"); + variables->set_column_expand(2,false); + variables->set_column_min_width(2,60); + variables->connect("item_edited",this,"_item_edited"); + + + graph = memnew( TextureFrame ); + graph->set_expand(true); + graph->set_stop_mouse(true); + graph->set_ignore_mouse(false); + graph->connect("draw",this,"_graph_tex_draw"); + graph->connect("input_event",this,"_graph_tex_input"); + graph->connect("mouse_exit",this,"_graph_tex_mouse_exit"); + + h_split->add_child(graph); + graph->set_h_size_flags(SIZE_EXPAND_FILL); + + add_constant_override("separation",3); + + int metric_size=CLAMP(int(EDITOR_DEF("debugger/profiler_frame_history_size",600)),60,1024); + frame_metrics.resize(metric_size); + last_metric=-1; +// cursor_metric=-1; + hover_metric=-1; + + + EDITOR_DEF("debugger/profiler_frame_max_functions",64); + + //display_mode=DISPLAY_FRAME_TIME; + + frame_delay = memnew( Timer ); + frame_delay->set_wait_time(0.1); + frame_delay->set_one_shot(true); + add_child(frame_delay); + frame_delay->connect("timeout",this,"_update_frame"); + + plot_delay = memnew( Timer ); + plot_delay->set_wait_time(0.1); + plot_delay->set_one_shot(true); + add_child(plot_delay); + plot_delay->connect("timeout",this,"_update_plot"); + + plot_sigs.insert("fixed_frame_time"); + plot_sigs.insert("category_frame_time"); + + seeking=false; + graph_height=1; + +// activate->set_disabled(true); + +} diff --git a/tools/editor/editor_profiler.h b/tools/editor/editor_profiler.h new file mode 100644 index 0000000000..aca3220717 --- /dev/null +++ b/tools/editor/editor_profiler.h @@ -0,0 +1,143 @@ +#ifndef EDITORPROFILER_H +#define EDITORPROFILER_H + + +#include "scene/gui/box_container.h" +#include "scene/gui/texture_frame.h" +#include "scene/gui/button.h" +#include "scene/gui/label.h" +#include "scene/gui/tree.h" +#include "scene/gui/split_container.h" +#include "scene/gui/option_button.h" +#include "scene/gui/spin_box.h" + + +class EditorProfiler : public VBoxContainer { + + OBJ_TYPE(EditorProfiler,VBoxContainer) + +public: + + struct Metric { + + bool valid; + + int frame_number; + float frame_time; + float idle_time; + float fixed_time; + float fixed_frame_time; + + struct Category { + + StringName signature; + String name; + float total_time; //total for category + + struct Item { + + StringName signature; + String name; + String script; + int line; + float self; + float total; + int calls; + }; + + Vector<Item> items; + }; + + Vector<Category> categories; + + Map<StringName,Category*> category_ptrs; + Map<StringName,Category::Item*> item_ptrs; + + + Metric() { valid=false; frame_number=0; } + }; + + enum DisplayMode { + DISPLAY_FRAME_TIME, + DISPLAY_AVERAGE_TIME, + DISPLAY_FRAME_PERCENT, + DISPLAY_FIXED_FRAME_PERCENT, + }; + + enum DisplayTime { + DISPLAY_TOTAL_TIME, + DISPLAY_SELF_TIME, + }; + +private: + Button *activate; + TextureFrame *graph; + Ref<ImageTexture> graph_texture; + DVector<uint8_t> graph_image; + Tree *variables; + HSplitContainer *h_split; + + Set<StringName> plot_sigs; + + OptionButton *display_mode; + OptionButton *display_time; + + SpinBox * cursor_metric_edit; + + Vector<Metric> frame_metrics; + int last_metric; + + int max_functions; + + bool updating_frame; + + //int cursor_metric; + int hover_metric; + + bool seeking; + + Timer *frame_delay; + Timer *plot_delay; + + void _update_frame(); + + void _activate_pressed(); + + String _get_time_as_text(Metric &m,float p_time,int p_calls); + + void _make_metric_ptrs(Metric& m); + void _item_edited(); + + void _update_plot(); + + void _graph_tex_mouse_exit(); + + void _graph_tex_draw(); + void _graph_tex_input(const InputEvent& p_ev); + + int _get_cursor_index() const; + + Color _get_color_from_signature(const StringName& p_signature) const; + + void _cursor_metric_changed(double); + + void _combo_changed(int); + +protected: + + void _notification(int p_what); + static void _bind_methods(); +public: + + void add_frame_metric(const Metric& p_metric, bool p_final=false); + void set_enabled(bool p_enable); + bool is_profiling(); + bool is_seeking() { return seeking; } + void disable_seeking(); + + void clear(); + + EditorProfiler(); +}; + +#endif // EDITORPROFILER_H diff --git a/tools/editor/script_editor_debugger.cpp b/tools/editor/script_editor_debugger.cpp index 325eadc1e5..b0cd2e925d 100644 --- a/tools/editor/script_editor_debugger.cpp +++ b/tools/editor/script_editor_debugger.cpp @@ -41,6 +41,8 @@ #include "globals.h" #include "editor_node.h" #include "main/performance.h" +#include "editor_profiler.h" +#include "editor_settings.h" class ScriptEditorDebuggerVariables : public Object { @@ -208,7 +210,13 @@ void ScriptEditorDebugger::_parse_message(const String& p_msg,const Array& p_dat docontinue->set_disabled(false); emit_signal("breaked",true,can_continue); OS::get_singleton()->move_window_to_foreground(); - tabs->set_current_tab(0); + if (!profiler->is_seeking()) + tabs->set_current_tab(0); + + profiler->set_enabled(false); + + EditorNode::get_singleton()->get_pause_button()->set_pressed(true); + EditorNode::get_singleton()->make_bottom_panel_item_visible(this); @@ -225,6 +233,11 @@ void ScriptEditorDebugger::_parse_message(const String& p_msg,const Array& p_dat docontinue->set_disabled(true); emit_signal("breaked",false,false); //tabs->set_current_tab(0); + profiler->set_enabled(true); + profiler->disable_seeking(); + + EditorNode::get_singleton()->get_pause_button()->set_pressed(false); + } else if (p_msg=="message:click_ctrl") { @@ -441,6 +454,137 @@ void ScriptEditorDebugger::_parse_message(const String& p_msg,const Array& p_dat packet_peer_stream->put_var(oe.warning); packet_peer_stream->put_var(oe.callstack); */ + + } else if (p_msg=="profile_sig") { + //cache a signature + print_line("SIG: "+String(Variant(p_data))); + profiler_signature[p_data[1]]=p_data[0]; + + } else if (p_msg=="profile_frame" || p_msg=="profile_total") { + + EditorProfiler::Metric metric; + metric.valid=true; + metric.frame_number=p_data[0]; + metric.frame_time=p_data[1]; + metric.idle_time=p_data[2]; + metric.fixed_time=p_data[3]; + metric.fixed_frame_time=p_data[4]; + int frame_data_amount = p_data[6]; + int frame_function_amount = p_data[7]; + + + if (frame_data_amount) { + EditorProfiler::Metric::Category frame_time; + frame_time.signature="category_frame_time"; + frame_time.name="Frame Time"; + frame_time.total_time=metric.frame_time; + + EditorProfiler::Metric::Category::Item item; + item.calls=1; + item.line=0; + item.name="Fixed Time"; + item.total=metric.fixed_time; + item.self=item.total; + item.signature="fixed_time"; + + + frame_time.items.push_back(item); + + item.name="Idle Time"; + item.total=metric.idle_time; + item.self=item.total; + item.signature="idle_time"; + + frame_time.items.push_back(item); + + item.name="Fixed Frame Time"; + item.total=metric.fixed_frame_time; + item.self=item.total; + item.signature="fixed_frame_time"; + + frame_time.items.push_back(item); + + metric.categories.push_back(frame_time); + + } + + + + int idx=8; + for(int i=0;i<frame_data_amount;i++) { + + EditorProfiler::Metric::Category c; + String name=p_data[idx++]; + Array values=p_data[idx++]; + c.name=name.capitalize(); + c.items.resize(values.size()/2); + c.total_time=0; + c.signature="categ::"+name; + for(int i=0;i<values.size();i+=2) { + + EditorProfiler::Metric::Category::Item item; + item.name=values[i]; + item.calls=1; + item.self=values[i+1]; + item.total=item.self; + item.signature="categ::"+name+"::"+item.name; + item.name=item.name.capitalize(); + c.total_time+=item.total; + c.items[i/2]=item; + + + } + metric.categories.push_back(c); + } + + EditorProfiler::Metric::Category funcs; + funcs.total_time=p_data[5]; //script time + funcs.items.resize(frame_function_amount); + funcs.name="Script Functions"; + funcs.signature="script_functions"; + for(int i=0;i<frame_function_amount;i++) { + + int signature = p_data[idx++]; + int calls = p_data[idx++]; + float total = p_data[idx++]; + float self = p_data[idx++]; + + + + EditorProfiler::Metric::Category::Item item; + if (profiler_signature.has(signature)) { + + item.signature=profiler_signature[signature]; + + String name = profiler_signature[signature]; + Vector<String> strings = name.split("::"); + if (strings.size()==3) { + item.name=strings[2]; + item.script=strings[0]; + item.line=strings[1].to_int(); + } + + } else { + item.name="SigErr "+itos(signature); + } + + + + + item.calls=calls; + item.self=self; + item.total=total; + funcs.items[i]=item; + + } + + metric.categories.push_back(funcs); + + if (p_msg=="profile_frame") + profiler->add_frame_metric(metric,false); + else + profiler->add_frame_metric(metric,true); + } else if (p_msg=="kill_me") { editor->call_deferred("stop_child_process"); @@ -586,15 +730,25 @@ void ScriptEditorDebugger::_notification(int p_what) { reason->set_text(TTR("Child Process Connected")); reason->set_tooltip(TTR("Child Process Connected")); + profiler->clear(); + scene_tree->clear(); le_set->set_disabled(true); le_clear->set_disabled(false); error_list->clear(); error_stack->clear(); error_count=0; + profiler_signature.clear(); //live_edit_root->set_text("/root"); + EditorNode::get_singleton()->get_pause_button()->set_pressed(false); + EditorNode::get_singleton()->get_pause_button()->set_disabled(false); + update_live_edit_root(); + if (profiler->is_profiling()) { + _profiler_activate(true); + } + } else { @@ -656,6 +810,7 @@ void ScriptEditorDebugger::_notification(int p_what) { } message_type=cmd; + //print_line("GOT: "+message_type); ret = ppeer->get_var(cmd); if (ret!=OK) { @@ -744,8 +899,14 @@ void ScriptEditorDebugger::stop(){ node_path_cache.clear(); res_path_cache.clear(); + profiler_signature.clear(); le_clear->set_disabled(false); le_set->set_disabled(true); + profiler->set_enabled(true); + + EditorNode::get_singleton()->get_pause_button()->set_pressed(false); + EditorNode::get_singleton()->get_pause_button()->set_disabled(true); + if (hide_on_stop) { @@ -756,6 +917,44 @@ void ScriptEditorDebugger::stop(){ } +void ScriptEditorDebugger::_profiler_activate(bool p_enable) { + + if (!connection.is_valid()) + return; + + + if (p_enable) { + profiler_signature.clear(); + Array msg; + msg.push_back("start_profiling"); + int max_funcs = EditorSettings::get_singleton()->get("debugger/profiler_frame_max_functions"); + max_funcs = CLAMP(max_funcs,16,512); + msg.push_back(max_funcs); + ppeer->put_var(msg); + + print_line("BEGIN PROFILING!"); + + } else { + Array msg; + msg.push_back("stop_profiling"); + ppeer->put_var(msg); + + print_line("END PROFILING!"); + + } + +} + +void ScriptEditorDebugger::_profiler_seeked() { + + if (!connection.is_valid() || !connection->is_connected()) + return; + + if (breaked) + return; + debug_break();; +} + void ScriptEditorDebugger::_stack_dump_frame_selected() { @@ -1172,6 +1371,21 @@ void ScriptEditorDebugger::set_hide_on_stop(bool p_hide) { hide_on_stop=p_hide; } +void ScriptEditorDebugger::_paused() { + + ERR_FAIL_COND(connection.is_null()); + ERR_FAIL_COND(!connection->is_connected()); + + if (!breaked && EditorNode::get_singleton()->get_pause_button()->is_pressed()) { + debug_break(); + } + + if (breaked && !EditorNode::get_singleton()->get_pause_button()->is_pressed()) { + debug_continue(); + } + +} + void ScriptEditorDebugger::_bind_methods() { ObjectTypeDB::bind_method(_MD("_stack_dump_frame_selected"),&ScriptEditorDebugger::_stack_dump_frame_selected); @@ -1189,6 +1403,11 @@ void ScriptEditorDebugger::_bind_methods() { ObjectTypeDB::bind_method(_MD("_error_selected"),&ScriptEditorDebugger::_error_selected); ObjectTypeDB::bind_method(_MD("_error_stack_selected"),&ScriptEditorDebugger::_error_stack_selected); + ObjectTypeDB::bind_method(_MD("_profiler_activate"),&ScriptEditorDebugger::_profiler_activate); + ObjectTypeDB::bind_method(_MD("_profiler_seeked"),&ScriptEditorDebugger::_profiler_seeked); + + ObjectTypeDB::bind_method(_MD("_paused"),&ScriptEditorDebugger::_paused); + ObjectTypeDB::bind_method(_MD("live_debug_create_node"),&ScriptEditorDebugger::live_debug_create_node); ObjectTypeDB::bind_method(_MD("live_debug_instance_node"),&ScriptEditorDebugger::live_debug_instance_node); @@ -1320,6 +1539,12 @@ ScriptEditorDebugger::ScriptEditorDebugger(EditorNode *p_editor){ error_split->set_name(TTR("Errors")); tabs->add_child(error_split); + profiler = memnew( EditorProfiler ); + profiler->set_name("Profiler"); + tabs->add_child(profiler); + profiler->connect("enable_profiling",this,"_profiler_activate"); + profiler->connect("break_request",this,"_profiler_seeked"); + HSplitContainer *hsp = memnew( HSplitContainer ); @@ -1334,7 +1559,7 @@ ScriptEditorDebugger::ScriptEditorDebugger(EditorNode *p_editor){ perf_draw = memnew( Control ); perf_draw->connect("draw",this,"_performance_draw"); hsp->add_child(perf_draw); - hsp->set_name("Performance"); + hsp->set_name("Metrics"); hsp->set_split_offset(300); tabs->add_child(hsp); perf_max.resize(Performance::MONITOR_MAX); @@ -1468,6 +1693,8 @@ ScriptEditorDebugger::ScriptEditorDebugger(EditorNode *p_editor){ hide_on_stop=true; last_error_count=0; + EditorNode::get_singleton()->get_pause_button()->connect("pressed",this,"_paused"); + } diff --git a/tools/editor/script_editor_debugger.h b/tools/editor/script_editor_debugger.h index ecd0494955..1288349884 100644 --- a/tools/editor/script_editor_debugger.h +++ b/tools/editor/script_editor_debugger.h @@ -34,6 +34,7 @@ #include "core/io/tcp_server.h" #include "core/io/packet_peer.h" + class Tree; class PropertyEditor; class EditorNode; @@ -46,6 +47,7 @@ class AcceptDialog; class TreeItem; class HSplitContainer; class ItemList; +class EditorProfiler; class ScriptEditorDebugger : public Control { @@ -93,6 +95,8 @@ class ScriptEditorDebugger : public Control { Vector<float> perf_max; Vector<TreeItem*> perf_items; + Map<int,String> profiler_signature; + Tree *perf_monitors; Control *perf_draw; @@ -115,6 +119,7 @@ class ScriptEditorDebugger : public Control { int last_path_id; Map<String,int> res_path_cache; + EditorProfiler *profiler; EditorNode *editor; @@ -148,6 +153,13 @@ class ScriptEditorDebugger : public Control { void _error_selected(int p_idx); void _error_stack_selected(int p_idx); + void _profiler_activate(bool p_enable); + void _profiler_seeked(); + + + + void _paused(); + protected: void _notification(int p_what); |