Skip to content

Instantly share code, notes, and snippets.

@puf
Last active July 17, 2017 16:29
Show Gist options
  • Save puf/9770188 to your computer and use it in GitHub Desktop.
Save puf/9770188 to your computer and use it in GitHub Desktop.
Tiny C# "manual" profiler (for those days that your proper profiler is proving too difficult to work with)
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
public static class Profiler {
private static List<ProfilerFrame> stack = new List<ProfilerFrame>();
private static Dictionary<string, ProfiledBlock> totals = new Dictionary<string, ProfiledBlock>();
private static Action<string> logger;
public static void SetLogger(Action<string> logger) {
Profiler.logger = logger;
}
public static ProfilerFrame Measure(string name) {
return new ProfilerFrame(name);
}
public static void PushFrame(ProfilerFrame frame) {
if (logger != null) {
var oneUp = stack.LastOrDefault();
if (oneUp != null && !oneUp.IsFrameEntranceLogged) {
logger(new String(' ', stack.Count * 2 - 2) + " => " + oneUp.Name);
oneUp.IsFrameEntranceLogged = true;
}
// logger(new String(' ', stack.Count * 2) + " => " + frame.Name);
}
stack.Add(frame);
}
public static void PushFrame(string name) {
Profiler.Measure(name);
}
public static void PopFrame(string name) {
// TODO: throw exception if top of stack does not match name
Profiler.PopFrame(stack[stack.Count - 1]);
}
public static void PopFrame() {
Profiler.PopFrame(stack[stack.Count - 1]);
}
public static void PopFrame(ProfilerFrame frame) {
// TODO: throw exception if frame is not at top of stack
if (logger != null) {
logger(new String(' ', stack.Count * 2 - 2) + (frame.IsFrameEntranceLogged ? " <= " : " <> ") + frame.Name + ": " + frame.Stopwatch.ElapsedMilliseconds + "ms");
}
var total = totals.ContainsKey(frame.Name) ? totals[frame.Name] : new ProfiledBlock(frame.Name);
total.Add(frame);
totals[frame.Name] = total;
stack.RemoveAt(stack.Count - 1);
}
public static void NextFrame(string name) {
PopFrame();
Measure(name);
}
public static IEnumerable<ProfiledBlock> Totals { get { return totals.Values; } }
}
public class ProfilerFrame : IDisposable {
public string Name { get; private set; }
public Stopwatch Stopwatch { get; private set; }
public bool IsFrameEntranceLogged { get; set; }
public ProfilerFrame(string name) {
Name = name;
Profiler.PushFrame(this);
Stopwatch = new Stopwatch();
Stopwatch.Start();
}
public void Dispose() {
Stopwatch.Stop();
Profiler.PopFrame(this);
}
}
public class ProfiledBlock {
public string Name { get; private set; }
public long TotalExecutionTimeInMilliseconds { get; private set; }
public long /*Moving*/AverageExecutionTimeInMilliseconds { get; private set; }
public int TotalInvocationCount { get; private set; }
public ProfiledBlock(string name) {
Name = name;
}
public void Add(ProfilerFrame frame) {
TotalExecutionTimeInMilliseconds += frame.Stopwatch.ElapsedMilliseconds;
AverageExecutionTimeInMilliseconds = (long)Math.Round((9.0 * AverageExecutionTimeInMilliseconds + frame.Stopwatch.ElapsedMilliseconds) / 10.0);
TotalInvocationCount++;
}
}
=> OuterMethod
=> InnerMethod
<> Phase 1: 1ms
<> Phase 2: 0ms
<= InnerMethod: 2ms
=> InnerMethod
<> Phase 1: 99ms
<> Phase 2: 200ms
<= InnerMethod: 300ms
=> InnerMethod
<> Phase 1: 199ms
<> Phase 2: 400ms
<= InnerMethod: 600ms
=> InnerMethod
<> Phase 1: 299ms
<> Phase 2: 600ms
<= InnerMethod: 899ms
=> InnerMethod
<> Phase 1: 399ms
<> Phase 2: 800ms
<= InnerMethod: 1200ms
=> InnerMethod
<> Phase 1: 500ms
<> Phase 2: 1000ms
<= InnerMethod: 1500ms
=> InnerMethod
<> Phase 1: 599ms
<> Phase 2: 1200ms
<= InnerMethod: 1800ms
=> InnerMethod
<> Phase 1: 700ms
<> Phase 2: 1400ms
<= InnerMethod: 2100ms
=> InnerMethod
<> Phase 1: 800ms
<> Phase 2: 1600ms
<= InnerMethod: 2400ms
=> InnerMethod
<> Phase 1: 900ms
<> Phase 2: 1800ms
<= InnerMethod: 2700ms
<= OuterMethod: 13504ms
OuterMethod: invoked 1 times, totalling 13504ms, Moving Average=1350ms
InnerMethod: invoked 10 times, totalling 13501ms, Moving Average=1047ms
Phase 2: invoked 10 times, totalling 9000ms, Moving Average=698ms
Phase 1: invoked 10 times, totalling 4498ms, Moving Average=348ms
public void OuterMethod() {
// send all method enters and exits to the console
Profiler.SetLogger(Console.WriteLine);
// start measuring, this will automatically stop the measurement when the using block ends
using (Profiler.Measure("OuterMethod")) {
for (var i=0; i < 10; i++) {
InnerMethod(i);
}
}
// also log the totals. Since these are static, they will be for all runs.
foreach (var total in Profiler.Totals.OrderByDescending(t => t.TotalExecutionTimeInMilliseconds)) {
Console.WriteLine(string.Format(
"{0}: invoked {1} times, totalling {2}ms, Moving Average={3}ms",
total.Name,
total.TotalInvocationCount,
total.TotalExecutionTimeInMilliseconds,
total.AverageExecutionTimeInMilliseconds
));
// The AverageExecutionTimeInMilliseconds is a moving average over 10 frames, this negates the effects of warmup over time
// To determine the real average just do total.TotalExecutionTimeInMilliseconds / total.TotalInvocationCount
}
}
public void InnerMethod(int i) {
// start measuring this method
using (Profiler.Measure("InnerMethod")) {
// this method has a number of "steps", each of which could be time-consuming. So we measure those separately
Profiler.PushFrame("Phase 1");
// do expensive operation
Thread.Sleep(i*100);
// now we start the next phase, this pops the Phase 1 frame and pushes a new one
Profiler.NextFrame("Phase 2");
// do second expensive operation, repeat this pattern for all phases
Thread.Sleep(i*200);
// we're done with the phases, so we pop the last frame
Profiler.PopFrame(); // Or Profiler.PopFrame("Phase 1") to make it more readible
}
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment