Added new debug feature: Performance Monitor. (#1019)

* Performance Monitor.

Search big performance issues for any plugin that in debug mode. No server slow down.
Output is plugin and function name, and server execution lag in ms. Output target: current amxlog file.

* Adding cvar to enable perflog. Force for all plugin if amx_debug is 2.

* Update cvar name

* Use another clock from chrono

* Fix debug check

* Skip internal amxx exec

* Move includes

* Fix debug check in amx_ExecPerf

* Tried to compile without min/max undefined

amxmodx/CForward.cpp

@@ -122,8 +122,8 @@ cell CForward::execute(cell *params, ForwardPreparedArray *preparedArrays)
 #if defined BINLOG_ENABLED
 			g_BinLog.WriteOp(BinLog_CallPubFunc, iter->pPlugin->getId(), iter->func);
 #endif
-			int err = amx_Exec(amx, &retVal, iter->func);
-			
+
+			int err = amx_ExecPerf(amx, &retVal, iter->func);
 			// log runtime error, if any
 			if (err != AMX_ERR_NONE)
 			{
@@ -327,8 +327,7 @@ cell CSPForward::execute(cell *params, ForwardPreparedArray *preparedArrays)
 #if defined BINLOG_ENABLED
 	g_BinLog.WriteOp(BinLog_CallPubFunc, pPlugin->getId(), m_Func);
 #endif
-	int err = amx_Exec(m_Amx, &retVal, m_Func);
-	
+	int err = amx_ExecPerf(m_Amx, &retVal, m_Func);
 	if (err != AMX_ERR_NONE)
 	{
 		//Did something else set an error?

amxmodx/amx.cpp

@@ -66,6 +66,9 @@
   #include <windows.h>
 #endif
 
+#include <chrono>
+#include <amxmodx.h>
+#include <CPlugin.h>
 
 /* When one or more of the AMX_funcname macris are defined, we want
  * to compile only those functions. However, when none of these macros
@@ -4173,3 +4176,37 @@ int AMXAPI amx_GetStringOld(char *dest,const cell *source,int use_wchar)
   dest[len]='\0';     /* store terminator */
   return AMX_ERR_NONE;
 }
+
+int AMXAPI amx_ExecPerf(AMX* amx, cell* retval, int index)
+{
+    CPluginMngr::CPlugin* perf_Plug = g_plugins.findPluginFast(amx);
+    if (amxmodx_perflog->value > 0.0f && perf_Plug && (perf_Plug->isDebug() || (int)amxmodx_debug->value == 2))
+    {
+        char perf_funcname[sNAMEMAX + 1];
+        perf_funcname[0] = '\0';
+        amx_GetPublic(perf_Plug->getAMX(), index, perf_funcname);
+        if (perf_funcname[0] == '\0')
+            sprintf(perf_funcname, "Unknown_ID%d", index);
+
+        const char* perf_plugname = perf_Plug->getName();
+        if (!perf_plugname || perf_plugname[0] == '\0')
+            perf_plugname = "Unknown_plugin";
+
+        using std::chrono::steady_clock;
+        using std::chrono::duration_cast;
+        using std::chrono::duration;
+        using std::chrono::microseconds;
+
+        auto t1 = steady_clock::now();
+        int err = amx_Exec(amx, retval, index);
+
+        auto ms_int = duration_cast<microseconds>(steady_clock::now() - t1);
+        auto ms_float = (float)(ms_int.count() / 1000.0f);
+        if (ms_float >= amxmodx_perflog->value)
+        {
+            AMXXLOG_Log("[%s] performance issue. Function %s executed more than %.*fms.", perf_plugname, perf_funcname, 1, ms_float);
+        }
+        return err;
+    }
+    return amx_Exec(amx, retval, index);
+}

amxmodx/amx.h

@@ -382,6 +382,7 @@ int AMXAPI amx_Callback(AMX *amx, cell index, cell *result, cell *params);
 int AMXAPI amx_CheckNatives(AMX *amx, AMX_NATIVE_FILTER nf);
 int AMXAPI amx_Cleanup(AMX *amx);
 int AMXAPI amx_Clone(AMX *amxClone, AMX *amxSource, void *data);
+int AMXAPI amx_ExecPerf(AMX* amx, cell* retval, int index);
 int AMXAPI amx_Exec(AMX *amx, cell *retval, int index);
 int AMXAPI amx_FindNative(AMX *amx, const char *name, int *index);
 int AMXAPI amx_FindPublic(AMX *amx, const char *funcname, int *index);

amxmodx/amxmodx.cpp

@@ -3709,7 +3709,7 @@ static cell AMX_NATIVE_CALL callfunc_end(AMX *amx, cell *params)
 		amx_Push(pAmx, gparams[i]);
 	}
 
-	err = amx_Exec(pAmx, &retVal, func);
+	err = amx_ExecPerf(pAmx, &retVal, func);
 
 	if (err != AMX_ERR_NONE)
 	{

amxmodx/amxmodx.h

@@ -196,7 +196,9 @@ extern bool g_official_mod;
 extern bool g_dontprecache;
 extern int g_srvindex;
 extern cvar_t* amxmodx_version;
+extern cvar_t* amxmodx_debug;
 extern cvar_t* amxmodx_language;
+extern cvar_t* amxmodx_perflog;
 extern cvar_t* hostname;
 extern cvar_t* mp_timelimit;
 extern fakecmd_t g_fakecmd;

amxmodx/debugger.cpp

@@ -728,7 +728,7 @@ int Handler::HandleModule(const char *module, bool isClass)
 	m_pAmx->flags |= AMX_FLAG_PRENIT;
 	amx_Push(m_pAmx, isClass ? 1 : 0);
 	amx_PushString(m_pAmx, &hea_addr, &phys_addr, module, 0, 0);
-	int err = amx_Exec(m_pAmx, &retval, m_iModFunc);
+	int err = amx_ExecPerf(m_pAmx, &retval, m_iModFunc);
 	amx_Release(m_pAmx, hea_addr);
 	m_pAmx->flags &= ~AMX_FLAG_PRENIT;
 
@@ -768,7 +768,7 @@ int Handler::HandleNative(const char *native, int index, int trap)
 	amx_Push(m_pAmx, trap);
 	amx_Push(m_pAmx, index);
 	amx_PushString(m_pAmx, &hea_addr, &phys_addr, native, 0, 0);
-	int err = amx_Exec(m_pAmx, &retval, m_iNatFunc);
+	int err = amx_ExecPerf(m_pAmx, &retval, m_iNatFunc);
 	if (err != AMX_ERR_NONE)
 	{
 		//LogError() took care of something for us.
@@ -841,7 +841,7 @@ int Handler::HandleError(const char *msg)
 	amx_PushString(m_pAmx, &hea_addr, &phys_addr, msg, 0, 0);
 	amx_Push(m_pAmx, pDebugger ? 1 : 0);
 	amx_Push(m_pAmx, error);
-	int err = amx_Exec(m_pAmx, &result, m_iErrFunc);
+	int err = amx_ExecPerf(m_pAmx, &result, m_iErrFunc);
 	if (err != AMX_ERR_NONE)
 	{
 		//handle this manually.

amxmodx/meta_api.cpp

@@ -135,9 +135,14 @@ cvar_t init_amxmodx_debug = {"amx_debug", "1", FCVAR_SPONLY};
 cvar_t init_amxmodx_mldebug = {"amx_mldebug", "", FCVAR_SPONLY};
 cvar_t init_amxmodx_language = {"amx_language", "en", FCVAR_SERVER};
 cvar_t init_amxmodx_cl_langs = {"amx_client_languages", "1", FCVAR_SERVER};
+cvar_t init_amxmodx_perflog = { "amx_perflog_ms", "1.0", FCVAR_SPONLY };
+
 cvar_t* amxmodx_version = NULL;
 cvar_t* amxmodx_modules = NULL;
+cvar_t* amxmodx_debug = NULL;
 cvar_t* amxmodx_language = NULL;
+cvar_t* amxmodx_perflog = NULL;
+
 cvar_t* hostname = NULL;
 cvar_t* mp_timelimit = NULL;
 
@@ -1627,9 +1632,12 @@ C_DLLEXPORT	int	Meta_Attach(PLUG_LOADTIME now, META_FUNCTIONS *pFunctionTable, m
 	CVAR_REGISTER(&init_amxmodx_mldebug);
 	CVAR_REGISTER(&init_amxmodx_language);
 	CVAR_REGISTER(&init_amxmodx_cl_langs);
+	CVAR_REGISTER(&init_amxmodx_perflog);
 
 	amxmodx_version = CVAR_GET_POINTER(init_amxmodx_version.name);
+	amxmodx_debug = CVAR_GET_POINTER(init_amxmodx_debug.name);
 	amxmodx_language = CVAR_GET_POINTER(init_amxmodx_language.name);
+	amxmodx_perflog = CVAR_GET_POINTER(init_amxmodx_perflog.name);
 
 	REG_SVR_COMMAND("amxx", amx_command);
 

amxmodx/modules.cpp

@@ -187,7 +187,7 @@ int load_amxscript_internal(AMX *amx, void **program, const char *filename, char
 	bool will_be_debugged = false;
 	tagAMX_DBG *pDbg = NULL;
 
-	if ((int)CVAR_GET_FLOAT("amx_debug") >= 2 || debug)
+	if ((int)amxmodx_debug->value == 2 || debug)
 	{
 		if ((hdr->file_version < CUR_FILE_VERSION))
 		{
@@ -544,7 +544,7 @@ int set_amxnatives(AMX* amx, char error[128])
 
 	if (amx_FindPublic(amx, "plugin_natives", &idx) == AMX_ERR_NONE)
 	{
-		if ((err = amx_Exec(amx, &retval, idx)) != AMX_ERR_NONE)
+		if ((err = amx_ExecPerf(amx, &retval, idx)) != AMX_ERR_NONE)
 		{
 			Debugger::GenericMessage(amx, err);
 			AMXXLOG_Log("An error occurred in plugin_natives. This is dangerous!");

amxmodx/natives.cpp

@@ -112,8 +112,7 @@ int amxx_DynaCallback(int idx, AMX *amx, cell *params)
 		pDebugger->BeginExec();
 	}
 
-	err=amx_Exec(pNative->amx, &ret, pNative->func);
-
+	err = amx_ExecPerf(pNative->amx, &ret, pNative->func);
 	if (err != AMX_ERR_NONE)
 	{
 		if (pDebugger && pDebugger->ErrorExists())

configs/amxx.cfg

@@ -181,3 +181,13 @@ amx_debug 1
 //
 // Default value: ""
 amx_mldebug ""
+
+// Performance monitor 
+//
+// If function executed more than amx_perflog_ms milliseconds
+// print plugin and function name to current amxmodx log file.
+//
+// Time in milliseconds
+// Default value: 1.0
+// 
+amx_perflog_ms 1.0

configs/cstrike/amxx.cfg

@@ -221,3 +221,12 @@ amx_statsx_freeze -2.0
 // Default value: 0
 amx_restrmapsettings 0
 
+// Performance monitor 
+//
+// If function executed more than amx_perflog_ms milliseconds
+// print plugin and function name to current amxmodx log file.
+//
+// Time in milliseconds
+// Default value: 1.0
+// 
+amx_perflog_ms 1.0

configs/ns/amxx.cfg

@@ -218,3 +218,14 @@ amx_idle_ignore_immunity 1
 //
 // Default value: 4
 amx_unstuck_frequency 4
+
+
+// Performance monitor 
+//
+// If function executed more than amx_perflog_ms milliseconds
+// print plugin and function name to current amxmodx log file.
+//
+// Time in milliseconds
+// Default value: 1.0
+// 
+amx_perflog_ms 1.0