7

I've been attempting to see how long functions take to execute in my code as practice to see where I can optimize. Right now I use a helper class that is essentially a stopwatch with a message to check these. The goal of this is that I should be able to wrap whatever method call I want in the helper and I'll get it's duration.

public class StopwatcherData
{
    public long Time { get; set; }
    public string Message { get; set; }

    public StopwatcherData(long time, string message)
    {
        Time = time;
        Message = message;
    }
}

public class Stopwatcher
{
    public delegate void CompletedCallBack(string result);

    public static List<StopwatcherData> Data { get; set; }
    private static Stopwatch stopwatch { get; set;}

    public Stopwatcher()
    {
        Data = new List<StopwatcherData>();
        stopwatch = new Stopwatch();
        stopwatch.Start();
    }

    public static void Click(string message)
    {
        Data.Add(new StopwatcherData(stopwatch.ElapsedMilliseconds, message));
    }

    public static void Reset()
    {
        stopwatch.Reset();
        stopwatch.Start();
    }
}

Right now to use this, I have to call the Reset before the function I want so that the timer is restarted, and then call the click after it.

Stopwatcher.Reset()
MyFunction();
Stopwatcher.Click("MyFunction");

I've read a bit about delegates and actions, but I'm unsure of how to apply them to this situation. Ideally, I would pass the function as part of the Stopwatcher call.

//End Goal:
Stopwatcher.Track(MyFunction(), "MyFunction Time");

Any help is welcome.

Blankdud
  • 698
  • 5
  • 9
  • 22
  • 2
    You might want to have a look at [BenchmarkDotNet](https://github.com/dotnet/BenchmarkDotNet) instead. – trashr0x Apr 23 '18 at 12:20
  • 2
    This can become very complex if you're not careful. Your best bet would be to use profiling tools that already exist or to manage the stopwatch apart from the function call, like what you already have. – Isaac Hildebrandt Apr 23 '18 at 12:22
  • Unless you’re talking function execution time on the order of seconds, this method is likely to be too imprecise to provide any useful data. – theMayer Apr 23 '18 at 12:32
  • 1
    Which version of VS do you use? the community/pro version has a lot of that sort of thing built in – BugFinder Apr 23 '18 at 12:35

3 Answers3

9

It's not really a good idea to profile your application like that, but if you insist, you can at least make some improvements.

First, don't reuse Stopwatch, just create new every time you need.

Second, you need to handle two cases - one when delegate you pass returns value and one when it does not.

Since your Track method is static - it's a common practice to make it thread safe. Non-thread-safe static methods are quite bad idea. For that you can store your messages in a thread-safe collection like ConcurrentBag, or just use lock every time you add item to your list.

In the end you can have something like this:

public class Stopwatcher {
    private static readonly ConcurrentBag<StopwatcherData> _data = new ConcurrentBag<StopwatcherData>();

    public static void Track(Action action, string message) {
        var w = Stopwatch.StartNew();
        try {
            action();
        }
        finally {
            w.Stop();
            _data.Add(new StopwatcherData(w.ElapsedMilliseconds, message));
        }
    }

    public static T Track<T>(Func<T> func, string message) {
        var w = Stopwatch.StartNew();
        try {
            return func();
        }
        finally {
            w.Stop();
            _data.Add(new StopwatcherData(w.ElapsedMilliseconds, message));
        }
    }
}

And use it like this:

Stopwatcher.Track(() => SomeAction(param1), "test");
bool result = Stopwatcher.Track(() => SomeFunc(param2), "test");

If you are going to use that with async delegates (which return Task or Task<T>) - you need to add two more overloads for that case.

Evk
  • 98,527
  • 8
  • 141
  • 191
  • This answer really helped me along to understand what I was trying to accomplish. I realize that my code was sub-par, as it was unfortunately thrown together very quickly to accomplish a strange requirement. For my own sake, in the future when it comes to benchmarking methods like this, what would you suggest as a tool? The overall goal being, finding what methods take the longest to execute? – Blankdud Apr 23 '18 at 12:47
  • @Blankdud you just need to use a dedicated tool - profiler. Which will show you a nice overview of what methods take most time and so on, without you writing any code. And if you need to benchmark something (that's a very different thing from profiling) - then use BenchmarkDotNet. – Evk Apr 23 '18 at 13:09
  • @Blankdud I don't say that your function is useless, it's just not the right tool for "how long functions take to execute in my code as practice to see where I can optimize". For that - profiler is the right tool. – Evk Apr 23 '18 at 13:28
  • Thanks. I'm still very new to the profiler and wasn't sure how to get the benchmarks I needed. I'll need to do more research on it. – Blankdud Apr 23 '18 at 13:58
3

Yes, you can create a timer function that accepts any action as a delegate. Try this block:

public static long TimeAction(Action action)
{
    var timer = new Stopwatch();
    timer.Start();
    action();
    timer.Stop();
    return timer.ElapsedMilliseconds;
}

This can be used like this:

  var elapsedMilliseconds = TimeAction(() => MyFunc(param1, param2));

This is a bit more awkward if your wrapped function returns a value, but you can deal with this by assigning a variable from within the closure, like this:

  bool isSuccess ;
  var elapsedMilliseconds = TimeToAction(() => {
    isSuccess = MyFunc(param1, param2);
  });
1

I've had this problem a while ago as well and was always afraid of the case that I'll leave errors when I change Stopwatcher.Track(() => SomeFunc(), "test")(See Evk's answer) back to SomeFunc(). So I tought about something that wraps it without changing it!

I came up with a using, which is for sure not the intended purpose.

public class OneTimeStopwatch : IDisposable
{
    private string _logPath = "C:\\Temp\\OneTimeStopwatch.log";
    private readonly string _itemname;
    private System.Diagnostics.Stopwatch sw = new System.Diagnostics.Stopwatch();

    public OneTimeStopwatch(string itemname)
    {
        _itemname = itemname;
        sw.Start();
    }

    public void Dispose()
    {
        sw.Stop();
        System.IO.File.AppendAllText(_logPath, string.Format($"{_itemname}: {sw.ElapsedMilliseconds}ms{Environment.NewLine}"));
    }
}

This can be used a easy way

using (new OneTimeStopwatch("test"))
{
    //some sensible code not to touch
    System.Threading.Thread.Sleep(1000);
}
//logfile with line "test: 1000ms"

I only need to remove 2 lines (and auto format) to make it normal again. Plus I can easily wrap multiple lines here which isn't possible without defining new functions in the other approach.

Again, this is not recommended for terms of few miliseconds.

Chrᴉz remembers Monica
  • 1,829
  • 1
  • 10
  • 24