Report "Script Execution Time" as the time spent executing the script in the last 30 seconds. Use a sliding window to calculate this.

Notes:
- This metric provides a better indication of which scripts are taking up a lot of CPU (and therefore should be optimized).
- Previously the execution time was reset to 0 in every new measurement period, causing the reported time to fluctuate for no reason. This has been fixed by using a sliding window.

4 files changed, 241 insertions, 51 deletions

diff --git a/OpenSim/Framework/MetricsCollector.cs b/OpenSim/Framework/MetricsCollector.cs
new file mode 100644
index 0000000..c8f4a33
--- /dev/null
+++ b/OpenSim/Framework/MetricsCollector.cs
@@ -0,0 +1,223 @@
+using System;
+using System.Diagnostics;
+
+namespace OpenSim.Framework
+{
+    /// <summary>
+    /// A MetricsCollector for 'long' values.
+    /// </summary>
+    public class MetricsCollectorLong : MetricsCollector<long>
+    {
+        public MetricsCollectorLong(int windowSize, int numBuckets)
+            : base(windowSize, numBuckets)
+        {
+        }
+
+        protected override long GetZero() { return 0; }
+
+        protected override long Add(long a, long b) { return a + b; }
+    }
+
+
+    /// <summary>
+    /// A MetricsCollector for time spans.
+    /// </summary>
+    public class MetricsCollectorTime : MetricsCollectorLong
+    {
+        public MetricsCollectorTime(int windowSize, int numBuckets)
+            : base(windowSize, numBuckets)
+        {
+        }
+
+        public void AddSample(Stopwatch timer)
+        {
+            long ticks = timer.ElapsedTicks;
+            if (ticks > 0)
+                AddSample(ticks);
+        }
+
+        public TimeSpan GetSumTime()
+        {
+            return TimeSpan.FromMilliseconds((GetSum() * 1000) / Stopwatch.Frequency);
+        }
+    }
+
+    
+    struct MetricsBucket<T>
+    {
+        public T value;
+        public int count;
+    }
+
+    
+    /// <summary>
+    /// Collects metrics in a sliding window.
+    /// </summary>
+    /// <remarks>
+    /// MetricsCollector provides the current Sum of the metrics that it collects. It can easily be extended
+    /// to provide the Average, too. It uses a sliding window to keep these values current.
+    /// 
+    /// This class is not thread-safe.
+    /// 
+    /// Subclass MetricsCollector to have it use a concrete value type. Override the abstract methods.
+    /// </remarks>
+    public abstract class MetricsCollector<T>
+    {
+        private int bucketSize;     // e.g. 3,000 ms
+
+        private MetricsBucket<T>[] buckets;
+
+        private int NumBuckets { get { return buckets.Length; } }
+
+
+        // The number of the current bucket, if we had an infinite number of buckets and didn't have to wrap around
+        long curBucketGlobal;
+
+        // The total of all the buckets
+        T totalSum;
+        int totalCount;
+
+
+        /// <summary>
+        /// Returns the default (zero) value.
+        /// </summary>
+        /// <returns></returns>
+        protected abstract T GetZero();
+
+        /// <summary>
+        /// Adds two values.
+        /// </summary>
+        protected abstract T Add(T a, T b);
+
+
+        /// <summary>
+        /// Creates a MetricsCollector.
+        /// </summary>
+        /// <param name="windowSize">The period of time over which to collect the metrics, in ms. E.g.: 30,000.</param>
+        /// <param name="numBuckets">The number of buckets to divide the samples into. E.g.: 10. Using more buckets
+        /// smooths the jarring that occurs whenever we drop an old bucket, but uses more memory.</param>
+        public MetricsCollector(int windowSize, int numBuckets)
+        {
+            bucketSize = windowSize / numBuckets;
+            buckets = new MetricsBucket<T>[numBuckets];
+            Reset();
+        }
+
+        public void Reset()
+        {
+            ZeroBuckets(0, NumBuckets);
+            curBucketGlobal = GetNow() / bucketSize;
+            totalSum = GetZero();
+            totalCount = 0;
+        }
+
+        public void AddSample(T sample)
+        {
+            MoveWindow();
+
+            int curBucket = (int)(curBucketGlobal % NumBuckets);
+            buckets[curBucket].value = Add(buckets[curBucket].value, sample);
+            buckets[curBucket].count++;
+
+            totalSum = Add(totalSum, sample);
+            totalCount++;
+        }
+
+        /// <summary>
+        /// Returns the total values in the collection window.
+        /// </summary>
+        public T GetSum()
+        {
+            // It might have been a while since we last added a sample, so we may need to adjust the window
+            MoveWindow();
+
+            return totalSum;
+        }
+
+        /// <summary>
+        /// Returns the current time in ms.
+        /// </summary>
+        private long GetNow()
+        {
+            return DateTime.Now.Ticks / TimeSpan.TicksPerMillisecond;
+        }
+
+        /// <summary>
+        /// Clears the values in buckets [offset, offset+num)
+        /// </summary>
+        private void ZeroBuckets(int offset, int num)
+        {
+            for (int i = 0; i < num; i++)
+            {
+                buckets[offset + i].value = GetZero();
+                buckets[offset + i].count = 0;
+            }
+        }
+
+        /// <summary>
+        /// Adjusts the buckets so that the "current bucket" corresponds to the current time.
+        /// This may require dropping old buckets.
+        /// </summary>
+        /// <remarks>
+        /// This method allows for the possibility that we don't get new samples for each bucket, so the
+        /// new bucket may be some distance away from the last used bucket.
+        /// </remarks>
+        private void MoveWindow()
+        {
+            long newBucketGlobal = GetNow() / bucketSize;
+            long bucketsDistance = newBucketGlobal - curBucketGlobal;
+
+            if (bucketsDistance == 0)
+            {
+                // We're still on the same bucket as before
+                return;
+            }
+
+            if (bucketsDistance >= NumBuckets)
+            {
+                // Discard everything
+                Reset();
+                return;
+            }
+
+            int curBucket = (int)(curBucketGlobal % NumBuckets);
+            int newBucket = (int)(newBucketGlobal % NumBuckets);
+
+
+            // Clear all the buckets in this range: (cur, new]
+            int numToClear = (int)bucketsDistance;
+
+            if (curBucket < NumBuckets - 1)
+            {
+                // Clear buckets at the end of the window
+                int num = Math.Min((int)bucketsDistance, NumBuckets - (curBucket + 1));
+                ZeroBuckets(curBucket + 1, num);
+                numToClear -= num;
+            }
+
+            if (numToClear > 0)
+            {
+                // Clear buckets at the beginning of the window
+                ZeroBuckets(0, numToClear);
+            }
+
+            // Move the "current bucket" pointer
+            curBucketGlobal = newBucketGlobal;
+
+            RecalcTotal();
+        }
+
+        private void RecalcTotal()
+        {
+            totalSum = GetZero();
+            totalCount = 0;
+
+            for (int i = 0; i < NumBuckets; i++)
+            {
+                totalSum = Add(totalSum, buckets[i].value);
+                totalCount += buckets[i].count;
+            }
+        }
+
+    }
+}
diff --git a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
index fa2ceef..f695eba 100644
--- a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
+++ b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
@@ -109,14 +109,9 @@ namespace OpenSim.Region.ScriptEngine.Interfaces
         DateTime TimeStarted { get; }
 
         /// <summary>
-        /// Tick the last measurement period was started.
+        /// Collects information about how long the script was executed.
         /// </summary>
-        long MeasurementPeriodTickStart { get; }
-
-        /// <summary>
-        /// Ticks spent executing in the last measurement period.
-        /// </summary>
-        long MeasurementPeriodExecutionTime { get; }
+        MetricsCollectorTime ExecutionTime { get; }
 
         /// <summary>
         /// Scene part in which this script instance is contained.
diff --git a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
index 05dea5d..d8ad62c 100644
--- a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
+++ b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
@@ -199,11 +199,9 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
 
         public DateTime TimeStarted { get; private set; }
 
-        public long MeasurementPeriodTickStart { get; private set; }
+        public MetricsCollectorTime ExecutionTime { get; private set; }
 
-        public long MeasurementPeriodExecutionTime { get; private set; }
-
-        public static readonly int MaxMeasurementPeriod = 30 * 1000;   // show the *recent* time used by the script, to find currently active scripts
+        private static readonly int MeasurementWindow = 30 * 1000;   // show the *recent* time used by the script, to find currently active scripts
 
         private bool m_coopTermination;
  
@@ -246,6 +244,8 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
 
             m_SaveState = StatePersistedHere;
 
+            ExecutionTime = new MetricsCollectorTime(MeasurementWindow, 10);
+
 //            m_log.DebugFormat(
 //                "[SCRIPT INSTANCE]: Instantiated script instance {0} (id {1}) in part {2} (id {3}) in object {4} attached avatar {5} in {6}",
 //                ScriptTask.Name, ScriptTask.ItemID, Part.Name, Part.UUID, Part.ParentGroup.Name, m_AttachedAvatar, Engine.World.Name);
@@ -505,8 +505,10 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
                 Running = true;
 
                 TimeStarted = DateTime.Now;
-                MeasurementPeriodTickStart = Util.EnvironmentTickCount();
-                MeasurementPeriodExecutionTime = 0;
+
+                // Note: we don't reset ExecutionTime. The reason is that runaway scripts are stopped and restarted
+                // automatically, and we *do* want to show that they had high CPU in that case. If we had reset
+                // ExecutionTime here then runaway scripts, paradoxically, would never show up in the "Top Scripts" dialog.
 
                 if (EventQueue.Count > 0)
                 {
@@ -832,20 +834,13 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
                             m_EventStart = DateTime.Now;
                             m_InEvent = true;
 
-                            // Reset the measurement period when we reach the end of the current one.
-                            if (Util.EnvironmentTickCountSubtract((int)MeasurementPeriodTickStart) > MaxMeasurementPeriod)
-                            {
-                                MeasurementPeriodTickStart = Util.EnvironmentTickCount();
-                                MeasurementPeriodExecutionTime = 0;
-                            }
+                            Stopwatch timer = new Stopwatch();
+                            timer.Start();
 
-                            Stopwatch executionTime = new Stopwatch();
-                            executionTime.Start();
-                            
                             m_Script.ExecuteEvent(State, data.EventName, data.Params);
 
-                            executionTime.Stop();
-                            MeasurementPeriodExecutionTime += executionTime.ElapsedMilliseconds;
+                            timer.Stop();
+                            ExecutionTime.AddSample(timer);
 
                             m_InEvent = false;
                             m_CurrentEvent = String.Empty;
diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
index ae02877..5071884 100755
--- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
+++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
@@ -2343,7 +2343,6 @@ namespace OpenSim.Region.ScriptEngine.XEngine
 
         public Dictionary<uint, float> GetObjectScriptsExecutionTimes()
         {
-            long tickNow = Util.EnvironmentTickCount();
             Dictionary<uint, float> topScripts = new Dictionary<uint, float>();
 
             lock (m_Scripts)
@@ -2353,7 +2352,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                     if (!topScripts.ContainsKey(si.LocalID))
                         topScripts[si.RootLocalID] = 0;
 
-                    topScripts[si.RootLocalID] += CalculateAdjustedExectionTime(si, tickNow);
+                    topScripts[si.RootLocalID] += GetExectionTime(si);
                 }
             }
 
@@ -2367,7 +2366,6 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                 return 0.0f;
             }
             float time = 0.0f;
-            long tickNow = Util.EnvironmentTickCount();
             IScriptInstance si;
             // Calculate the time for all scripts that this engine is executing
             // Ignore any others
@@ -2376,36 +2374,15 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                 si = GetInstance(id);
                 if (si != null && si.Running)
                 {
-                    time += CalculateAdjustedExectionTime(si, tickNow);
+                    time += GetExectionTime(si);
                 }
             }
             return time;
         }
 
-        private float CalculateAdjustedExectionTime(IScriptInstance si, long tickNow)
+        private float GetExectionTime(IScriptInstance si)
         {
-            long ticksElapsed = Util.EnvironmentTickCountSubtract((int)tickNow, (int)si.MeasurementPeriodTickStart);
-
-            // Avoid divide by zero
-            if (ticksElapsed == 0)
-                ticksElapsed = 1;
-
-            // Scale execution time to the ideal 55 fps frame time for these reasons.
-            //
-            // 1) XEngine does not execute scripts per frame, unlike other script engines.  Hence, there is no
-            // 'script execution time per frame', which is the original purpose of this value.
-            //
-            // 2) Giving the raw execution times is misleading since scripts start at different times, making
-            // it impossible to compare scripts.
-            //
-            // 3) Scaling the raw execution time to the time that the script has been running is better but
-            // is still misleading since a script that has just been rezzed may appear to have been running
-            // for much longer.
-            //
-            // 4) Hence, we scale execution time to an idealised frame time (55 fps).  This is also not perfect
-            // since the figure does not represent actual execution time and very hard running scripts will
-            // never exceed 18ms (though this is a very high number for script execution so is a warning sign).
-            return ((float)si.MeasurementPeriodExecutionTime / ticksElapsed) * 18.1818f;
+            return (float)si.ExecutionTime.GetSumTime().TotalMilliseconds;
         }
 
         public void SuspendScript(UUID itemID)