From 0fa303b1cf244b3066395413e640318b2122c19f Mon Sep 17 00:00:00 2001 From: Justin Clark-Casey (justincc) Date: Wed, 20 Jun 2012 00:10:19 +0100 Subject: 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. --- .../Framework/Interfaces/IEntityInventory.cs | 19 +++- OpenSim/Region/Framework/Scenes/Scene.Inventory.cs | 21 +++- .../Framework/Scenes/SceneObjectGroup.Inventory.cs | 18 +++- .../Framework/Scenes/SceneObjectPartInventory.cs | 110 +++++++++++---------- OpenSim/Region/ScriptEngine/XEngine/XEngine.cs | 64 +++++++++++- 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 /// /// Start all the scripts contained in this entity's inventory /// - void CreateScriptInstances(int startParam, bool postOnRez, string engine, int stateSource); + /// + /// + /// + /// + /// Number of scripts started. + 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 /// /// /// - void CreateScriptInstance( + /// + /// 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.) + /// + bool CreateScriptInstance( TaskInventoryItem item, int startParam, bool postOnRez, string engine, int stateSource); /// @@ -113,7 +122,11 @@ namespace OpenSim.Region.Framework.Interfaces /// /// /// - void CreateScriptInstance(UUID itemId, int startParam, bool postOnRez, string engine, int stateSource); + /// + /// 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.) + /// + bool CreateScriptInstance(UUID itemId, int startParam, bool postOnRez, string engine, int stateSource); /// /// 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 /// /// Creates all the scripts in the scene which should be started. /// - public void CreateScriptInstances() + /// + /// 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) + /// + 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; } /// @@ -80,7 +93,7 @@ namespace OpenSim.Region.Framework.Scenes /// 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(); 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 /// /// Start the scripts contained in all the prims in this group. /// - public void CreateScriptInstances(int startParam, bool postOnRez, - string engine, int stateSource) + /// + /// + /// + /// + /// + /// 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) + /// + 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; } /// 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 } } - /// - /// Start all the scripts contained in this prim's inventory - /// - 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 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. /// /// - /// - public void CreateScriptInstance(TaskInventoryItem item, int startParam, bool postOnRez, string engine, int stateSource) + /// true if the script instance was created, false otherwise + 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; } - /// - /// Start a script which is in this prim's inventory. - /// - /// - /// A - /// - 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; + } } /// 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); + /// + /// Control the printing of certain debug messages. + /// + /// + /// If DebugLevel >= 1, then we log every time that a script is started. + /// +// 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 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 []", +// "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); } /// + /// Change debug level + /// + /// + /// +// 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"); +// } +// } + + /// /// Parse the raw item id into a script instance from the command params if it's present. /// /// @@ -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, -- cgit v1.1