Tiny C# "manual" profiler (for those days that your proper profiler is proving too difficult to work with)

Profiler.cs

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++;
    }
}

Sample output

 => 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

Sample usage

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
  }  
}