From 98b79bc497a9ec59224f09867d4571373aa2caa9 Mon Sep 17 00:00:00 2001
From: Nick Gammon <nick@gammon.com.au>
Date: Tue, 16 Nov 2010 14:05:23 +1100
Subject: [PATCH] Added timing metric for plugin script execution times

---
 plugins.cpp                           |  1 +
 plugins.h                             |  1 +
 scripting/lua_scripting.cpp           |  6 ++++++
 scripting/methods/methods_plugins.cpp | 11 +++++++++++
 scripting/scriptengine.cpp            |  4 ++++
 world_debug.cpp                       |  9 +++++++--
 6 files changed, 30 insertions(+), 2 deletions(-)

diff --git a/plugins.cpp b/plugins.cpp
index a86f6e86..3a0bd6fa 100644
--- a/plugins.cpp
+++ b/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
 
diff --git a/plugins.h b/plugins.h
index fb83b45f..0e2ff8a8 100644
--- a/plugins.h
+++ b/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
diff --git a/scripting/lua_scripting.cpp b/scripting/lua_scripting.cpp
index c7f4a108..f2fe6659 100644
--- a/scripting/lua_scripting.cpp
+++ b/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))
diff --git a/scripting/methods/methods_plugins.cpp b/scripting/methods/methods_plugins.cpp
index 5192513d..7d81f026 100644
--- a/scripting/methods/methods_plugins.cpp
+++ b/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;
diff --git a/scripting/scriptengine.cpp b/scripting/scriptengine.cpp
index 0690c295..d9cb0119 100644
--- a/scripting/scriptengine.cpp
+++ b/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);
diff --git a/world_debug.cpp b/world_debug.cpp
index 735b0b7c..172f996c 100644
--- a/world_debug.cpp
+++ b/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;