11 files changed, 413 insertions, 2 deletions

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