From 418c0cb01d72a48bb1cd708d25a3e9159e711661 Mon Sep 17 00:00:00 2001 From: Justin Clark-Casey (justincc) Date: Wed, 12 Dec 2012 22:06:09 +0000 Subject: Add asset id to "show script" and "show scripts" command output to make it easier to extract and inspect the script's asset via "dump asset" --- OpenSim/Region/ScriptEngine/XEngine/XEngine.cs | 1 + 1 file changed, 1 insertion(+) (limited to 'OpenSim/Region/ScriptEngine') diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs index 965101a..986f658 100644 --- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs +++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs @@ -542,6 +542,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine sb.AppendFormat("Queued events : {0}\n", instance.EventsQueued); sb.AppendFormat("Processed events : {0}\n", instance.EventsProcessed); sb.AppendFormat("Item UUID : {0}\n", instance.ItemID); + sb.AppendFormat("Asset UUID : {0}\n", instance.AssetID); sb.AppendFormat("Containing part name: {0}\n", instance.PrimName); sb.AppendFormat("Containing part UUID: {0}\n", instance.ObjectID); sb.AppendFormat("Position : {0}\n", sop.AbsolutePosition); -- cgit v1.1 From 047270bdc83d029486215a418fada27b225dbab0 Mon Sep 17 00:00:00 2001 From: Justin Clark-Casey (justincc) Date: Wed, 12 Dec 2012 23:13:34 +0000 Subject: Add "debug script log" command to allow setting a numeric debug level on individual IScriptInstances for debugging purposes. Current, state changes and event fires can be logged for individual scripts. See command help for more details. --- .../ScriptEngine/Interfaces/IScriptInstance.cs | 12 +++++ .../ScriptEngine/Shared/Instance/ScriptInstance.cs | 37 +++++++++++---- OpenSim/Region/ScriptEngine/XEngine/XEngine.cs | 53 ++++++++++++++++++++-- 3 files changed, 89 insertions(+), 13 deletions(-) (limited to 'OpenSim/Region/ScriptEngine') diff --git a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs index 0cef550..00a99c3 100644 --- a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs +++ b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs @@ -59,6 +59,18 @@ namespace OpenSim.Region.ScriptEngine.Interfaces public interface IScriptInstance { /// + /// Debug level for this script instance. + /// + /// + /// Level == 0, no extra data is logged. + /// Level >= 1, state changes are logged. + /// Level >= 2, event firing is logged. + /// + /// The debug level. + /// + int DebugLevel { get; set; } + + /// /// Is the script currently running? /// bool Running { get; set; } diff --git a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs index 5ad6eeb..435e9dc 100644 --- a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs +++ b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs @@ -93,6 +93,8 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance private UUID m_CurrentStateHash; private UUID m_RegionID; + public int DebugLevel { get; set; } + public Dictionary, KeyValuePair> LineMap { get; set; } private Dictionary m_Apis = new Dictionary(); @@ -703,21 +705,42 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance if (data.EventName == "collision") m_CollisionInQueue = false; } - -// m_log.DebugFormat("[XEngine]: Processing event {0} for {1}", data.EventName, this); + + SceneObjectPart part = Engine.World.GetSceneObjectPart(LocalID); + + if (DebugLevel >= 2) + m_log.DebugFormat( + "[SCRIPT INSTANCE]: Processing event {0} for {1}/{2}({3})/{4}({5}) @ {6}/{7}", + data.EventName, + ScriptName, + part.Name, + part.LocalId, + part.ParentGroup.Name, + part.ParentGroup.UUID, + part.AbsolutePosition, + part.ParentGroup.Scene.Name); m_DetectParams = data.DetectParams; if (data.EventName == "state") // Hardcoded state change { - // m_log.DebugFormat("[Script] Script {0}.{1} state set to {2}", - // PrimName, ScriptName, data.Params[0].ToString()); State = data.Params[0].ToString(); + + if (DebugLevel >= 1) + m_log.DebugFormat( + "[SCRIPT INSTANCE]: Changing state to {0} for {1}/{2}({3})/{4}({5}) @ {6}/{7}", + State, + ScriptName, + part.Name, + part.LocalId, + part.ParentGroup.Name, + part.ParentGroup.UUID, + part.AbsolutePosition, + part.ParentGroup.Scene.Name); + AsyncCommandManager.RemoveScript(Engine, LocalID, ItemID); - SceneObjectPart part = Engine.World.GetSceneObjectPart( - LocalID); if (part != null) { part.SetScriptEvents(ItemID, @@ -729,8 +752,6 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance if (Engine.World.PipeEventsForScript(LocalID) || data.EventName == "control") // Don't freeze avies! { - SceneObjectPart part = Engine.World.GetSceneObjectPart( - LocalID); // m_log.DebugFormat("[Script] Delivered event {2} in state {3} to {0}.{1}", // PrimName, ScriptName, data.EventName, State); diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs index 986f658..828f2fb 100644 --- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs +++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs @@ -304,7 +304,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine MainConsole.Instance.Commands.AddCommand( "Scripts", false, "scripts show", "scripts show []", "Show script information", - "Show information on all scripts known to the script engine." + "Show information on all scripts known to the script engine.\n" + "If a is given then only information on that script will be shown.", HandleShowScripts); @@ -323,22 +323,30 @@ namespace OpenSim.Region.ScriptEngine.XEngine MainConsole.Instance.Commands.AddCommand( "Scripts", false, "scripts resume", "scripts resume []", "Resumes all suspended scripts", "Resumes all currently suspended scripts.\n" - + "Resumed scripts will process all events accumulated whilst suspended." + + "Resumed scripts will process all events accumulated whilst suspended.\n" + "If a is given then only that script will be resumed. Otherwise, all suitable scripts are resumed.", (module, cmdparams) => HandleScriptsAction(cmdparams, HandleResumeScript)); MainConsole.Instance.Commands.AddCommand( "Scripts", false, "scripts stop", "scripts stop []", "Stops all running scripts", - "Stops all running scripts." + "Stops all running scripts.\n" + "If a is given then only that script will be stopped. Otherwise, all suitable scripts are stopped.", (module, cmdparams) => HandleScriptsAction(cmdparams, HandleStopScript)); MainConsole.Instance.Commands.AddCommand( "Scripts", false, "scripts start", "scripts start []", "Starts all stopped scripts", - "Starts all stopped scripts." + "Starts all stopped scripts.\n" + "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( + "Scripts", false, "debug script log", "debug scripts log ", "Extra debug logging for a script", + "Activates or deactivates extra debug logging for the given script.\n" + + "Level == 0, deactivate extra debug logging.\n" + + "Level >= 1, log state changes.\n" + + "Level >= 2, log event invocations.\n", + HandleDebugScriptLogCommand); + // MainConsole.Instance.Commands.AddCommand( // "Debug", false, "debug xengine", "debug xengine []", // "Turn on detailed xengine debugging.", @@ -347,6 +355,41 @@ namespace OpenSim.Region.ScriptEngine.XEngine // HandleDebugLevelCommand); } + private void HandleDebugScriptLogCommand(string module, string[] args) + { + if (!(MainConsole.Instance.ConsoleScene == null || MainConsole.Instance.ConsoleScene == m_Scene)) + return; + + if (args.Length != 5) + { + MainConsole.Instance.Output("Usage: debug script log "); + return; + } + + UUID itemId; + + if (!ConsoleUtil.TryParseConsoleUuid(MainConsole.Instance, args[3], out itemId)) + return; + + int newLevel; + + if (!ConsoleUtil.TryParseConsoleInt(MainConsole.Instance, args[4], out newLevel)) + return; + + IScriptInstance si; + + lock (m_Scripts) + { + // XXX: We can't give the user feedback on a bad item id because this may apply to a different script + // engine + if (!m_Scripts.TryGetValue(itemId, out si)) + return; + } + + si.DebugLevel = newLevel; + MainConsole.Instance.OutputFormat("Set debug level of {0} {1} to {2}", si.ScriptName, si.ItemID, newLevel); + } + /// /// Change debug level /// @@ -418,7 +461,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine if (!UUID.TryParse(rawItemId, out itemId)) { - MainConsole.Instance.OutputFormat("Error - {0} is not a valid UUID", rawItemId); + MainConsole.Instance.OutputFormat("ERROR: {0} is not a valid UUID", rawItemId); return; } -- cgit v1.1 From 512e4c931379877a1fd8c35f41111431f0a85ff5 Mon Sep 17 00:00:00 2001 From: Justin Clark-Casey (justincc) Date: Wed, 12 Dec 2012 23:30:26 +0000 Subject: Log situations where workitem event threads are aborted on stop request because they failed to complete event processing within the given timeout. This is for bug hunting purposes where thread aborts may be causing dangling lock issues and subsequent vm crashes on mono (with ReaderWriterLockSlim, etc.) --- OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'OpenSim/Region/ScriptEngine') diff --git a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs index 435e9dc..dfe8386 100644 --- a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs +++ b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs @@ -550,9 +550,9 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance // forcibly abort the work item (this aborts the underlying thread). if (!m_InSelfDelete) { -// m_log.ErrorFormat( -// "[SCRIPT INSTANCE]: Aborting script {0} {1} in prim {2} {3} {4} {5}", -// ScriptName, ItemID, PrimName, ObjectID, m_InSelfDelete, DateTime.Now.Ticks); + m_log.DebugFormat( + "[SCRIPT INSTANCE]: Aborting unstopped script {0} {1} in prim {2}, localID {3}, timeout was {4} ms", + ScriptName, ItemID, PrimName, LocalID, timeout); workItem.Abort(); } -- cgit v1.1 From 523213060b315c677bf3142b5d2925460a49c9ed Mon Sep 17 00:00:00 2001 From: Justin Clark-Casey (justincc) Date: Thu, 13 Dec 2012 21:02:55 +0000 Subject: Add WaitForEventCompletionOnScriptStop [XEngine] config param to OpenSimDefaults.ini to allow change of the wait time for an event to complete on script removal before aborting its thread Default is 1000, as has previously been the case. This parameter exists for further debug work concerning mono 2.10 crashes that may be related to locks not being removed on Thread.Abort --- OpenSim/Region/ScriptEngine/XEngine/XEngine.cs | 34 ++++++++++++++++++-------- 1 file changed, 24 insertions(+), 10 deletions(-) (limited to 'OpenSim/Region/ScriptEngine') diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs index 828f2fb..1dd50c7 100644 --- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs +++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs @@ -107,6 +107,24 @@ namespace OpenSim.Region.ScriptEngine.XEngine private IXmlRpcRouter m_XmlRpcRouter; private int m_EventLimit; private bool m_KillTimedOutScripts; + + /// + /// Number of milliseconds we will wait for a script event to complete on script stop before we forcibly abort + /// its thread. + /// + /// + /// It appears that if a script thread is aborted whilst it is holding ReaderWriterLockSlim (possibly the write + /// lock) then the lock is not properly released. This causes mono 2.6, 2.10 and possibly + /// later to crash, sometimes with symptoms such as a leap to 100% script usage and a vm thead dump showing + /// all threads waiting on release of ReaderWriterLockSlim write thread which none of the threads listed + /// actually hold. + /// + /// Pausing for event completion reduces the risk of this happening. However, it may be that aborting threads + /// is not a mono issue per se but rather a risky activity in itself in an AppDomain that is not immediately + /// shutting down. + /// + private int m_WaitForEventCompletionOnScriptStop = 1000; + private string m_ScriptEnginesPath = null; private ExpiringCache m_runFlags = new ExpiringCache(); @@ -249,6 +267,9 @@ namespace OpenSim.Region.ScriptEngine.XEngine m_EventLimit = m_ScriptConfig.GetInt("EventLimit", 30); m_KillTimedOutScripts = m_ScriptConfig.GetBoolean("KillTimedOutScripts", false); m_SaveTime = m_ScriptConfig.GetInt("SaveInterval", 120) * 1000; + m_WaitForEventCompletionOnScriptStop + = m_ScriptConfig.GetInt("WaitForEventCompletionOnScriptStop", m_WaitForEventCompletionOnScriptStop); + m_ScriptEnginesPath = m_ScriptConfig.GetString("ScriptEnginesPath", "ScriptEngines"); m_Prio = ThreadPriority.BelowNormal; @@ -1335,9 +1356,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine instance.ClearQueue(); - // Give the script some time to finish processing its last event. Simply aborting the script thread can - // cause issues on mono 2.6, 2.10 and possibly later where locks are not released properly on abort. - instance.Stop(1000); + instance.Stop(m_WaitForEventCompletionOnScriptStop); // bool objectRemoved = false; @@ -1687,16 +1706,11 @@ namespace OpenSim.Region.ScriptEngine.XEngine public void StopScript(UUID itemID) { IScriptInstance instance = GetInstance(itemID); + if (instance != null) - { - // Give the script some time to finish processing its last event. Simply aborting the script thread can - // cause issues on mono 2.6, 2.10 and possibly later where locks are not released properly on abort. - instance.Stop(1000); - } + instance.Stop(m_WaitForEventCompletionOnScriptStop); else - { m_runFlags.AddOrUpdate(itemID, false, 240); - } } public DetectParams GetDetectParams(UUID itemID, int idx) -- cgit v1.1