Added timing metric for plugin script execution times

Author: nickgammon

plugins.cpp

@@ -164,6 +164,7 @@ CPlugin::CPlugin (CMUSHclientDoc * pDoc)
   m_bSendToScriptUsed = false;
   m_bGlobal = false;
   m_iLoadOrder = 0;
+  m_iScriptTimeTaken = 0;
 
   } // end of constructor
 

plugins.h

@@ -102,6 +102,7 @@ class CPlugin :public CObject
   bool m_bSendToScriptUsed;     // plugin sends to script
   bool m_bGlobal;               // true if plugin was loaded from global prefs
   long m_iLoadOrder;            // sequence in which plugins are processed
+  LONGLONG m_iScriptTimeTaken;  // time taken to execute scripts
 
   // Lua note - for Lua the DISPID is a flag indicating whether or not
   // the routine exists. It is set to DISPID_UNKNOWN if the last call caused an error

scripting/lua_scripting.cpp

@@ -304,6 +304,8 @@ bool CScriptEngine::ParseLua (const CString & strCode, const CString & strWhat)
     {
     QueryPerformanceCounter (&finish);
     m_pDoc->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
+    if (m_pDoc->m_CurrentPlugin)
+      m_pDoc->m_CurrentPlugin->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
     }
 
   return false;
@@ -611,6 +613,8 @@ bool CScriptEngine::ExecuteLua (DISPID & dispid,  // dispatch ID, will be set to
     {
     QueryPerformanceCounter (&finish);
     m_pDoc->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
+    if (m_pDoc->m_CurrentPlugin)
+      m_pDoc->m_CurrentPlugin->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
     }
 
   if (result)
@@ -702,6 +706,8 @@ bool CScriptEngine::ExecuteLua (DISPID & dispid,          // dispatch ID, will b
     {
     QueryPerformanceCounter (&finish);
     m_pDoc->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
+    if (m_pDoc->m_CurrentPlugin)
+      m_pDoc->m_CurrentPlugin->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
     }
 
   if (lua_gettop (L) > 0 && lua_isstring (L, 1))

scripting/methods/methods_plugins.cpp

@@ -149,6 +149,17 @@ VARIANT CMUSHclientDoc::GetPluginInfo(LPCTSTR PluginID, short InfoType)
     case  22: SetUpVariantDate   (vaResult, COleDateTime (pPlugin->m_tDateInstalled.GetTime ()));  break;
     case  23: SetUpVariantString (vaResult, pPlugin->m_strCallingPluginID); break;
 
+    case  24:
+      {
+      double elapsed_time = 0.0;
+      if (App.m_iCounterFrequency > 0)
+        elapsed_time = ((double) pPlugin->m_iScriptTimeTaken) / 
+                       ((double) App.m_iCounterFrequency);
+
+      SetUpVariantDouble (vaResult, elapsed_time); 
+      break;
+      }
+
     default:
       vaResult.vt = VT_NULL;
       break;

scripting/scriptengine.cpp

@@ -118,6 +118,8 @@ bool CScriptEngine::Execute (DISPID & dispid,  // dispatch ID, will be set to DI
     {
     QueryPerformanceCounter (&finish);
     m_pDoc->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
+    if (m_pDoc->m_CurrentPlugin)
+      m_pDoc->m_CurrentPlugin->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
     }
 
   // put status line back
@@ -462,6 +464,8 @@ SCRIPTSTATE ss;
     {
     QueryPerformanceCounter (&finish);
     m_pDoc->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
+    if (m_pDoc->m_CurrentPlugin)
+      m_pDoc->m_CurrentPlugin->m_iScriptTimeTaken += finish.QuadPart - start.QuadPart;
     }
 
  ::SysFreeString (bstrCode);

world_debug.cpp

@@ -1292,8 +1292,13 @@ VARIANT CMUSHclientDoc::Debug(LPCTSTR Command)
       else
         strLanguage.SetAt (0, toupper (strLanguage [0]));
 
-      ColourTell (strColour, "", TFormat ("', (%s) %s", 
-            (LPCSTR) strLanguage, pActive));
+      double elapsed_time = 0.0;
+      if (App.m_iCounterFrequency > 0)
+        elapsed_time = ((double) pPlugin->m_iScriptTimeTaken) / 
+                       ((double) App.m_iCounterFrequency);
+
+      ColourTell (strColour, "", TFormat ("', (%s, %0.3f s) %s", 
+            (LPCSTR) strLanguage, elapsed_time, pActive));
 
       // no quick way of finding variables count
       int nTotalVariables = 0;