Log how many scripts are candidates for starting and how many are actually started.

Adds DebugLevel infrastructure to XEngine though currently commented out and unused.

5 files changed, 166 insertions, 66 deletions

diff --git a/OpenSim/Region/Framework/Interfaces/IEntityInventory.cs b/OpenSim/Region/Framework/Interfaces/IEntityInventory.cs
index 4370fcc..1c9bdce 100644
--- a/OpenSim/Region/Framework/Interfaces/IEntityInventory.cs
+++ b/OpenSim/Region/Framework/Interfaces/IEntityInventory.cs
@@ -81,7 +81,12 @@ namespace OpenSim.Region.Framework.Interfaces
         /// <summary>
         /// Start all the scripts contained in this entity's inventory
         /// </summary>
-        void CreateScriptInstances(int startParam, bool postOnRez, string engine, int stateSource);
+        /// <param name="startParam"></param>
+        /// <param name="postOnRez"></param>
+        /// <param name="engine"></param>
+        /// <param name="stateSource"></param>
+        /// <returns>Number of scripts started.</returns>
+        int CreateScriptInstances(int startParam, bool postOnRez, string engine, int stateSource);
         
         ArrayList GetScriptErrors(UUID itemID);
         void ResumeScripts();
@@ -102,7 +107,11 @@ namespace OpenSim.Region.Framework.Interfaces
         /// <param name="postOnRez"></param>
         /// <param name="engine"></param>
         /// <param name="stateSource"></param>
-        void CreateScriptInstance(
+        /// <returns>
+        /// true if the script instance was valid for starting, false otherwise.  This does not guarantee
+        /// that the script was actually started, just that the script was valid (i.e. its asset data could be found, etc.)
+        /// </returns>
+        bool CreateScriptInstance(
             TaskInventoryItem item, int startParam, bool postOnRez, string engine, int stateSource);
 
         /// <summary>
@@ -113,7 +122,11 @@ namespace OpenSim.Region.Framework.Interfaces
         /// <param name="postOnRez"></param>
         /// <param name="engine"></param>
         /// <param name="stateSource"></param>
-        void CreateScriptInstance(UUID itemId, int startParam, bool postOnRez, string engine, int stateSource);
+        /// <returns>
+        /// true if the script instance was valid for starting, false otherwise.  This does not guarantee
+        /// that the script was actually started, just that the script was valid (i.e. its asset data could be found, etc.)
+        /// </returns>
+        bool CreateScriptInstance(UUID itemId, int startParam, bool postOnRez, string engine, int stateSource);
 
         /// <summary>
         /// Stop a script which is in this prim's inventory.
diff --git a/OpenSim/Region/Framework/Scenes/Scene.Inventory.cs b/OpenSim/Region/Framework/Scenes/Scene.Inventory.cs
index b59fd05..e413281 100644
--- a/OpenSim/Region/Framework/Scenes/Scene.Inventory.cs
+++ b/OpenSim/Region/Framework/Scenes/Scene.Inventory.cs
@@ -60,19 +60,32 @@ namespace OpenSim.Region.Framework.Scenes
         /// <summary>
         /// Creates all the scripts in the scene which should be started.
         /// </summary>
-        public void CreateScriptInstances()
+        /// <returns>
+        /// Number of scripts that were valid for starting.  This does not guarantee that all these scripts
+        /// were actually started, but just that the start could be attempt (e.g. the asset data for the script could be found)
+        /// </returns>
+        public int CreateScriptInstances()
         {
-            m_log.Info("[PRIM INVENTORY]: Creating scripts in scene");
+            m_log.InfoFormat("[SCENE]: Initializing script instances in {0}", RegionInfo.RegionName);
+
+            int scriptsValidForStarting = 0;
 
             EntityBase[] entities = Entities.GetEntities();
             foreach (EntityBase group in entities)
             {
                 if (group is SceneObjectGroup)
                 {
-                    ((SceneObjectGroup) group).CreateScriptInstances(0, false, DefaultScriptEngine, 0);
+                    scriptsValidForStarting
+                        += ((SceneObjectGroup) group).CreateScriptInstances(0, false, DefaultScriptEngine, 0);
                     ((SceneObjectGroup) group).ResumeScripts();
                 }
             }
+
+            m_log.InfoFormat(
+                "[SCENE]: Initialized {0} script instances in {1}",
+                scriptsValidForStarting, RegionInfo.RegionName);
+
+            return scriptsValidForStarting;
         }
 
         /// <summary>
@@ -80,7 +93,7 @@ namespace OpenSim.Region.Framework.Scenes
         /// </summary>
         public void StartScripts()
         {
-            m_log.Info("[PRIM INVENTORY]: Starting scripts in scene");
+            m_log.InfoFormat("[SCENE]: Starting scripts in {0}, please wait.", RegionInfo.RegionName);
 
             IScriptModule[] engines = RequestModuleInterfaces<IScriptModule>();
 
diff --git a/OpenSim/Region/Framework/Scenes/SceneObjectGroup.Inventory.cs b/OpenSim/Region/Framework/Scenes/SceneObjectGroup.Inventory.cs
index 10012d0..2866b54 100644
--- a/OpenSim/Region/Framework/Scenes/SceneObjectGroup.Inventory.cs
+++ b/OpenSim/Region/Framework/Scenes/SceneObjectGroup.Inventory.cs
@@ -54,16 +54,28 @@ namespace OpenSim.Region.Framework.Scenes
         /// <summary>
         /// Start the scripts contained in all the prims in this group.
         /// </summary>
-        public void CreateScriptInstances(int startParam, bool postOnRez,
-                string engine, int stateSource)
+        /// <param name="startParam"></param>
+        /// <param name="postOnRez"></param>
+        /// <param name="engine"></param>
+        /// <param name="stateSource"></param>
+        /// <returns>
+        /// Number of scripts that were valid for starting.  This does not guarantee that all these scripts
+        /// were actually started, but just that the start could be attempt (e.g. the asset data for the script could be found)
+        /// </returns>
+        public int CreateScriptInstances(int startParam, bool postOnRez, string engine, int stateSource)
         {
+            int scriptsStarted = 0;
+
             // Don't start scripts if they're turned off in the region!
             if (!m_scene.RegionInfo.RegionSettings.DisableScripts)
             {
                 SceneObjectPart[] parts = m_parts.GetArray();
                 for (int i = 0; i < parts.Length; i++)
-                    parts[i].Inventory.CreateScriptInstances(startParam, postOnRez, engine, stateSource);
+                    scriptsStarted
+                        += parts[i].Inventory.CreateScriptInstances(startParam, postOnRez, engine, stateSource);
             }
+
+            return scriptsStarted;
         }
 
         /// <summary>
diff --git a/OpenSim/Region/Framework/Scenes/SceneObjectPartInventory.cs b/OpenSim/Region/Framework/Scenes/SceneObjectPartInventory.cs
index 8810903..c223474 100644
--- a/OpenSim/Region/Framework/Scenes/SceneObjectPartInventory.cs
+++ b/OpenSim/Region/Framework/Scenes/SceneObjectPartInventory.cs
@@ -217,14 +217,16 @@ namespace OpenSim.Region.Framework.Scenes
             }
         }
 
-        /// <summary>
-        /// Start all the scripts contained in this prim's inventory
-        /// </summary>
-        public void CreateScriptInstances(int startParam, bool postOnRez, string engine, int stateSource)
+        public int CreateScriptInstances(int startParam, bool postOnRez, string engine, int stateSource)
         {
+            int scriptsValidForStarting = 0;
+
             List<TaskInventoryItem> scripts = GetInventoryItems(InventoryType.LSL);
             foreach (TaskInventoryItem item in scripts)
-                CreateScriptInstance(item, startParam, postOnRez, engine, stateSource);
+                if (CreateScriptInstance(item, startParam, postOnRez, engine, stateSource))
+                    scriptsValidForStarting++;
+
+            return scriptsValidForStarting;
         }
 
         public ArrayList GetScriptErrors(UUID itemID)
@@ -264,61 +266,65 @@ namespace OpenSim.Region.Framework.Scenes
         /// Start a script which is in this prim's inventory.
         /// </summary>
         /// <param name="item"></param>
-        /// <returns></returns>
-        public void CreateScriptInstance(TaskInventoryItem item, int startParam, bool postOnRez, string engine, int stateSource)
+        /// <returns>true if the script instance was created, false otherwise</returns>
+        public bool CreateScriptInstance(TaskInventoryItem item, int startParam, bool postOnRez, string engine, int stateSource)
         {
 //             m_log.DebugFormat("[PRIM INVENTORY]: Starting script {0} {1} in prim {2} {3} in {4}",
 //                 item.Name, item.ItemID, m_part.Name, m_part.UUID, m_part.ParentGroup.Scene.RegionInfo.RegionName);
 
             if (!m_part.ParentGroup.Scene.Permissions.CanRunScript(item.ItemID, m_part.UUID, item.OwnerID))
-                return;
+                return false;
 
             m_part.AddFlag(PrimFlags.Scripted);
 
-            if (!m_part.ParentGroup.Scene.RegionInfo.RegionSettings.DisableScripts)
+            if (m_part.ParentGroup.Scene.RegionInfo.RegionSettings.DisableScripts)
+                return false;
+
+            if (stateSource == 2 && // Prim crossing
+                    m_part.ParentGroup.Scene.m_trustBinaries)
             {
-                if (stateSource == 2 && // Prim crossing
-                        m_part.ParentGroup.Scene.m_trustBinaries)
+                lock (m_items)
                 {
-                    lock (m_items)
-                    {
-                        m_items[item.ItemID].PermsMask = 0;
-                        m_items[item.ItemID].PermsGranter = UUID.Zero;
-                    }
-                    
-                    m_part.ParentGroup.Scene.EventManager.TriggerRezScript(
-                        m_part.LocalId, item.ItemID, String.Empty, startParam, postOnRez, engine, stateSource);
-                    m_part.ParentGroup.AddActiveScriptCount(1);
-                    m_part.ScheduleFullUpdate();
-                    return;
+                    m_items[item.ItemID].PermsMask = 0;
+                    m_items[item.ItemID].PermsGranter = UUID.Zero;
                 }
+                
+                m_part.ParentGroup.Scene.EventManager.TriggerRezScript(
+                    m_part.LocalId, item.ItemID, String.Empty, startParam, postOnRez, engine, stateSource);
+                m_part.ParentGroup.AddActiveScriptCount(1);
+                m_part.ScheduleFullUpdate();
+                return true;
+            }
 
-                AssetBase asset = m_part.ParentGroup.Scene.AssetService.Get(item.AssetID.ToString());
-                if (null == asset)
+            AssetBase asset = m_part.ParentGroup.Scene.AssetService.Get(item.AssetID.ToString());
+            if (null == asset)
+            {
+                m_log.ErrorFormat(
+                    "[PRIM INVENTORY]: Couldn't start script {0}, {1} at {2} in {3} since asset ID {4} could not be found",
+                    item.Name, item.ItemID, m_part.AbsolutePosition, 
+                    m_part.ParentGroup.Scene.RegionInfo.RegionName, item.AssetID);
+
+                return false;
+            }
+            else
+            {
+                if (m_part.ParentGroup.m_savedScriptState != null)
+                    item.OldItemID = RestoreSavedScriptState(item.LoadedItemID, item.OldItemID, item.ItemID);
+
+                lock (m_items)
                 {
-                    m_log.ErrorFormat(
-                        "[PRIM INVENTORY]: Couldn't start script {0}, {1} at {2} in {3} since asset ID {4} could not be found",
-                        item.Name, item.ItemID, m_part.AbsolutePosition, 
-                        m_part.ParentGroup.Scene.RegionInfo.RegionName, item.AssetID);
+                    m_items[item.ItemID].OldItemID = item.OldItemID;
+                    m_items[item.ItemID].PermsMask = 0;
+                    m_items[item.ItemID].PermsGranter = UUID.Zero;
                 }
-                else
-                {
-                    if (m_part.ParentGroup.m_savedScriptState != null)
-                        item.OldItemID = RestoreSavedScriptState(item.LoadedItemID, item.OldItemID, item.ItemID);
 
-                    lock (m_items)
-                    {
-                        m_items[item.ItemID].OldItemID = item.OldItemID;
-                        m_items[item.ItemID].PermsMask = 0;
-                        m_items[item.ItemID].PermsGranter = UUID.Zero;
-                    }
+                string script = Utils.BytesToString(asset.Data);
+                m_part.ParentGroup.Scene.EventManager.TriggerRezScript(
+                    m_part.LocalId, item.ItemID, script, startParam, postOnRez, engine, stateSource);
+                m_part.ParentGroup.AddActiveScriptCount(1);
+                m_part.ScheduleFullUpdate();
 
-                    string script = Utils.BytesToString(asset.Data);
-                    m_part.ParentGroup.Scene.EventManager.TriggerRezScript(
-                        m_part.LocalId, item.ItemID, script, startParam, postOnRez, engine, stateSource);
-                    m_part.ParentGroup.AddActiveScriptCount(1);
-                    m_part.ScheduleFullUpdate();
-                }
+                return true;
             }
         }
 
@@ -384,22 +390,22 @@ namespace OpenSim.Region.Framework.Scenes
             return stateID;
         }
 
-        /// <summary>
-        /// Start a script which is in this prim's inventory.
-        /// </summary>
-        /// <param name="itemId">
-        /// A <see cref="UUID"/>
-        /// </param>
-        public void CreateScriptInstance(UUID itemId, int startParam, bool postOnRez, string engine, int stateSource)
+        public bool CreateScriptInstance(UUID itemId, int startParam, bool postOnRez, string engine, int stateSource)
         {
             TaskInventoryItem item = GetInventoryItem(itemId);
             if (item != null)
-                CreateScriptInstance(item, startParam, postOnRez, engine, stateSource);
+            {
+                return CreateScriptInstance(item, startParam, postOnRez, engine, stateSource);
+            }
             else
+            {
                 m_log.ErrorFormat(
                     "[PRIM INVENTORY]: Couldn't start script with ID {0} since it couldn't be found for prim {1}, {2} at {3} in {4}",
                     itemId, m_part.Name, m_part.UUID, 
                     m_part.AbsolutePosition, m_part.ParentGroup.Scene.RegionInfo.RegionName);
+
+                return false;
+            }
         }
 
         /// <summary>
diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
index aedf2c1..3f623de 100644
--- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
+++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
@@ -62,6 +62,14 @@ namespace OpenSim.Region.ScriptEngine.XEngine
     {
         private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
 
+        /// <summary>
+        /// Control the printing of certain debug messages.
+        /// </summary>
+        /// <remarks>
+        /// If DebugLevel >= 1, then we log every time that a script is started.
+        /// </remarks>
+//        public int DebugLevel { get; set; }
+
         private SmartThreadPool m_ThreadPool;
         private int m_MaxScriptQueue;
         private Scene m_Scene;
@@ -216,9 +224,8 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             AppDomain.CurrentDomain.AssemblyResolve +=
                 OnAssemblyResolve;
 
-            m_log.InfoFormat("[XEngine] Initializing scripts in region {0}",
-                             scene.RegionInfo.RegionName);
             m_Scene = scene;
+            m_log.InfoFormat("[XEngine]: Initializing scripts in region {0}", m_Scene.RegionInfo.RegionName);
 
             m_MinThreads = m_ScriptConfig.GetInt("MinThreads", 2);
             m_MaxThreads = m_ScriptConfig.GetInt("MaxThreads", 100);
@@ -321,9 +328,42 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                 "Starts all stopped scripts."
                     + "If a <script-item-uuid> is given then only that script will be started.  Otherwise, all suitable scripts are started.",
                 (module, cmdparams) => HandleScriptsAction(cmdparams, HandleStartScript));
+
+//            MainConsole.Instance.Commands.AddCommand(
+//                "Debug", false, "debug xengine", "debug xengine [<level>]",
+//                "Turn on detailed xengine debugging.",
+//                  "If level <= 0, then no extra logging is done.\n"
+//                + "If level >= 1, then we log every time that a script is started.",
+//                HandleDebugLevelCommand);
         }
 
         /// <summary>
+        /// Change debug level
+        /// </summary>
+        /// <param name="module"></param>
+        /// <param name="args"></param>
+//        private void HandleDebugLevelCommand(string module, string[] args)
+//        {
+//            if (args.Length == 3)
+//            {
+//                int newDebug;
+//                if (int.TryParse(args[2], out newDebug))
+//                {
+//                    DebugLevel = newDebug;
+//                    MainConsole.Instance.OutputFormat("Debug level set to {0}", newDebug);
+//                }
+//            }
+//            else if (args.Length == 2)
+//            {
+//                MainConsole.Instance.OutputFormat("Current debug level is {0}", DebugLevel);
+//            }
+//            else
+//            {
+//                MainConsole.Instance.Output("Usage: debug xengine 0..1");
+//            }
+//        }
+
+        /// <summary>
         /// Parse the raw item id into a script instance from the command params if it's present.
         /// </summary>
         /// <param name="cmdparams"></param>
@@ -825,8 +865,23 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             }
 
             object[] o;
+
+            int scriptsStarted = 0;
+
             while (m_CompileQueue.Dequeue(out o))
-                DoOnRezScript(o);
+            {
+                if (DoOnRezScript(o))
+                {
+                    scriptsStarted++;
+
+//                    if (scriptsStarted % 50 == 0)
+//                        m_log.DebugFormat(
+//                            "[XEngine]: Started {0} scripts in {1}", scriptsStarted, m_Scene.RegionInfo.RegionName);
+                }
+            }
+
+            m_log.DebugFormat(
+                "[XEngine]: Completed starting {0} scripts on {1}", scriptsStarted, m_Scene.RegionInfo.RegionName);
 
             // NOTE: Despite having a lockless queue, this lock is required
             // to make sure there is never no compile thread while there
@@ -1066,7 +1121,8 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                                                   part.ParentGroup.RootPart.Name,
                                                   item.Name, startParam, postOnRez,
                                                   stateSource, m_MaxScriptQueue);
-                    
+
+//                    if (DebugLevel >= 1)
                     m_log.DebugFormat(
                         "[XEngine] Loaded script {0}.{1}, item UUID {2}, prim UUID {3} @ {4}.{5}",
                         part.ParentGroup.RootPart.Name, item.Name, itemID, part.UUID,