diff options
author | Oren Hurvitz | 2015-07-27 12:16:21 +0300 |
---|---|---|
committer | Oren Hurvitz | 2015-08-11 08:42:26 +0100 |
commit | a3bed1fbcbcbe19681aa57733f260ef647a33d8e (patch) | |
tree | 2092c169cd80ed3db70f1b03d88406f48dc20f44 /OpenSim | |
parent | Improved calculation of Script Execution TimeStarted (diff) | |
download | opensim-SC_OLD-a3bed1fbcbcbe19681aa57733f260ef647a33d8e.zip opensim-SC_OLD-a3bed1fbcbcbe19681aa57733f260ef647a33d8e.tar.gz opensim-SC_OLD-a3bed1fbcbcbe19681aa57733f260ef647a33d8e.tar.bz2 opensim-SC_OLD-a3bed1fbcbcbe19681aa57733f260ef647a33d8e.tar.xz |
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.
Diffstat (limited to 'OpenSim')
-rw-r--r-- | OpenSim/Framework/MetricsCollector.cs | 223 | ||||
-rw-r--r-- | OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs | 9 | ||||
-rw-r--r-- | OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs | 29 | ||||
-rwxr-xr-x | OpenSim/Region/ScriptEngine/XEngine/XEngine.cs | 31 |
4 files changed, 241 insertions, 51 deletions
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 @@ | |||
1 | using System; | ||
2 | using System.Diagnostics; | ||
3 | |||
4 | namespace OpenSim.Framework | ||
5 | { | ||
6 | /// <summary> | ||
7 | /// A MetricsCollector for 'long' values. | ||
8 | /// </summary> | ||
9 | public class MetricsCollectorLong : MetricsCollector<long> | ||
10 | { | ||
11 | public MetricsCollectorLong(int windowSize, int numBuckets) | ||
12 | : base(windowSize, numBuckets) | ||
13 | { | ||
14 | } | ||
15 | |||
16 | protected override long GetZero() { return 0; } | ||
17 | |||
18 | protected override long Add(long a, long b) { return a + b; } | ||
19 | } | ||
20 | |||
21 | |||
22 | /// <summary> | ||
23 | /// A MetricsCollector for time spans. | ||
24 | /// </summary> | ||
25 | public class MetricsCollectorTime : MetricsCollectorLong | ||
26 | { | ||
27 | public MetricsCollectorTime(int windowSize, int numBuckets) | ||
28 | : base(windowSize, numBuckets) | ||
29 | { | ||
30 | } | ||
31 | |||
32 | public void AddSample(Stopwatch timer) | ||
33 | { | ||
34 | long ticks = timer.ElapsedTicks; | ||
35 | if (ticks > 0) | ||
36 | AddSample(ticks); | ||
37 | } | ||
38 | |||
39 | public TimeSpan GetSumTime() | ||
40 | { | ||
41 | return TimeSpan.FromMilliseconds((GetSum() * 1000) / Stopwatch.Frequency); | ||
42 | } | ||
43 | } | ||
44 | |||
45 | |||
46 | struct MetricsBucket<T> | ||
47 | { | ||
48 | public T value; | ||
49 | public int count; | ||
50 | } | ||
51 | |||
52 | |||
53 | /// <summary> | ||
54 | /// Collects metrics in a sliding window. | ||
55 | /// </summary> | ||
56 | /// <remarks> | ||
57 | /// MetricsCollector provides the current Sum of the metrics that it collects. It can easily be extended | ||
58 | /// to provide the Average, too. It uses a sliding window to keep these values current. | ||
59 | /// | ||
60 | /// This class is not thread-safe. | ||
61 | /// | ||
62 | /// Subclass MetricsCollector to have it use a concrete value type. Override the abstract methods. | ||
63 | /// </remarks> | ||
64 | public abstract class MetricsCollector<T> | ||
65 | { | ||
66 | private int bucketSize; // e.g. 3,000 ms | ||
67 | |||
68 | private MetricsBucket<T>[] buckets; | ||
69 | |||
70 | private int NumBuckets { get { return buckets.Length; } } | ||
71 | |||
72 | |||
73 | // The number of the current bucket, if we had an infinite number of buckets and didn't have to wrap around | ||
74 | long curBucketGlobal; | ||
75 | |||
76 | // The total of all the buckets | ||
77 | T totalSum; | ||
78 | int totalCount; | ||
79 | |||
80 | |||
81 | /// <summary> | ||
82 | /// Returns the default (zero) value. | ||
83 | /// </summary> | ||
84 | /// <returns></returns> | ||
85 | protected abstract T GetZero(); | ||
86 | |||
87 | /// <summary> | ||
88 | /// Adds two values. | ||
89 | /// </summary> | ||
90 | protected abstract T Add(T a, T b); | ||
91 | |||
92 | |||
93 | /// <summary> | ||
94 | /// Creates a MetricsCollector. | ||
95 | /// </summary> | ||
96 | /// <param name="windowSize">The period of time over which to collect the metrics, in ms. E.g.: 30,000.</param> | ||
97 | /// <param name="numBuckets">The number of buckets to divide the samples into. E.g.: 10. Using more buckets | ||
98 | /// smooths the jarring that occurs whenever we drop an old bucket, but uses more memory.</param> | ||
99 | public MetricsCollector(int windowSize, int numBuckets) | ||
100 | { | ||
101 | bucketSize = windowSize / numBuckets; | ||
102 | buckets = new MetricsBucket<T>[numBuckets]; | ||
103 | Reset(); | ||
104 | } | ||
105 | |||
106 | public void Reset() | ||
107 | { | ||
108 | ZeroBuckets(0, NumBuckets); | ||
109 | curBucketGlobal = GetNow() / bucketSize; | ||
110 | totalSum = GetZero(); | ||
111 | totalCount = 0; | ||
112 | } | ||
113 | |||
114 | public void AddSample(T sample) | ||
115 | { | ||
116 | MoveWindow(); | ||
117 | |||
118 | int curBucket = (int)(curBucketGlobal % NumBuckets); | ||
119 | buckets[curBucket].value = Add(buckets[curBucket].value, sample); | ||
120 | buckets[curBucket].count++; | ||
121 | |||
122 | totalSum = Add(totalSum, sample); | ||
123 | totalCount++; | ||
124 | } | ||
125 | |||
126 | /// <summary> | ||
127 | /// Returns the total values in the collection window. | ||
128 | /// </summary> | ||
129 | public T GetSum() | ||
130 | { | ||
131 | // It might have been a while since we last added a sample, so we may need to adjust the window | ||
132 | MoveWindow(); | ||
133 | |||
134 | return totalSum; | ||
135 | } | ||
136 | |||
137 | /// <summary> | ||
138 | /// Returns the current time in ms. | ||
139 | /// </summary> | ||
140 | private long GetNow() | ||
141 | { | ||
142 | return DateTime.Now.Ticks / TimeSpan.TicksPerMillisecond; | ||
143 | } | ||
144 | |||
145 | /// <summary> | ||
146 | /// Clears the values in buckets [offset, offset+num) | ||
147 | /// </summary> | ||
148 | private void ZeroBuckets(int offset, int num) | ||
149 | { | ||
150 | for (int i = 0; i < num; i++) | ||
151 | { | ||
152 | buckets[offset + i].value = GetZero(); | ||
153 | buckets[offset + i].count = 0; | ||
154 | } | ||
155 | } | ||
156 | |||
157 | /// <summary> | ||
158 | /// Adjusts the buckets so that the "current bucket" corresponds to the current time. | ||
159 | /// This may require dropping old buckets. | ||
160 | /// </summary> | ||
161 | /// <remarks> | ||
162 | /// This method allows for the possibility that we don't get new samples for each bucket, so the | ||
163 | /// new bucket may be some distance away from the last used bucket. | ||
164 | /// </remarks> | ||
165 | private void MoveWindow() | ||
166 | { | ||
167 | long newBucketGlobal = GetNow() / bucketSize; | ||
168 | long bucketsDistance = newBucketGlobal - curBucketGlobal; | ||
169 | |||
170 | if (bucketsDistance == 0) | ||
171 | { | ||
172 | // We're still on the same bucket as before | ||
173 | return; | ||
174 | } | ||
175 | |||
176 | if (bucketsDistance >= NumBuckets) | ||
177 | { | ||
178 | // Discard everything | ||
179 | Reset(); | ||
180 | return; | ||
181 | } | ||
182 | |||
183 | int curBucket = (int)(curBucketGlobal % NumBuckets); | ||
184 | int newBucket = (int)(newBucketGlobal % NumBuckets); | ||
185 | |||
186 | |||
187 | // Clear all the buckets in this range: (cur, new] | ||
188 | int numToClear = (int)bucketsDistance; | ||
189 | |||
190 | if (curBucket < NumBuckets - 1) | ||
191 | { | ||
192 | // Clear buckets at the end of the window | ||
193 | int num = Math.Min((int)bucketsDistance, NumBuckets - (curBucket + 1)); | ||
194 | ZeroBuckets(curBucket + 1, num); | ||
195 | numToClear -= num; | ||
196 | } | ||
197 | |||
198 | if (numToClear > 0) | ||
199 | { | ||
200 | // Clear buckets at the beginning of the window | ||
201 | ZeroBuckets(0, numToClear); | ||
202 | } | ||
203 | |||
204 | // Move the "current bucket" pointer | ||
205 | curBucketGlobal = newBucketGlobal; | ||
206 | |||
207 | RecalcTotal(); | ||
208 | } | ||
209 | |||
210 | private void RecalcTotal() | ||
211 | { | ||
212 | totalSum = GetZero(); | ||
213 | totalCount = 0; | ||
214 | |||
215 | for (int i = 0; i < NumBuckets; i++) | ||
216 | { | ||
217 | totalSum = Add(totalSum, buckets[i].value); | ||
218 | totalCount += buckets[i].count; | ||
219 | } | ||
220 | } | ||
221 | |||
222 | } | ||
223 | } | ||
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 | |||
109 | DateTime TimeStarted { get; } | 109 | DateTime TimeStarted { get; } |
110 | 110 | ||
111 | /// <summary> | 111 | /// <summary> |
112 | /// Tick the last measurement period was started. | 112 | /// Collects information about how long the script was executed. |
113 | /// </summary> | 113 | /// </summary> |
114 | long MeasurementPeriodTickStart { get; } | 114 | MetricsCollectorTime ExecutionTime { get; } |
115 | |||
116 | /// <summary> | ||
117 | /// Ticks spent executing in the last measurement period. | ||
118 | /// </summary> | ||
119 | long MeasurementPeriodExecutionTime { get; } | ||
120 | 115 | ||
121 | /// <summary> | 116 | /// <summary> |
122 | /// Scene part in which this script instance is contained. | 117 | /// 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 | |||
199 | 199 | ||
200 | public DateTime TimeStarted { get; private set; } | 200 | public DateTime TimeStarted { get; private set; } |
201 | 201 | ||
202 | public long MeasurementPeriodTickStart { get; private set; } | 202 | public MetricsCollectorTime ExecutionTime { get; private set; } |
203 | 203 | ||
204 | public long MeasurementPeriodExecutionTime { get; private set; } | 204 | private static readonly int MeasurementWindow = 30 * 1000; // show the *recent* time used by the script, to find currently active scripts |
205 | |||
206 | public static readonly int MaxMeasurementPeriod = 30 * 1000; // show the *recent* time used by the script, to find currently active scripts | ||
207 | 205 | ||
208 | private bool m_coopTermination; | 206 | private bool m_coopTermination; |
209 | 207 | ||
@@ -246,6 +244,8 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance | |||
246 | 244 | ||
247 | m_SaveState = StatePersistedHere; | 245 | m_SaveState = StatePersistedHere; |
248 | 246 | ||
247 | ExecutionTime = new MetricsCollectorTime(MeasurementWindow, 10); | ||
248 | |||
249 | // m_log.DebugFormat( | 249 | // m_log.DebugFormat( |
250 | // "[SCRIPT INSTANCE]: Instantiated script instance {0} (id {1}) in part {2} (id {3}) in object {4} attached avatar {5} in {6}", | 250 | // "[SCRIPT INSTANCE]: Instantiated script instance {0} (id {1}) in part {2} (id {3}) in object {4} attached avatar {5} in {6}", |
251 | // ScriptTask.Name, ScriptTask.ItemID, Part.Name, Part.UUID, Part.ParentGroup.Name, m_AttachedAvatar, Engine.World.Name); | 251 | // 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 | |||
505 | Running = true; | 505 | Running = true; |
506 | 506 | ||
507 | TimeStarted = DateTime.Now; | 507 | TimeStarted = DateTime.Now; |
508 | MeasurementPeriodTickStart = Util.EnvironmentTickCount(); | 508 | |
509 | MeasurementPeriodExecutionTime = 0; | 509 | // Note: we don't reset ExecutionTime. The reason is that runaway scripts are stopped and restarted |
510 | // automatically, and we *do* want to show that they had high CPU in that case. If we had reset | ||
511 | // ExecutionTime here then runaway scripts, paradoxically, would never show up in the "Top Scripts" dialog. | ||
510 | 512 | ||
511 | if (EventQueue.Count > 0) | 513 | if (EventQueue.Count > 0) |
512 | { | 514 | { |
@@ -832,20 +834,13 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance | |||
832 | m_EventStart = DateTime.Now; | 834 | m_EventStart = DateTime.Now; |
833 | m_InEvent = true; | 835 | m_InEvent = true; |
834 | 836 | ||
835 | // Reset the measurement period when we reach the end of the current one. | 837 | Stopwatch timer = new Stopwatch(); |
836 | if (Util.EnvironmentTickCountSubtract((int)MeasurementPeriodTickStart) > MaxMeasurementPeriod) | 838 | timer.Start(); |
837 | { | ||
838 | MeasurementPeriodTickStart = Util.EnvironmentTickCount(); | ||
839 | MeasurementPeriodExecutionTime = 0; | ||
840 | } | ||
841 | 839 | ||
842 | Stopwatch executionTime = new Stopwatch(); | ||
843 | executionTime.Start(); | ||
844 | |||
845 | m_Script.ExecuteEvent(State, data.EventName, data.Params); | 840 | m_Script.ExecuteEvent(State, data.EventName, data.Params); |
846 | 841 | ||
847 | executionTime.Stop(); | 842 | timer.Stop(); |
848 | MeasurementPeriodExecutionTime += executionTime.ElapsedMilliseconds; | 843 | ExecutionTime.AddSample(timer); |
849 | 844 | ||
850 | m_InEvent = false; | 845 | m_InEvent = false; |
851 | m_CurrentEvent = String.Empty; | 846 | 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 | |||
2343 | 2343 | ||
2344 | public Dictionary<uint, float> GetObjectScriptsExecutionTimes() | 2344 | public Dictionary<uint, float> GetObjectScriptsExecutionTimes() |
2345 | { | 2345 | { |
2346 | long tickNow = Util.EnvironmentTickCount(); | ||
2347 | Dictionary<uint, float> topScripts = new Dictionary<uint, float>(); | 2346 | Dictionary<uint, float> topScripts = new Dictionary<uint, float>(); |
2348 | 2347 | ||
2349 | lock (m_Scripts) | 2348 | lock (m_Scripts) |
@@ -2353,7 +2352,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine | |||
2353 | if (!topScripts.ContainsKey(si.LocalID)) | 2352 | if (!topScripts.ContainsKey(si.LocalID)) |
2354 | topScripts[si.RootLocalID] = 0; | 2353 | topScripts[si.RootLocalID] = 0; |
2355 | 2354 | ||
2356 | topScripts[si.RootLocalID] += CalculateAdjustedExectionTime(si, tickNow); | 2355 | topScripts[si.RootLocalID] += GetExectionTime(si); |
2357 | } | 2356 | } |
2358 | } | 2357 | } |
2359 | 2358 | ||
@@ -2367,7 +2366,6 @@ namespace OpenSim.Region.ScriptEngine.XEngine | |||
2367 | return 0.0f; | 2366 | return 0.0f; |
2368 | } | 2367 | } |
2369 | float time = 0.0f; | 2368 | float time = 0.0f; |
2370 | long tickNow = Util.EnvironmentTickCount(); | ||
2371 | IScriptInstance si; | 2369 | IScriptInstance si; |
2372 | // Calculate the time for all scripts that this engine is executing | 2370 | // Calculate the time for all scripts that this engine is executing |
2373 | // Ignore any others | 2371 | // Ignore any others |
@@ -2376,36 +2374,15 @@ namespace OpenSim.Region.ScriptEngine.XEngine | |||
2376 | si = GetInstance(id); | 2374 | si = GetInstance(id); |
2377 | if (si != null && si.Running) | 2375 | if (si != null && si.Running) |
2378 | { | 2376 | { |
2379 | time += CalculateAdjustedExectionTime(si, tickNow); | 2377 | time += GetExectionTime(si); |
2380 | } | 2378 | } |
2381 | } | 2379 | } |
2382 | return time; | 2380 | return time; |
2383 | } | 2381 | } |
2384 | 2382 | ||
2385 | private float CalculateAdjustedExectionTime(IScriptInstance si, long tickNow) | 2383 | private float GetExectionTime(IScriptInstance si) |
2386 | { | 2384 | { |
2387 | long ticksElapsed = Util.EnvironmentTickCountSubtract((int)tickNow, (int)si.MeasurementPeriodTickStart); | 2385 | return (float)si.ExecutionTime.GetSumTime().TotalMilliseconds; |
2388 | |||
2389 | // Avoid divide by zero | ||
2390 | if (ticksElapsed == 0) | ||
2391 | ticksElapsed = 1; | ||
2392 | |||
2393 | // Scale execution time to the ideal 55 fps frame time for these reasons. | ||
2394 | // | ||
2395 | // 1) XEngine does not execute scripts per frame, unlike other script engines. Hence, there is no | ||
2396 | // 'script execution time per frame', which is the original purpose of this value. | ||
2397 | // | ||
2398 | // 2) Giving the raw execution times is misleading since scripts start at different times, making | ||
2399 | // it impossible to compare scripts. | ||
2400 | // | ||
2401 | // 3) Scaling the raw execution time to the time that the script has been running is better but | ||
2402 | // is still misleading since a script that has just been rezzed may appear to have been running | ||
2403 | // for much longer. | ||
2404 | // | ||
2405 | // 4) Hence, we scale execution time to an idealised frame time (55 fps). This is also not perfect | ||
2406 | // since the figure does not represent actual execution time and very hard running scripts will | ||
2407 | // never exceed 18ms (though this is a very high number for script execution so is a warning sign). | ||
2408 | return ((float)si.MeasurementPeriodExecutionTime / ticksElapsed) * 18.1818f; | ||
2409 | } | 2386 | } |
2410 | 2387 | ||
2411 | public void SuspendScript(UUID itemID) | 2388 | public void SuspendScript(UUID itemID) |