Added code to profile vm execution, it's activated by defining PROFILE_SQVM

SquiLu/samples/process-profile-data.nut

@@ -0,0 +1,47 @@
+local profile_data = [==[
+1	1	7	0	_OP_LOAD
+2	2	1193711	2266	_OP_LOADINT
+6	6	796719	1509	_OP_CALL
+8	8	265587	516	_OP_PREPCALLK
+9	9	6	0	_OP_GETK
+10	10	659839	1258	_OP_MOVE
+14	14	528410	1004	_OP_GET
+17	17	265574	552	_OP_ADD
+18	18	262849	532	_OP_SUB
+19	19	4	0	_OP_MUL
+23	23	531133	993	_OP_RETURN
+26	26	265566	513	_OP_LOADBOOL
+27	27	134148	244	_OP_DMOVE
+28	28	1364	2	_OP_JMP
+29	29	266936	512	_OP_JCMP
+30	30	265566	595	_OP_JZ
+32	32	525688	969	_OP_GETOUTER
+33	33	265566	517	_OP_NEWOBJ
+34	34	528410	1018	_OP_APPENDARRAY
+37	37	132782	254	_OP_INCL
+48	48	2	6	_OP_CLOSURE
+]==]
+
+local profile = [];
+local total_time = 0.0;
+foreach(line in profile_data.split('\n')){
+	//print(line);
+	local rec = line.split('\t');
+	rec[2] = rec[2].tointeger();
+	rec[3] = rec[3].tointeger();
+	total_time += rec[3];
+	profile.push(rec);
+}
+
+foreach(rec in profile){
+	local pct = (rec[3] / total_time) * 100;
+	rec[1] = math.roundf(pct, 2);
+	rec.insert(2, math.roundf(rec[3]/rec[2].tofloat(), 4));
+}
+
+profile.sort(@(a,b) b[1] <=> a[1]);
+
+print("OP\t%time\t%call\t%ncalls\ttotal_time\tOP name");
+foreach(rec in profile){
+	print(rec.concat("\t"));
+}

SquiLu/squirrel/sqopcodes.h

@@ -97,9 +97,12 @@ enum AppendArrayType {
 	ENUM_OP(_OP_THROW, 0x39)\
 	ENUM_OP(_OP_NEWSLOTA, 0x3A)\
 	ENUM_OP(_OP_GETBASE, 0x3B)\
-	ENUM_OP(_OP_CLOSE, 0x3C)
+	ENUM_OP(_OP_CLOSE, 0x3C)\
+	ENUM_OP(_OP__LAST__, 0x3D)
 
-#define ENUM_OP(a,b) a = b,
+//#define ENUM_OP(a,b) a = b,
+//there is no point right now to manually number the opcodes
+#define ENUM_OP(a,b) a,
 enum SQOpcode
 {
     SQ_OP_CODE_LIST()

SquiLu/squirrel/sqvm.cpp

@@ -114,6 +114,12 @@ bool SQVM::ARITH_OP(SQUnsignedInteger op,SQObjectPtr &trg,const SQObjectPtr &o1,
 	}
 	return true;
 }
+
+#ifdef PROFILE_SQVM
+//from sqstdsystem
+int GetMilliCount();
+int GetMilliSpan( int nTimeStart );
+#endif
 
 SQVM::SQVM(SQSharedState *ss)
 {
@@ -135,11 +141,22 @@ SQVM::SQVM(SQSharedState *ss)
 	_openouters = NULL;
 	ci = NULL;
 	INIT_CHAIN();ADD_TO_CHAIN(&_ss(this)->_gc_chain,this);
-	_check_delayed_relase_hooks = true;
-}
+	_check_delayed_relase_hooks = true;
+#ifdef PROFILE_SQVM
+	printf("SQVM::SQVM : %p\n", this);
+	_last_op_profile_time = GetMilliCount();
+	_op_profile.resize(_OP__LAST__+1);
+	for(SQUnsignedInteger i=0; i <= _OP__LAST__; ++i){
+		OpProfile &opp = _op_profile[i];
+		opp.op = i;
+		opp.count = opp.total_time = 0;
+	}
+#endif
+}
 
 void SQVM::Finalize()
 {
+	if(!_alloccallsstacksize) return; //to prevent multiple calls
     CallAtExitHandler();
     _sharedstate->CallDelayedReleaseHooks(this);
 	if(_openouters) CloseOuters(&_stack._vals[0]);
@@ -155,6 +172,16 @@ void SQVM::Finalize()
 	SQInteger size=_stack.size();
 	for(SQInteger i=0;i<size;i++)
 		_stack[i].Null();
+#ifdef PROFILE_SQVM
+	printf("SQVM::Finalize : %p\n", this);
+#define ENUM_OP(a,b) {\
+		OpProfile &opp = _op_profile[a];\
+		if(opp.count) printf("%d\t%d\t%d\t%d\t%s\n", a, opp.op, opp.count, opp.total_time, _SC(#a));\
+	}
+    SQ_OP_CODE_LIST()
+#undef ENUM_OP
+#endif
+	_alloccallsstacksize = 0; //to prevent multiple calls
 }
 
 SQVM::~SQVM()
@@ -748,15 +775,24 @@ exception_restore:
 #else
 
 	//
-	{
+	{
 		for(;;)
 		{
 		    //if the last instruction was a call then check for release hooks
 		    //obs.: changing the order of comparison bellow with gcc makes the code slower
 		    if((ci->_ip->op == _OP_CALL) && _check_delayed_relase_hooks) _sharedstate->CallDelayedReleaseHooks(this);
+#ifdef PROFILE_SQVM
+			OpProfile &opp_last = _op_profile[ci->_ip->op];
+			opp_last.total_time += GetMilliSpan(_last_op_profile_time);
+			_last_op_profile_time = GetMilliCount();
+#endif
 			const SQInstruction &_i_ = *ci->_ip++;
 			//dumpstack(_stackbase);
 			//scprintf("\n[%d] %s %d %d %d %d\n",ci->_ip-ci->_iv->_vals,g_InstrDesc[_i_.op].name,arg0,arg1,arg2,arg3);
+#ifdef PROFILE_SQVM
+			OpProfile &opp = _op_profile[_i_.op];
+			++opp.count;
+#endif
 			switch(_i_.op)
 			{
 			case _OP_LINE: if (_debughook) CallDebugHook(_SC('l'),arg1); continue;

SquiLu/squirrel/sqvm.h

@@ -45,7 +45,11 @@ struct SQVM : public CHAINABLE_OBJ
 		SQBool _root;
 	};
 
-typedef sqvector<CallInfo> CallInfoVec;
+typedef sqvector<CallInfo> CallInfoVec;
+#ifdef PROFILE_SQVM
+	struct OpProfile {SQInteger op, count, total_time;};
+	typedef sqvector<OpProfile> OpProfileVec;
+#endif
 public:
 	void DebugHookProxy(SQInteger type, const SQChar * sourcename, SQInteger line, const SQChar * funcname);
 	static void _DebugHookProxy(HSQUIRRELVM v, SQInteger type, const SQChar * sourcename, SQInteger line, const SQChar * funcname);
@@ -179,7 +183,11 @@ public:
 	SQBool _suspended_root;
 	SQBool _check_delayed_relase_hooks;
 	SQInteger _suspended_target;
-	SQInteger _suspended_traps;
+	SQInteger _suspended_traps;
+#ifdef PROFILE_SQVM
+	OpProfileVec _op_profile;
+	SQInteger _last_op_profile_time;
+#endif
 };
 
 struct AutoDec{