From a3bed1fbcbcbe19681aa57733f260ef647a33d8e Mon Sep 17 00:00:00 2001 From: Oren Hurvitz Date: Mon, 27 Jul 2015 12:16:21 +0300 Subject: Report "Script Execution Time" as the time spent executing the script in the last 30 seconds. Use a sliding window to calculate this. Notes: - This metric provides a better indication of which scripts are taking up a lot of CPU (and therefore should be optimized). - Previously the execution time was reset to 0 in every new measurement period, causing the reported time to fluctuate for no reason. This has been fixed by using a sliding window. --- OpenSim/Framework/MetricsCollector.cs | 223 +++++++++++++++++++++ .../ScriptEngine/Interfaces/IScriptInstance.cs | 9 +- .../ScriptEngine/Shared/Instance/ScriptInstance.cs | 29 ++- OpenSim/Region/ScriptEngine/XEngine/XEngine.cs | 31 +-- 4 files changed, 241 insertions(+), 51 deletions(-) create mode 100644 OpenSim/Framework/MetricsCollector.cs diff --git a/OpenSim/Framework/MetricsCollector.cs b/OpenSim/Framework/MetricsCollector.cs new file mode 100644 index 0000000..c8f4a33 --- /dev/null +++ b/OpenSim/Framework/MetricsCollector.cs @@ -0,0 +1,223 @@ +using System; +using System.Diagnostics; + +namespace OpenSim.Framework +{ + /// + /// A MetricsCollector for 'long' values. + /// + public class MetricsCollectorLong : MetricsCollector + { + public MetricsCollectorLong(int windowSize, int numBuckets) + : base(windowSize, numBuckets) + { + } + + protected override long GetZero() { return 0; } + + protected override long Add(long a, long b) { return a + b; } + } + + + /// + /// A MetricsCollector for time spans. + /// + public class MetricsCollectorTime : MetricsCollectorLong + { + public MetricsCollectorTime(int windowSize, int numBuckets) + : base(windowSize, numBuckets) + { + } + + public void AddSample(Stopwatch timer) + { + long ticks = timer.ElapsedTicks; + if (ticks > 0) + AddSample(ticks); + } + + public TimeSpan GetSumTime() + { + return TimeSpan.FromMilliseconds((GetSum() * 1000) / Stopwatch.Frequency); + } + } + + + struct MetricsBucket + { + public T value; + public int count; + } + + + /// + /// Collects metrics in a sliding window. + /// + /// + /// MetricsCollector provides the current Sum of the metrics that it collects. It can easily be extended + /// to provide the Average, too. It uses a sliding window to keep these values current. + /// + /// This class is not thread-safe. + /// + /// Subclass MetricsCollector to have it use a concrete value type. Override the abstract methods. + /// + public abstract class MetricsCollector + { + private int bucketSize; // e.g. 3,000 ms + + private MetricsBucket[] buckets; + + private int NumBuckets { get { return buckets.Length; } } + + + // The number of the current bucket, if we had an infinite number of buckets and didn't have to wrap around + long curBucketGlobal; + + // The total of all the buckets + T totalSum; + int totalCount; + + + /// + /// Returns the default (zero) value. + /// + /// + protected abstract T GetZero(); + + /// + /// Adds two values. + /// + protected abstract T Add(T a, T b); + + + /// + /// Creates a MetricsCollector. + /// + /// The period of time over which to collect the metrics, in ms. E.g.: 30,000. + /// The number of buckets to divide the samples into. E.g.: 10. Using more buckets + /// smooths the jarring that occurs whenever we drop an old bucket, but uses more memory. + public MetricsCollector(int windowSize, int numBuckets) + { + bucketSize = windowSize / numBuckets; + buckets = new MetricsBucket[numBuckets]; + Reset(); + } + + public void Reset() + { + ZeroBuckets(0, NumBuckets); + curBucketGlobal = GetNow() / bucketSize; + totalSum = GetZero(); + totalCount = 0; + } + + public void AddSample(T sample) + { + MoveWindow(); + + int curBucket = (int)(curBucketGlobal % NumBuckets); + buckets[curBucket].value = Add(buckets[curBucket].value, sample); + buckets[curBucket].count++; + + totalSum = Add(totalSum, sample); + totalCount++; + } + + /// + /// Returns the total values in the collection window. + /// + public T GetSum() + { + // It might have been a while since we last added a sample, so we may need to adjust the window + MoveWindow(); + + return totalSum; + } + + /// + /// Returns the current time in ms. + /// + private long GetNow() + { + return DateTime.Now.Ticks / TimeSpan.TicksPerMillisecond; + } + + /// + /// Clears the values in buckets [offset, offset+num) + /// + private void ZeroBuckets(int offset, int num) + { + for (int i = 0; i < num; i++) + { + buckets[offset + i].value = GetZero(); + buckets[offset + i].count = 0; + } + } + + /// + /// Adjusts the buckets so that the "current bucket" corresponds to the current time. + /// This may require dropping old buckets. + /// + /// + /// This method allows for the possibility that we don't get new samples for each bucket, so the + /// new bucket may be some distance away from the last used bucket. + /// + private void MoveWindow() + { + long newBucketGlobal = GetNow() / bucketSize; + long bucketsDistance = newBucketGlobal - curBucketGlobal; + + if (bucketsDistance == 0) + { + // We're still on the same bucket as before + return; + } + + if (bucketsDistance >= NumBuckets) + { + // Discard everything + Reset(); + return; + } + + int curBucket = (int)(curBucketGlobal % NumBuckets); + int newBucket = (int)(newBucketGlobal % NumBuckets); + + + // Clear all the buckets in this range: (cur, new] + int numToClear = (int)bucketsDistance; + + if (curBucket < NumBuckets - 1) + { + // Clear buckets at the end of the window + int num = Math.Min((int)bucketsDistance, NumBuckets - (curBucket + 1)); + ZeroBuckets(curBucket + 1, num); + numToClear -= num; + } + + if (numToClear > 0) + { + // Clear buckets at the beginning of the window + ZeroBuckets(0, numToClear); + } + + // Move the "current bucket" pointer + curBucketGlobal = newBucketGlobal; + + RecalcTotal(); + } + + private void RecalcTotal() + { + totalSum = GetZero(); + totalCount = 0; + + for (int i = 0; i < NumBuckets; i++) + { + totalSum = Add(totalSum, buckets[i].value); + totalCount += buckets[i].count; + } + } + + } +} diff --git a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs index fa2ceef..f695eba 100644 --- a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs +++ b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs @@ -109,14 +109,9 @@ namespace OpenSim.Region.ScriptEngine.Interfaces DateTime TimeStarted { get; } /// - /// Tick the last measurement period was started. + /// Collects information about how long the script was executed. /// - long MeasurementPeriodTickStart { get; } - - /// - /// Ticks spent executing in the last measurement period. - /// - long MeasurementPeriodExecutionTime { get; } + MetricsCollectorTime ExecutionTime { get; } /// /// Scene part in which this script instance is contained. diff --git a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs index 05dea5d..d8ad62c 100644 --- a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs +++ b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs @@ -199,11 +199,9 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance public DateTime TimeStarted { get; private set; } - public long MeasurementPeriodTickStart { get; private set; } + public MetricsCollectorTime ExecutionTime { get; private set; } - public long MeasurementPeriodExecutionTime { get; private set; } - - public static readonly int MaxMeasurementPeriod = 30 * 1000; // show the *recent* time used by the script, to find currently active scripts + private static readonly int MeasurementWindow = 30 * 1000; // show the *recent* time used by the script, to find currently active scripts private bool m_coopTermination; @@ -246,6 +244,8 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance m_SaveState = StatePersistedHere; + ExecutionTime = new MetricsCollectorTime(MeasurementWindow, 10); + // m_log.DebugFormat( // "[SCRIPT INSTANCE]: Instantiated script instance {0} (id {1}) in part {2} (id {3}) in object {4} attached avatar {5} in {6}", // ScriptTask.Name, ScriptTask.ItemID, Part.Name, Part.UUID, Part.ParentGroup.Name, m_AttachedAvatar, Engine.World.Name); @@ -505,8 +505,10 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance Running = true; TimeStarted = DateTime.Now; - MeasurementPeriodTickStart = Util.EnvironmentTickCount(); - MeasurementPeriodExecutionTime = 0; + + // Note: we don't reset ExecutionTime. The reason is that runaway scripts are stopped and restarted + // automatically, and we *do* want to show that they had high CPU in that case. If we had reset + // ExecutionTime here then runaway scripts, paradoxically, would never show up in the "Top Scripts" dialog. if (EventQueue.Count > 0) { @@ -832,20 +834,13 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance m_EventStart = DateTime.Now; m_InEvent = true; - // Reset the measurement period when we reach the end of the current one. - if (Util.EnvironmentTickCountSubtract((int)MeasurementPeriodTickStart) > MaxMeasurementPeriod) - { - MeasurementPeriodTickStart = Util.EnvironmentTickCount(); - MeasurementPeriodExecutionTime = 0; - } + Stopwatch timer = new Stopwatch(); + timer.Start(); - Stopwatch executionTime = new Stopwatch(); - executionTime.Start(); - m_Script.ExecuteEvent(State, data.EventName, data.Params); - executionTime.Stop(); - MeasurementPeriodExecutionTime += executionTime.ElapsedMilliseconds; + timer.Stop(); + ExecutionTime.AddSample(timer); m_InEvent = false; m_CurrentEvent = String.Empty; diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs index ae02877..5071884 100755 --- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs +++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs @@ -2343,7 +2343,6 @@ namespace OpenSim.Region.ScriptEngine.XEngine public Dictionary GetObjectScriptsExecutionTimes() { - long tickNow = Util.EnvironmentTickCount(); Dictionary topScripts = new Dictionary(); lock (m_Scripts) @@ -2353,7 +2352,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine if (!topScripts.ContainsKey(si.LocalID)) topScripts[si.RootLocalID] = 0; - topScripts[si.RootLocalID] += CalculateAdjustedExectionTime(si, tickNow); + topScripts[si.RootLocalID] += GetExectionTime(si); } } @@ -2367,7 +2366,6 @@ namespace OpenSim.Region.ScriptEngine.XEngine return 0.0f; } float time = 0.0f; - long tickNow = Util.EnvironmentTickCount(); IScriptInstance si; // Calculate the time for all scripts that this engine is executing // Ignore any others @@ -2376,36 +2374,15 @@ namespace OpenSim.Region.ScriptEngine.XEngine si = GetInstance(id); if (si != null && si.Running) { - time += CalculateAdjustedExectionTime(si, tickNow); + time += GetExectionTime(si); } } return time; } - private float CalculateAdjustedExectionTime(IScriptInstance si, long tickNow) + private float GetExectionTime(IScriptInstance si) { - long ticksElapsed = Util.EnvironmentTickCountSubtract((int)tickNow, (int)si.MeasurementPeriodTickStart); - - // Avoid divide by zero - 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). - return ((float)si.MeasurementPeriodExecutionTime / ticksElapsed) * 18.1818f; + return (float)si.ExecutionTime.GetSumTime().TotalMilliseconds; } public void SuspendScript(UUID itemID) -- cgit v1.1