Netduino home hardware projects downloads community

Jump to content


The Netduino forums have been replaced by new forums at community.wildernesslabs.co. This site has been preserved for archival purposes only and the ability to make new accounts or posts has been turned off.
Photo

A more useful way to measure performance of loops


  • Please log in to reply
1 reply to this topic

#1 BitFlipper

BitFlipper

    Advanced Member

  • Members
  • PipPipPip
  • 61 posts

Posted 20 May 2011 - 07:47 PM

I'm relatively new to Netduino and the MF, but I have been doing full .Net development for many years. I've written some performance-critical applications in .Net, including realtime audio applications (both managed VST plugins as well as a managed DAW application that can host VST plugins) and a 3D XNA game engine. Because of this I've developed some classes to help with performance related measurements.

Now with Netduino, things are much simpler (and quite a bit slower :( ), but I find that some of the classes I used before is still helpful. I have taken some of my classes and simplified it a bit to work with Netduino. This one is a variation on the Stopwatch class that people use on these forums.

Its main advantage over Stopwatch is that you can take multiple measurements and afterwards you can get the Min, Max and Avg time for all measurements. This is useful if you have a loop and want to see how much "jitter" there is, or to see how much extra time a GC adds since you can clearly see when the Max time is much higher than the Min time. It sticks out like a sore thumb.

Another advantage is that there is a nice time formatting method that you can use to display the results.

PerformanceTimer:
using System;
using Microsoft.SPOT.Hardware;

namespace UtilityEx
{
    /// <summary>
    /// Accurately measures timing
    /// </summary>
    public class PerformanceTimer
    {
        private bool m_running;
        private int m_runCount;
        private long m_initialStartTick;
        private long m_currentSartTick;
        private long m_lastStopTick;
        private long m_totalOnTicks;
        private long m_minTicks;
        private long m_maxTicks;
        private const float kSecondsPerTick = 0.001f / TimeSpan.TicksPerMillisecond;

        /// <summary>
        /// Constructor
        /// </summary>
        public PerformanceTimer()
        {
        }

        /// <summary>
        /// Get whether the timer is running
        /// </summary>
        public bool Running
        {
            get { return m_running; }
        }

        /// <summary>
        /// Get the number of runs
        /// </summary>
        public int RunCount
        {
            get { return m_runCount; }
        }

        /// <summary>
        /// Get the average in seconds
        /// </summary>
        public float AvgTime
        {
            get
            {
                if (m_runCount == 0)
                    return 0.0f;

                return (float)(TicksToSeconds(m_totalOnTicks) / m_runCount);
            }
        }

        /// <summary>
        /// Get the min run time in seconds
        /// </summary>
        public float MinTime
        {
            get { return TicksToSeconds(m_minTicks); }
        }

        /// <summary>
        /// Get the max run time in seconds
        /// </summary>
        public float MaxTime
        {
            get { return TicksToSeconds(m_maxTicks); }
        }

        /// <summary>
        /// Get the total ON time
        /// </summary>
        public float TotalOnTime
        {
            get { return TicksToSeconds(m_totalOnTicks); }
        }

        /// <summary>
        /// Get the total elapsed time since the initial Start call
        /// </summary>
        public float TotalElapsedTime
        {
            get { return TicksToSeconds(MathEx.Max(0, m_lastStopTick - m_initialStartTick)); }
        }

        /// <summary>
        /// Get the percentage that the run time is of the total time
        /// </summary>
        public float PercentTime
        {
            get
            {
                if (m_runCount == 0 || m_lastStopTick == 0)
                    return 0.0f;

                return (float)(TicksToSeconds(m_totalOnTicks) / this.TotalElapsedTime) * 100.0f;
            }
        }

        /// <summary>
        /// Convert from ticks to seconds
        /// </summary>
        /// <param name="ticks"></param>
        /// <returns></returns>
        public static float TicksToSeconds(long ticks)
        {
            return (float)ticks * kSecondsPerTick;
        }

        /// <summary>
        /// Start the stopwatch
        /// </summary>
        public void Start()
        {
            var currentTick = Utility.GetMachineTime().Ticks;

            if (m_runCount == 0)
            {
                m_initialStartTick = currentTick;
                m_lastStopTick = m_initialStartTick;
            }

            m_currentSartTick = currentTick;
            m_running = true;
        }

        /// <summary>
        /// Stop the stopwatch
        /// </summary>
        public void Stop()
        {
            if (!m_running)
                return;

            var currentTick = Utility.GetMachineTime().Ticks;
            var currentElapsedTicks = MathEx.Max(0, currentTick - m_currentSartTick);

            m_lastStopTick = currentTick;
            m_totalOnTicks += currentElapsedTicks;
            m_maxTicks = MathEx.Max(m_maxTicks, currentElapsedTicks);

            m_runCount++;

            if (m_runCount == 1)
                m_minTicks = currentElapsedTicks;
            else
                m_minTicks = MathEx.Min(m_minTicks, currentElapsedTicks);

            m_running = false;
        }

        /// <summary>
        /// Reset everything
        /// </summary>
        public void Reset()
        {
            m_running = false;
            m_runCount = 0;
            m_initialStartTick = 0;
            m_currentSartTick = 0;
            m_totalOnTicks = 0;
            m_minTicks = 0;
            m_maxTicks = 0;
            m_lastStopTick = 0;
        }
    }
}

And some supporting classes:
namespace UtilityEx
{
    public static class MathEx
    {
        /// <summary>
        /// Get the min from the two values
        /// </summary>
        /// <param name="val1"></param>
        /// <param name="val2"></param>
        /// <returns></returns>
        public static long Min(long val1, long val2)
        {
            return val1 < val2 ? val1 : val2;
        }
        
        /// <summary>
        /// Get the max from the two values
        /// </summary>
        /// <param name="val1"></param>
        /// <param name="val2"></param>
        /// <returns></returns>
        public static long Max(long val1, long val2)
        {
            return val1 > val2 ? val1 : val2;
        }

        /// <summary>
        /// Get the absolute value
        /// </summary>
        /// <param name="value"></param>
        /// <returns></returns>
        public static float Abs(float value)
        {
            return value > 0.0f ? value : -value;
        }
    }
}

namespace UtilityEx
{
    /// <summary>
    /// Extension methods
    /// </summary>
    public static class Extensions
    {
        /// <summary>
        /// Format the float value as time
        /// </summary>
        /// <param name="value"></param>
        /// <returns></returns>
        public static string FormatAsTime(this float seconds)
        {
            string text = null;
            var negative = seconds < 0.0f;

            if (negative)
                seconds = -seconds;

            if (seconds < 0.000000001f)
                return "0.00 ms";
            else if (seconds < 0.00000001f)
                text = ((double)(seconds * 1000000000.0f)).ToString("F2") + " ns";
            else if (seconds < 0.0000001f)
                text = ((double)(seconds * 1000000000.0f)).ToString("F1") + " ns";
            else if (seconds < 0.000001f)
                text = ((double)(seconds * 1000000000.0f)).ToString("F0") + " ns";
            else if (seconds < 0.00001f)
                text = ((double)(seconds * 1000000.0f)).ToString("F2") + " us";
            else if (seconds < 0.0001f)
                text = ((double)(seconds * 1000000.0f)).ToString("F1") + " us";
            else if (seconds < 0.001f)
                text = ((double)(seconds * 1000000.0f)).ToString("F0") + " us";
            else if (seconds < 0.01f)
                text = ((double)(seconds * 1000.0f)).ToString("F2") + " ms";
            else if (seconds < 0.1f)
                text = ((double)(seconds * 1000.0f)).ToString("F1") + " ms";
            else if (seconds < 1.0f)
                text = ((double)(seconds * 1000.0f)).ToString("F0") + " ms";
            else if (seconds < 10.0f)
                text = seconds.ToString("F2") + " s";
            else if (seconds < 100.0f)
                text = seconds.ToString("F1") + " s";
            else
                text = seconds.ToString("F0") + " s";

            return negative ? ("-" + text) : text;
        }
    }
}

namespace System.Runtime.CompilerServices 
{ 
    [AttributeUsage(AttributeTargets.Assembly | AttributeTargets.Class | AttributeTargets.Method)]  
    public sealed class ExtensionAttribute : Attribute { } 
}

Typical usage:


public void DoWork()
{
    var timer = new PerformanceTimer();

    while (true)
    {
        timer.Start();

        // Do some suff here...
        // ...
                
        timer.Stop();

        if (timer.RunCount >= 100)
        {
            ShowStats(timer);
            timer.Reset();
        }
      
        Thread.Sleep(5);
    }
}

private void ShowStats(PerformanceTimer timer)
{
    if (timer.RunCount == 0)
    {
        Debug.Print("Timer: [no runs]");
        return;
    }

    Debug.Print("Timer: Runs = " + timer.RunCount.ToString() +
    ", Min = " + timer.MinTime.FormatAsTime() +
    ", Max = " + timer.MaxTime.FormatAsTime() +
    ", Avg = " + timer.AvgTime.FormatAsTime());
}

Typical output would look like this:
Timer: Runs = 100, Min = 555 us, Max = 2.50 ms, Avg = 879 us
Timer: Runs = 100, Min = 555 us, Max = 2.75 ms, Avg = 988 us
Timer: Runs = 100, Min = 555 us, Max = 2.75 ms, Avg = 1.03 ms
Timer: Runs = 100, Min = 555 us, Max = 2.71 ms, Avg = 916 us
Timer: Runs = 100, Min = 555 us, Max = 2.71 ms, Avg = 914 us
Timer: Runs = 100, Min = 555 us, Max = 2.67 ms, Avg = 787 us


#2 devup

devup

    New Member

  • Members
  • Pip
  • 1 posts

Posted 21 February 2013 - 08:13 AM

Thank You BitFlipper, your performance timer is working great and really helpful for me !






0 user(s) are reading this topic

0 members, 0 guests, 0 anonymous users

home    hardware    projects    downloads    community    where to buy    contact Copyright © 2016 Wilderness Labs Inc.  |  Legal   |   CC BY-SA
This webpage is licensed under a Creative Commons Attribution-ShareAlike License.