Replace script-lines-per-second with the script execution time scaled by its measurement period and an idealised frame time.

The previous lines-per-second measurement used for top scripts report was inaccurate, since lines executed does not reflect time taken to execute.
Also, every fetch of the report would reset all the numbers limiting its usefulness and we weren't even guaranteed to see the top 100.
The actual measurement value should be script execution time per frame but XEngine does not work this way.
Therefore, we use actual script execution time scaled by the measurement period and an idealised frame time.
This is still not ideal but gives reasonable results and allows scripts to be compared.
This commit moves script execution time calculations from SceneGraph into IScriptModule implementations.

7 files changed, 145 insertions, 70 deletions

diff --git a/OpenSim/Region/CoreModules/World/Estate/EstateManagementModule.cs b/OpenSim/Region/CoreModules/World/Estate/EstateManagementModule.cs
index c303d6d..d363b15 100644
--- a/OpenSim/Region/CoreModules/World/Estate/EstateManagementModule.cs
+++ b/OpenSim/Region/CoreModules/World/Estate/EstateManagementModule.cs
@@ -26,8 +26,10 @@
  */
 
 using System;
+using System.Collections;
 using System.Collections.Generic;
 using System.IO;
+using System.Linq;
 using System.Reflection;
 using System.Security;
 using log4net;
@@ -876,52 +878,67 @@ namespace OpenSim.Region.CoreModules.World.Estate
             if (!Scene.Permissions.CanIssueEstateCommand(remoteClient.AgentId, false))
                 return;
 
-            Dictionary<uint, float> SceneData = new Dictionary<uint,float>();
+            Dictionary<uint, float> sceneData = null;
             List<UUID> uuidNameLookupList = new List<UUID>();
 
             if (reportType == 1)
             {
-                SceneData = Scene.PhysicsScene.GetTopColliders();
+                sceneData = Scene.PhysicsScene.GetTopColliders();
             }
             else if (reportType == 0)
             {
-                SceneData = Scene.SceneGraph.GetTopScripts();
+                IScriptModule scriptModule = Scene.RequestModuleInterface<IScriptModule>();
+
+                if (scriptModule != null)
+                    sceneData = scriptModule.GetObjectScriptsExecutionTimes();
             }
 
             List<LandStatReportItem> SceneReport = new List<LandStatReportItem>();
-            lock (SceneData)
+            if (sceneData != null)
             {
-                foreach (uint obj in SceneData.Keys)
+                var sortedSceneData
+                    = sceneData.Select(
+                        item => new { Measurement = item.Value, Part = Scene.GetSceneObjectPart(item.Key) });
+
+                sortedSceneData.OrderBy(item => item.Measurement);
+
+                int items = 0;
+
+                foreach (var entry in sortedSceneData)
                 {
-                    SceneObjectPart prt = Scene.GetSceneObjectPart(obj);
-                    if (prt != null)
+                    if (entry.Part == null)
+                        continue;
+
+                    items++;
+                    SceneObjectGroup so = entry.Part.ParentGroup;
+
+                    LandStatReportItem lsri = new LandStatReportItem();
+                    lsri.LocationX = so.AbsolutePosition.X;
+                    lsri.LocationY = so.AbsolutePosition.Y;
+                    lsri.LocationZ = so.AbsolutePosition.Z;
+                    lsri.Score = entry.Measurement;
+                    lsri.TaskID = so.UUID;
+                    lsri.TaskLocalID = so.LocalId;
+                    lsri.TaskName = entry.Part.Name;
+                    lsri.OwnerName = "waiting";
+                    lock (uuidNameLookupList)
+                        uuidNameLookupList.Add(so.OwnerID);
+
+                    if (filter.Length != 0)
                     {
-                        SceneObjectGroup sog = prt.ParentGroup;
-                        LandStatReportItem lsri = new LandStatReportItem();
-                        lsri.LocationX = sog.AbsolutePosition.X;
-                        lsri.LocationY = sog.AbsolutePosition.Y;
-                        lsri.LocationZ = sog.AbsolutePosition.Z;
-                        lsri.Score = SceneData[obj];
-                        lsri.TaskID = sog.UUID;
-                        lsri.TaskLocalID = sog.LocalId;
-                        lsri.TaskName = sog.GetPartName(obj);
-                        lsri.OwnerName = "waiting";
-                        lock (uuidNameLookupList)
-                            uuidNameLookupList.Add(sog.OwnerID);
-
-                        if (filter.Length != 0)
+                        if ((lsri.OwnerName.Contains(filter) || lsri.TaskName.Contains(filter)))
                         {
-                            if ((lsri.OwnerName.Contains(filter) || lsri.TaskName.Contains(filter)))
-                            {
-                            }
-                            else
-                            {
-                                continue;
-                            }
                         }
-
-                        SceneReport.Add(lsri);
+                        else
+                        {
+                            continue;
+                        }
                     }
+
+                    SceneReport.Add(lsri);
+
+                    if (items >= 100)
+                        break;
                 }
             }
 
diff --git a/OpenSim/Region/Framework/Interfaces/IScriptModule.cs b/OpenSim/Region/Framework/Interfaces/IScriptModule.cs
index 18c45dd..9fb4a25 100644
--- a/OpenSim/Region/Framework/Interfaces/IScriptModule.cs
+++ b/OpenSim/Region/Framework/Interfaces/IScriptModule.cs
@@ -27,6 +27,7 @@
 
 using System;
 using System.Collections;
+using System.Collections.Generic;
 using OpenMetaverse;
 
 namespace OpenSim.Region.Framework.Interfaces
@@ -74,5 +75,11 @@ namespace OpenSim.Region.Framework.Interfaces
         /// Starts the processing threads.
         /// </summary>
         void StartProcessing();
+
+        /// <summary>
+        /// Get the execution times of all scripts in each object.
+        /// </summary>
+        /// <returns>A dictionary where the key is a local object ID and the value is an execution time in milliseconds.</returns>
+        Dictionary<uint, float> GetObjectScriptsExecutionTimes();
     }
-}
+}
\ No newline at end of file
diff --git a/OpenSim/Region/Framework/Scenes/SceneGraph.cs b/OpenSim/Region/Framework/Scenes/SceneGraph.cs
index bc3400a..5c542d6 100644
--- a/OpenSim/Region/Framework/Scenes/SceneGraph.cs
+++ b/OpenSim/Region/Framework/Scenes/SceneGraph.cs
@@ -733,6 +733,7 @@ namespace OpenSim.Region.Framework.Scenes
         #endregion
 
         #region Get Methods
+        
         /// <summary>
         /// Get the controlling client for the given avatar, if there is one.
         ///
@@ -1074,36 +1075,6 @@ namespace OpenSim.Region.Framework.Scenes
             return Entities.GetEntities();
         }
 
-        public Dictionary<uint, float> GetTopScripts()
-        {
-            Dictionary<uint, float> topScripts = new Dictionary<uint, float>();
-
-            EntityBase[] EntityList = GetEntities();
-            int limit = 0;
-            foreach (EntityBase ent in EntityList)
-            {
-                if (ent is SceneObjectGroup)
-                {
-                    SceneObjectGroup grp = (SceneObjectGroup)ent;
-                    if ((grp.RootPart.GetEffectiveObjectFlags() & (uint)PrimFlags.Scripted) != 0)
-                    {
-                        if (grp.scriptScore >= 0.01)
-                        {
-                            topScripts.Add(grp.LocalId, grp.scriptScore);
-                            limit++;
-                            if (limit >= 100)
-                            {
-                                break;
-                            }
-                        }
-                        grp.scriptScore = 0;
-                    }
-                }
-            }
-
-            return topScripts;
-        }
-
         #endregion
 
         #region Other Methods
diff --git a/OpenSim/Region/Framework/Scenes/SceneObjectGroup.cs b/OpenSim/Region/Framework/Scenes/SceneObjectGroup.cs
index 878476e..afb5ccf 100644
--- a/OpenSim/Region/Framework/Scenes/SceneObjectGroup.cs
+++ b/OpenSim/Region/Framework/Scenes/SceneObjectGroup.cs
@@ -229,8 +229,6 @@ namespace OpenSim.Region.Framework.Scenes
             get { return RootPart.VolumeDetectActive; }
         }
 
-        public float scriptScore;
-
         private Vector3 lastPhysGroupPos;
         private Quaternion lastPhysGroupRot;
 
@@ -1184,12 +1182,7 @@ namespace OpenSim.Region.Framework.Scenes
 
         public void AddScriptLPS(int count)
         {
-            if (scriptScore + count >= float.MaxValue - count)
-                scriptScore = 0;
-
-            scriptScore += (float)count;
-            SceneGraph d = m_scene.SceneGraph;
-            d.AddToScriptLPS(count);
+            m_scene.SceneGraph.AddToScriptLPS(count);
         }
 
         public void AddActiveScriptCount(int count)
diff --git a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
index 8762642..11f54a2 100644
--- a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
+++ b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
@@ -78,6 +78,21 @@ namespace OpenSim.Region.ScriptEngine.Interfaces
         /// </summary>
         string State { get; set; }
 
+        /// <summary>
+        /// Time the script was last started
+        /// </summary>
+        DateTime TimeStarted { get; }
+
+        /// <summary>
+        /// Tick the last measurement period was started.
+        /// </summary>
+        long MeasurementPeriodTickStart { get; }
+
+        /// <summary>
+        /// Ticks spent executing in the last measurement period.
+        /// </summary>
+        long MeasurementPeriodExecutionTime { get; }
+
         IScriptEngine Engine { get; }
         UUID AppDomain { get; set; }
         string PrimName { get; }
diff --git a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
index 968351b..b177287 100644
--- a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
+++ b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
@@ -172,6 +172,14 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
 
         public TaskInventoryItem ScriptTask { get; private set; }
 
+        public DateTime TimeStarted { get; private set; }
+
+        public long MeasurementPeriodTickStart { get; private set; }
+
+        public long MeasurementPeriodExecutionTime { get; private set; }
+
+        public static readonly long MaxMeasurementPeriod = 30 * TimeSpan.TicksPerMinute;
+
         public void ClearQueue()
         {
             m_TimerQueued = false;
@@ -458,6 +466,10 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
 
                 Running = true;
 
+                TimeStarted = DateTime.Now;
+                MeasurementPeriodTickStart = Util.EnvironmentTickCount();
+                MeasurementPeriodExecutionTime = 0;
+
                 if (EventQueue.Count > 0)
                 {
                     if (m_CurrentWorkItem == null)
@@ -710,8 +722,16 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
                             m_EventStart = DateTime.Now;
                             m_InEvent = true;
 
+                            int start = Util.EnvironmentTickCount();
+
+                            // Reset the measurement period when we reach the end of the current one.
+                            if (start - MeasurementPeriodTickStart > MaxMeasurementPeriod)
+                                MeasurementPeriodTickStart = start;
+
                             m_Script.ExecuteEvent(State, data.EventName, data.Params);
 
+                            MeasurementPeriodExecutionTime += Util.EnvironmentTickCount() - start;
+
                             m_InEvent = false;
                             m_CurrentEvent = String.Empty;
 
@@ -720,7 +740,6 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
                                 // This will be the very first event we deliver
                                 // (state_entry) in default state
                                 //
-
                                 SaveState(m_Assembly);
 
                                 m_SaveState = false;
diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
index 105d97d..bddb1b9 100644
--- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
+++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
@@ -1891,6 +1891,59 @@ 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)
+            {
+                foreach (IScriptInstance si in m_Scripts.Values)
+                {
+                    if (!topScripts.ContainsKey(si.LocalID))
+                        topScripts[si.LocalID] = 0;
+
+//                    long ticksElapsed = tickNow - si.MeasurementPeriodTickStart;
+//                    float framesElapsed = ticksElapsed / (18.1818 * TimeSpan.TicksPerMillisecond);
+
+                    // Execution time of the script adjusted by it's measurement period to make scripts started at
+                    // different times comparable.
+//                    float adjustedExecutionTime
+//                        = (float)si.MeasurementPeriodExecutionTime
+//                            / ((float)(tickNow - si.MeasurementPeriodTickStart) / ScriptInstance.MaxMeasurementPeriod)
+//                            / TimeSpan.TicksPerMillisecond;
+
+                    long ticksElapsed = tickNow - si.MeasurementPeriodTickStart;
+
+                    // Avoid divide by zerp
+                    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).
+                    float adjustedExecutionTime
+                        = ((float)si.MeasurementPeriodExecutionTime / ticksElapsed) * 18.1818f;
+
+                    topScripts[si.LocalID] += adjustedExecutionTime;
+                }
+            }
+
+            return topScripts;
+        }
+
         public void SuspendScript(UUID itemID)
         {
 //            m_log.DebugFormat("[XEngine]: Received request to suspend script with ID {0}", itemID);