epic/OpenRA
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge pull request #5408 from RoosterDragon/perftimer-tick

Browse Source 
Changed logging in DoTimed/RunActivity to create less overhead
This commit is contained in:
Paul Chote
2014-05-31 16:55:47 +12:00
parent 4ef82f2863 d1b3d77662
commit 67f1207ef5
5 changed files with 73 additions and 60 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
OpenRA.Game/Settings.cs
View File

@@ -71,7 +71,7 @@ namespace OpenRA
public bool BotDebug = false;
public bool PerfText = false;
public bool PerfGraph = false;
public TimeSpan LongTickThreshold = TimeSpan.FromMilliseconds(1d);
public float LongTickThresholdMs = 1;
public bool SanityCheckUnsyncedCode = false;
public int Samples = 25;
public bool IgnoreVersionMismatch = false;

83
OpenRA.Game/Support/PerfTimer.cs
View File

@@ -18,42 +18,42 @@ namespace OpenRA.Support
{
public class PerfTimer : IDisposable
{
readonly Stopwatch sw;
readonly string name;
readonly int thresholdMs;
readonly int depth;
readonly float thresholdMs;
readonly byte depth;
readonly PerfTimer parent;
List<PerfTimer> children;
long ticks;
static ThreadLocal<PerfTimer> Parent = new ThreadLocal<PerfTimer>();
// Tree settings
const int MaxWidth = 60, Digits = 6;
const int MaxIndentedLabel = MaxWidth - Digits;
const int Digits = 6;
const string IndentationString = "| ";
static readonly string FormatString = "{0," + MaxIndentedLabel + "} {1," + Digits + "} ms";
const string FormatSeperation = " ms ";
static readonly string FormatString = "{0," + Digits + ":0}" + FormatSeperation + "{1}";
public PerfTimer(string name, int thresholdMs = 0)
public PerfTimer(string name, float thresholdMs = 0)
{
this.name = name;
this.thresholdMs = thresholdMs;
parent = Parent.Value;
depth = parent == null ? 0 : parent.depth + 1;
depth = parent == null ? (byte)0 : (byte)(parent.depth + 1);
Parent.Value = this;
sw = Stopwatch.StartNew();
ticks = Stopwatch.GetTimestamp();
}
public void Dispose()
{
sw.Stop();
ticks = Stopwatch.GetTimestamp() - ticks;
Parent.Value = parent;
if (parent == null)
Write();
else if (sw.Elapsed.TotalMilliseconds > thresholdMs)
else if (ElapsedMs > thresholdMs)
{
if (parent.children == null)
parent.children = new List<PerfTimer>();
@@ -63,56 +63,45 @@ namespace OpenRA.Support
void Write()
{
var elapsedMs = Math.Round(this.sw.Elapsed.TotalMilliseconds);
if (children != null)
{
Log.Write("perf", GetHeader(Indentation, this.name));
Log.Write("perf", GetHeader(Indentation, name));
foreach (var child in children)
child.Write();
Log.Write("perf", FormatString, GetFooter(Indentation), elapsedMs);
Log.Write("perf", FormatString, ElapsedMs, GetFooter(Indentation));
}
else if (ElapsedMs >= thresholdMs)
Log.Write("perf", FormatString, ElapsedMs, Indentation + name);
}
float ElapsedMs { get { return 1000f * ticks / Stopwatch.Frequency; } }
public static void LogLongTick(long startStopwatchTicks, long endStopwatchTicks, string name, object item)
{
var type = item.GetType();
var label = type == typeof(string) || type.IsGenericType ? item.ToString() : type.Name;
Log.Write("perf", FormatString,
1000f * (endStopwatchTicks - startStopwatchTicks) / Stopwatch.Frequency,
"[{0}] {1}: {2}".F(Game.LocalTick, name, label));
}
public static long LongTickThresholdInStopwatchTicks
{
get
{
return (long)(Stopwatch.Frequency * Game.Settings.Debug.LongTickThresholdMs / 1000f);
}
else if (elapsedMs >= thresholdMs)
Log.Write("perf", FormatString, GetOneLiner(Indentation, this.name), elapsedMs);
}
#region Formatting helpers
static string GetHeader(string indentation, string label)
{
return string.Concat(indentation, LimitLength(label, MaxIndentedLabel - indentation.Length));
}
static string GetOneLiner(string indentation, string label)
{
return string.Concat(indentation, SetLength(label, MaxIndentedLabel - indentation.Length));
return string.Concat(new string(' ', Digits + FormatSeperation.Length), indentation, label);
}
static string GetFooter(string indentation)
{
return string.Concat(indentation, new string('-', MaxIndentedLabel - indentation.Length));
}
static string LimitLength(string s, int length, int minLength = 8)
{
length = Math.Max(length, minLength);
if (s == null || s.Length <= length)
return s;
return s.Substring(0, length);
}
static string SetLength(string s, int length, int minLength = 8)
{
length = Math.Max(length, minLength);
if (s == null || s.Length == length)
return s;
if (s.Length < length)
return s.PadRight(length);
return s.Substring(0, length);
return string.Concat(indentation, new string('-', Math.Max(15, 50 - indentation.Length)));
}
string Indentation

17
OpenRA.Game/Traits/Util.cs
View File

@@ -78,17 +78,26 @@ namespace OpenRA.Traits
public static Activity RunActivity(Actor self, Activity act)
{
// Note - manual iteration here for performance due to high call volume.
var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks;
var start = Stopwatch.GetTimestamp();
while (act != null)
{
var prev = act;
using (new PerfTimer("[{0}] Activity: {1}".F(Game.LocalTick, prev), (int)Game.Settings.Debug.LongTickThreshold.TotalMilliseconds))
act = act.Tick(self);
var current = Stopwatch.GetTimestamp();
if (current - start > longTickThresholdInStopwatchTicks)
{
PerfTimer.LogLongTick(start, current, "Activity", prev);
start = Stopwatch.GetTimestamp();
}
else
{
start = current;
}
if (prev == act)
break;
}
return act;
}

4
OpenRA.Game/World.cs
View File

@@ -244,9 +244,9 @@ namespace OpenRA
foreach (var a in actors)
a.Tick();
ActorsWithTrait<ITick>().DoTimed(x => x.Trait.Tick(x.Actor), "Trait", Game.Settings.Debug.LongTickThreshold);
ActorsWithTrait<ITick>().DoTimed(x => x.Trait.Tick(x.Actor), "Trait");
effects.DoTimed(e => e.Tick(this), "Effect", Game.Settings.Debug.LongTickThreshold);
effects.DoTimed(e => e.Tick(this), "Effect");
}
while (frameEndActions.Count != 0)

25
OpenRA.Game/WorldUtils.cs
View File

@@ -172,13 +172,28 @@ namespace OpenRA
}
}
public static void DoTimed<T>(this IEnumerable<T> e, Action<T> a, string text, TimeSpan time)
public static void DoTimed<T>(this IEnumerable<T> e, Action<T> a, string text)
{
e.Do(x =>
// Note - manual enumeration here for performance due to high call volume.
var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks;
using (var enumerator = e.GetEnumerator())
{
using (new PerfTimer("[{0}] {1}: {2}".F(Game.LocalTick, text, x), (int)time.TotalMilliseconds))
a(x);
});
var start = Stopwatch.GetTimestamp();
while (enumerator.MoveNext())
{
a(enumerator.Current);
var current = Stopwatch.GetTimestamp();
if (current - start > longTickThresholdInStopwatchTicks)
{
PerfTimer.LogLongTick(start, current, text, enumerator.Current);
start = Stopwatch.GetTimestamp();
}
else
{
start = current;
}
}
}
}
public static bool AreMutualAllies( Player a, Player b )