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.0.8.2-post-fixes
Oren Hurvitz
parent
287096d826
commit
a3bed1fbcb
|
|
@ -0,0 +1,223 @@
|
|||
using System;
|
||||
using System.Diagnostics;
|
||||
|
||||
namespace OpenSim.Framework
|
||||
{
|
||||
/// <summary>
|
||||
/// A MetricsCollector for 'long' values.
|
||||
/// </summary>
|
||||
public class MetricsCollectorLong : MetricsCollector<long>
|
||||
{
|
||||
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; }
|
||||
}
|
||||
|
||||
|
||||
/// <summary>
|
||||
/// A MetricsCollector for time spans.
|
||||
/// </summary>
|
||||
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<T>
|
||||
{
|
||||
public T value;
|
||||
public int count;
|
||||
}
|
||||
|
||||
|
||||
/// <summary>
|
||||
/// Collects metrics in a sliding window.
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// 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.
|
||||
/// </remarks>
|
||||
public abstract class MetricsCollector<T>
|
||||
{
|
||||
private int bucketSize; // e.g. 3,000 ms
|
||||
|
||||
private MetricsBucket<T>[] 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;
|
||||
|
||||
|
||||
/// <summary>
|
||||
/// Returns the default (zero) value.
|
||||
/// </summary>
|
||||
/// <returns></returns>
|
||||
protected abstract T GetZero();
|
||||
|
||||
/// <summary>
|
||||
/// Adds two values.
|
||||
/// </summary>
|
||||
protected abstract T Add(T a, T b);
|
||||
|
||||
|
||||
/// <summary>
|
||||
/// Creates a MetricsCollector.
|
||||
/// </summary>
|
||||
/// <param name="windowSize">The period of time over which to collect the metrics, in ms. E.g.: 30,000.</param>
|
||||
/// <param name="numBuckets">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.</param>
|
||||
public MetricsCollector(int windowSize, int numBuckets)
|
||||
{
|
||||
bucketSize = windowSize / numBuckets;
|
||||
buckets = new MetricsBucket<T>[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++;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Returns the total values in the collection window.
|
||||
/// </summary>
|
||||
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;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Returns the current time in ms.
|
||||
/// </summary>
|
||||
private long GetNow()
|
||||
{
|
||||
return DateTime.Now.Ticks / TimeSpan.TicksPerMillisecond;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Clears the values in buckets [offset, offset+num)
|
||||
/// </summary>
|
||||
private void ZeroBuckets(int offset, int num)
|
||||
{
|
||||
for (int i = 0; i < num; i++)
|
||||
{
|
||||
buckets[offset + i].value = GetZero();
|
||||
buckets[offset + i].count = 0;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Adjusts the buckets so that the "current bucket" corresponds to the current time.
|
||||
/// This may require dropping old buckets.
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// 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.
|
||||
/// </remarks>
|
||||
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;
|
||||
}
|
||||
}
|
||||
|
||||
}
|
||||
}
|
||||
|
|
@ -109,14 +109,9 @@ namespace OpenSim.Region.ScriptEngine.Interfaces
|
|||
DateTime TimeStarted { get; }
|
||||
|
||||
/// <summary>
|
||||
/// Tick the last measurement period was started.
|
||||
/// Collects information about how long the script was executed.
|
||||
/// </summary>
|
||||
long MeasurementPeriodTickStart { get; }
|
||||
|
||||
/// <summary>
|
||||
/// Ticks spent executing in the last measurement period.
|
||||
/// </summary>
|
||||
long MeasurementPeriodExecutionTime { get; }
|
||||
MetricsCollectorTime ExecutionTime { get; }
|
||||
|
||||
/// <summary>
|
||||
/// Scene part in which this script instance is contained.
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
|
|
|
|||
|
|
@ -2343,7 +2343,6 @@ namespace OpenSim.Region.ScriptEngine.XEngine
|
|||
|
||||
public Dictionary<uint, float> GetObjectScriptsExecutionTimes()
|
||||
{
|
||||
long tickNow = Util.EnvironmentTickCount();
|
||||
Dictionary<uint, float> topScripts = new Dictionary<uint, float>();
|
||||
|
||||
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)
|
||||
|
|
|
|||
Loading…
Reference in New Issue