diff options
author | Oren Hurvitz | 2015-07-27 12:34:09 +0300 |
---|---|---|
committer | Oren Hurvitz | 2015-08-11 08:42:31 +0100 |
commit | 5679cd0100feb5e74462ca8cb0dff0550a4f5d65 (patch) | |
tree | 495821fd0069c8ec02f1a45ca677553a4f63347d /OpenSim/Region/ScriptEngine/Shared/Instance | |
parent | Report "Script Execution Time" as the time spent executing the script in the ... (diff) | |
download | opensim-SC_OLD-5679cd0100feb5e74462ca8cb0dff0550a4f5d65.zip opensim-SC_OLD-5679cd0100feb5e74462ca8cb0dff0550a4f5d65.tar.gz opensim-SC_OLD-5679cd0100feb5e74462ca8cb0dff0550a4f5d65.tar.bz2 opensim-SC_OLD-5679cd0100feb5e74462ca8cb0dff0550a4f5d65.tar.xz |
Changed "Script Execution Time" to be the gross time, i.e. including handling it in XEngine
Previously the "Net Time" was reported: only the time actually spent in the script's code. This is not a correct indication of how much load the script places on the simulator, because scripts that change state often or have many events use up a lot of time just in the event handlers, and previously this time wasn't counted.
Diffstat (limited to 'OpenSim/Region/ScriptEngine/Shared/Instance')
-rw-r--r-- | OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs | 340 |
1 files changed, 176 insertions, 164 deletions
diff --git a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs index d8ad62c..24b33f8 100644 --- a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs +++ b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs | |||
@@ -753,208 +753,220 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance | |||
753 | if (Suspended) | 753 | if (Suspended) |
754 | return 0; | 754 | return 0; |
755 | 755 | ||
756 | EventParams data = null; | 756 | Stopwatch timer = new Stopwatch(); |
757 | timer.Start(); | ||
758 | |||
759 | try | ||
760 | { | ||
761 | return EventProcessorInt(); | ||
762 | } | ||
763 | finally | ||
764 | { | ||
765 | timer.Stop(); | ||
766 | ExecutionTime.AddSample(timer); | ||
767 | } | ||
768 | } | ||
769 | } | ||
757 | 770 | ||
758 | lock (EventQueue) | 771 | private object EventProcessorInt() |
772 | { | ||
773 | EventParams data = null; | ||
774 | |||
775 | lock (EventQueue) | ||
776 | { | ||
777 | data = (EventParams)EventQueue.Dequeue(); | ||
778 | if (data == null) // Shouldn't happen | ||
759 | { | 779 | { |
760 | data = (EventParams)EventQueue.Dequeue(); | 780 | if (EventQueue.Count > 0 && Running && !ShuttingDown) |
761 | if (data == null) // Shouldn't happen | ||
762 | { | 781 | { |
763 | if (EventQueue.Count > 0 && Running && !ShuttingDown) | 782 | m_CurrentWorkItem = Engine.QueueEventHandler(this); |
764 | { | ||
765 | m_CurrentWorkItem = Engine.QueueEventHandler(this); | ||
766 | } | ||
767 | else | ||
768 | { | ||
769 | m_CurrentWorkItem = null; | ||
770 | } | ||
771 | return 0; | ||
772 | } | 783 | } |
773 | 784 | else | |
774 | if (data.EventName == "timer") | ||
775 | m_TimerQueued = false; | ||
776 | if (data.EventName == "control") | ||
777 | { | 785 | { |
778 | if (m_ControlEventsInQueue > 0) | 786 | m_CurrentWorkItem = null; |
779 | m_ControlEventsInQueue--; | ||
780 | } | 787 | } |
781 | if (data.EventName == "collision") | 788 | return 0; |
782 | m_CollisionInQueue = false; | 789 | } |
790 | |||
791 | if (data.EventName == "timer") | ||
792 | m_TimerQueued = false; | ||
793 | if (data.EventName == "control") | ||
794 | { | ||
795 | if (m_ControlEventsInQueue > 0) | ||
796 | m_ControlEventsInQueue--; | ||
783 | } | 797 | } |
798 | if (data.EventName == "collision") | ||
799 | m_CollisionInQueue = false; | ||
800 | } | ||
784 | 801 | ||
785 | if (DebugLevel >= 2) | 802 | if (DebugLevel >= 2) |
803 | m_log.DebugFormat( | ||
804 | "[SCRIPT INSTANCE]: Processing event {0} for {1}/{2}({3})/{4}({5}) @ {6}/{7}", | ||
805 | data.EventName, | ||
806 | ScriptName, | ||
807 | Part.Name, | ||
808 | Part.LocalId, | ||
809 | Part.ParentGroup.Name, | ||
810 | Part.ParentGroup.UUID, | ||
811 | Part.AbsolutePosition, | ||
812 | Part.ParentGroup.Scene.Name); | ||
813 | |||
814 | m_DetectParams = data.DetectParams; | ||
815 | |||
816 | if (data.EventName == "state") // Hardcoded state change | ||
817 | { | ||
818 | State = data.Params[0].ToString(); | ||
819 | |||
820 | if (DebugLevel >= 1) | ||
786 | m_log.DebugFormat( | 821 | m_log.DebugFormat( |
787 | "[SCRIPT INSTANCE]: Processing event {0} for {1}/{2}({3})/{4}({5}) @ {6}/{7}", | 822 | "[SCRIPT INSTANCE]: Changing state to {0} for {1}/{2}({3})/{4}({5}) @ {6}/{7}", |
788 | data.EventName, | 823 | State, |
789 | ScriptName, | 824 | ScriptName, |
790 | Part.Name, | 825 | Part.Name, |
791 | Part.LocalId, | 826 | Part.LocalId, |
792 | Part.ParentGroup.Name, | 827 | Part.ParentGroup.Name, |
793 | Part.ParentGroup.UUID, | 828 | Part.ParentGroup.UUID, |
794 | Part.AbsolutePosition, | 829 | Part.AbsolutePosition, |
795 | Part.ParentGroup.Scene.Name); | 830 | Part.ParentGroup.Scene.Name); |
796 | 831 | ||
797 | m_DetectParams = data.DetectParams; | 832 | AsyncCommandManager.StateChange(Engine, |
833 | LocalID, ItemID); | ||
834 | // we are effectively in the new state now, so we can resume queueing | ||
835 | // and processing other non-timer events | ||
836 | m_StateChangeInProgress = false; | ||
798 | 837 | ||
799 | if (data.EventName == "state") // Hardcoded state change | 838 | Part.SetScriptEvents(ItemID, (int)m_Script.GetStateEventFlags(State)); |
839 | } | ||
840 | else | ||
841 | { | ||
842 | if (Engine.World.PipeEventsForScript(LocalID) || | ||
843 | data.EventName == "control") // Don't freeze avies! | ||
800 | { | 844 | { |
801 | State = data.Params[0].ToString(); | 845 | // m_log.DebugFormat("[Script] Delivered event {2} in state {3} to {0}.{1}", |
846 | // PrimName, ScriptName, data.EventName, State); | ||
802 | 847 | ||
803 | if (DebugLevel >= 1) | 848 | try |
804 | m_log.DebugFormat( | ||
805 | "[SCRIPT INSTANCE]: Changing state to {0} for {1}/{2}({3})/{4}({5}) @ {6}/{7}", | ||
806 | State, | ||
807 | ScriptName, | ||
808 | Part.Name, | ||
809 | Part.LocalId, | ||
810 | Part.ParentGroup.Name, | ||
811 | Part.ParentGroup.UUID, | ||
812 | Part.AbsolutePosition, | ||
813 | Part.ParentGroup.Scene.Name); | ||
814 | |||
815 | AsyncCommandManager.StateChange(Engine, | ||
816 | LocalID, ItemID); | ||
817 | // we are effectively in the new state now, so we can resume queueing | ||
818 | // and processing other non-timer events | ||
819 | m_StateChangeInProgress = false; | ||
820 | |||
821 | Part.SetScriptEvents(ItemID, (int)m_Script.GetStateEventFlags(State)); | ||
822 | } | ||
823 | else | ||
824 | { | ||
825 | if (Engine.World.PipeEventsForScript(LocalID) || | ||
826 | data.EventName == "control") // Don't freeze avies! | ||
827 | { | 849 | { |
828 | // m_log.DebugFormat("[Script] Delivered event {2} in state {3} to {0}.{1}", | 850 | m_CurrentEvent = data.EventName; |
829 | // PrimName, ScriptName, data.EventName, State); | 851 | m_EventStart = DateTime.Now; |
852 | m_InEvent = true; | ||
830 | 853 | ||
831 | try | 854 | try |
832 | { | 855 | { |
833 | m_CurrentEvent = data.EventName; | ||
834 | m_EventStart = DateTime.Now; | ||
835 | m_InEvent = true; | ||
836 | |||
837 | Stopwatch timer = new Stopwatch(); | ||
838 | timer.Start(); | ||
839 | |||
840 | m_Script.ExecuteEvent(State, data.EventName, data.Params); | 856 | m_Script.ExecuteEvent(State, data.EventName, data.Params); |
841 | 857 | } | |
842 | timer.Stop(); | 858 | finally |
843 | ExecutionTime.AddSample(timer); | 859 | { |
844 | |||
845 | m_InEvent = false; | 860 | m_InEvent = false; |
846 | m_CurrentEvent = String.Empty; | 861 | m_CurrentEvent = String.Empty; |
862 | } | ||
847 | 863 | ||
848 | if (m_SaveState) | 864 | if (m_SaveState) |
849 | { | 865 | { |
850 | // This will be the very first event we deliver | 866 | // This will be the very first event we deliver |
851 | // (state_entry) in default state | 867 | // (state_entry) in default state |
852 | // | 868 | // |
853 | SaveState(); | 869 | SaveState(); |
854 | 870 | ||
855 | m_SaveState = false; | 871 | m_SaveState = false; |
856 | } | ||
857 | } | 872 | } |
858 | catch (Exception e) | 873 | } |
874 | catch (Exception e) | ||
875 | { | ||
876 | // m_log.DebugFormat( | ||
877 | // "[SCRIPT] Exception in script {0} {1}: {2}{3}", | ||
878 | // ScriptName, ItemID, e.Message, e.StackTrace); | ||
879 | |||
880 | if ((!(e is TargetInvocationException) | ||
881 | || (!(e.InnerException is SelfDeleteException) | ||
882 | && !(e.InnerException is ScriptDeleteException) | ||
883 | && !(e.InnerException is ScriptCoopStopException))) | ||
884 | && !(e is ThreadAbortException)) | ||
859 | { | 885 | { |
860 | // m_log.DebugFormat( | 886 | try |
861 | // "[SCRIPT] Exception in script {0} {1}: {2}{3}", | ||
862 | // ScriptName, ItemID, e.Message, e.StackTrace); | ||
863 | |||
864 | m_InEvent = false; | ||
865 | m_CurrentEvent = String.Empty; | ||
866 | |||
867 | if ((!(e is TargetInvocationException) | ||
868 | || (!(e.InnerException is SelfDeleteException) | ||
869 | && !(e.InnerException is ScriptDeleteException) | ||
870 | && !(e.InnerException is ScriptCoopStopException))) | ||
871 | && !(e is ThreadAbortException)) | ||
872 | { | 887 | { |
873 | try | 888 | // DISPLAY ERROR INWORLD |
874 | { | 889 | string text = FormatException(e); |
875 | // DISPLAY ERROR INWORLD | 890 | |
876 | string text = FormatException(e); | 891 | if (text.Length > 1000) |
877 | 892 | text = text.Substring(0, 1000); | |
878 | if (text.Length > 1000) | 893 | Engine.World.SimChat(Utils.StringToBytes(text), |
879 | text = text.Substring(0, 1000); | 894 | ChatTypeEnum.DebugChannel, 2147483647, |
880 | Engine.World.SimChat(Utils.StringToBytes(text), | 895 | Part.AbsolutePosition, |
881 | ChatTypeEnum.DebugChannel, 2147483647, | 896 | Part.Name, Part.UUID, false); |
882 | Part.AbsolutePosition, | 897 | |
883 | Part.Name, Part.UUID, false); | 898 | |
884 | 899 | m_log.Debug(string.Format( | |
885 | 900 | "[SCRIPT INSTANCE]: Runtime error in script {0} (event {1}), part {2} {3} at {4} in {5} ", | |
886 | m_log.Debug(string.Format( | 901 | ScriptName, |
887 | "[SCRIPT INSTANCE]: Runtime error in script {0} (event {1}), part {2} {3} at {4} in {5} ", | 902 | data.EventName, |
888 | ScriptName, | 903 | PrimName, |
889 | data.EventName, | 904 | Part.UUID, |
890 | PrimName, | 905 | Part.AbsolutePosition, |
891 | Part.UUID, | 906 | Part.ParentGroup.Scene.Name), |
892 | Part.AbsolutePosition, | 907 | e); |
893 | Part.ParentGroup.Scene.Name), | ||
894 | e); | ||
895 | } | ||
896 | catch (Exception) | ||
897 | { | ||
898 | } | ||
899 | // catch (Exception e2) // LEGIT: User Scripting | ||
900 | // { | ||
901 | // m_log.Error("[SCRIPT]: "+ | ||
902 | // "Error displaying error in-world: " + | ||
903 | // e2.ToString()); | ||
904 | // m_log.Error("[SCRIPT]: " + | ||
905 | // "Errormessage: Error compiling script:\r\n" + | ||
906 | // e.ToString()); | ||
907 | // } | ||
908 | } | 908 | } |
909 | else if ((e is TargetInvocationException) && (e.InnerException is SelfDeleteException)) | 909 | catch (Exception) |
910 | { | 910 | { |
911 | m_InSelfDelete = true; | ||
912 | Engine.World.DeleteSceneObject(Part.ParentGroup, false); | ||
913 | } | ||
914 | else if ((e is TargetInvocationException) && (e.InnerException is ScriptDeleteException)) | ||
915 | { | ||
916 | m_InSelfDelete = true; | ||
917 | Part.Inventory.RemoveInventoryItem(ItemID); | ||
918 | } | ||
919 | else if ((e is TargetInvocationException) && (e.InnerException is ScriptCoopStopException)) | ||
920 | { | ||
921 | if (DebugLevel >= 1) | ||
922 | m_log.DebugFormat( | ||
923 | "[SCRIPT INSTANCE]: Script {0}.{1} in event {2}, state {3} stopped co-operatively.", | ||
924 | PrimName, ScriptName, data.EventName, State); | ||
925 | } | 911 | } |
912 | // catch (Exception e2) // LEGIT: User Scripting | ||
913 | // { | ||
914 | // m_log.Error("[SCRIPT]: "+ | ||
915 | // "Error displaying error in-world: " + | ||
916 | // e2.ToString()); | ||
917 | // m_log.Error("[SCRIPT]: " + | ||
918 | // "Errormessage: Error compiling script:\r\n" + | ||
919 | // e.ToString()); | ||
920 | // } | ||
921 | } | ||
922 | else if ((e is TargetInvocationException) && (e.InnerException is SelfDeleteException)) | ||
923 | { | ||
924 | m_InSelfDelete = true; | ||
925 | Engine.World.DeleteSceneObject(Part.ParentGroup, false); | ||
926 | } | ||
927 | else if ((e is TargetInvocationException) && (e.InnerException is ScriptDeleteException)) | ||
928 | { | ||
929 | m_InSelfDelete = true; | ||
930 | Part.Inventory.RemoveInventoryItem(ItemID); | ||
931 | } | ||
932 | else if ((e is TargetInvocationException) && (e.InnerException is ScriptCoopStopException)) | ||
933 | { | ||
934 | if (DebugLevel >= 1) | ||
935 | m_log.DebugFormat( | ||
936 | "[SCRIPT INSTANCE]: Script {0}.{1} in event {2}, state {3} stopped co-operatively.", | ||
937 | PrimName, ScriptName, data.EventName, State); | ||
926 | } | 938 | } |
927 | } | 939 | } |
928 | } | 940 | } |
941 | } | ||
929 | 942 | ||
930 | // If there are more events and we are currently running and not shutting down, then ask the | 943 | // If there are more events and we are currently running and not shutting down, then ask the |
931 | // script engine to run the next event. | 944 | // script engine to run the next event. |
932 | lock (EventQueue) | 945 | lock (EventQueue) |
933 | { | 946 | { |
934 | EventsProcessed++; | 947 | EventsProcessed++; |
935 | 948 | ||
936 | if ((EventsProcessed == 1000) || (EventsProcessed == 10000) || ((EventsProcessed % 100000) == 0)) | 949 | if ((EventsProcessed == 1000) || (EventsProcessed == 10000) || ((EventsProcessed % 100000) == 0)) |
937 | { | 950 | { |
938 | m_log.DebugFormat("[SCRIPT INSTANCE]: Script \"{0}\" (Object \"{1}\" {2} @ {3}.{4}, Item ID {5}, Asset {6}) in event {7}: processed {8:n0} script events", | 951 | m_log.DebugFormat("[SCRIPT INSTANCE]: Script \"{0}\" (Object \"{1}\" {2} @ {3}.{4}, Item ID {5}, Asset {6}) in event {7}: processed {8:n0} script events", |
939 | ScriptTask.Name, | 952 | ScriptTask.Name, |
940 | Part.ParentGroup.Name, Part.ParentGroup.UUID, Part.ParentGroup.AbsolutePosition, Part.ParentGroup.Scene.Name, | 953 | Part.ParentGroup.Name, Part.ParentGroup.UUID, Part.ParentGroup.AbsolutePosition, Part.ParentGroup.Scene.Name, |
941 | ScriptTask.ItemID, ScriptTask.AssetID, data.EventName, EventsProcessed); | 954 | ScriptTask.ItemID, ScriptTask.AssetID, data.EventName, EventsProcessed); |
942 | } | 955 | } |
943 | 956 | ||
944 | if (EventQueue.Count > 0 && Running && !ShuttingDown) | 957 | if (EventQueue.Count > 0 && Running && !ShuttingDown) |
945 | { | 958 | { |
946 | m_CurrentWorkItem = Engine.QueueEventHandler(this); | 959 | m_CurrentWorkItem = Engine.QueueEventHandler(this); |
947 | } | 960 | } |
948 | else | 961 | else |
949 | { | 962 | { |
950 | m_CurrentWorkItem = null; | 963 | m_CurrentWorkItem = null; |
951 | } | ||
952 | } | 964 | } |
965 | } | ||
953 | 966 | ||
954 | m_DetectParams = null; | 967 | m_DetectParams = null; |
955 | 968 | ||
956 | return 0; | 969 | return 0; |
957 | } | ||
958 | } | 970 | } |
959 | 971 | ||
960 | public int EventTime() | 972 | public int EventTime() |