Benchmarking.cs

using NodaTime;
using System;
using System.Diagnostics;
using System.Linq;
using System.Reflection;
using System.Runtime.CompilerServices;

namespace JITterOptimisations
{
    public static class Extensions
    {
        /// <summary>
        /// This does absolutely nothing, but 
        /// allows us to consume a property value without having
        /// a useless local variable. It should end up being JITted
        /// away completely, so have no effect on the results.
        /// </summary>
        internal static void Consume<T>(this T value)
        {
            //Borrowed from NodaTime benchmarks!!
            //https://code.google.com/p/noda-time/source/browse/src/NodaTime.Benchmarks/Framework/Extensions.cs
        }

        [MethodImpl(MethodImplOptions.NoInlining)]
        internal static T ConsumeNoInlining<T>(this T item)
        {
            return item;
        }

        // Borrowed from LambdaMicrobenchmarking - https://github.com/biboudis/LambdaMicrobenchmarking/blob/master/LambdaMicrobenchmarking/Compiler.cs#L11
        static public T ConsumeValue<T>(this T dummy)
        {
            return dummy;
        }
    }

    class Program
    {
        private static object resultObject;
        private static double resultDouble;

        static void Main(string[] args)
        {
            CheckProgramState();
            var program = new Program();

            var numIterations = 10000000;

            Log(ConsoleColor.Cyan, "Profiling code:\"" + "Math.Sqrt(123.456)" + "\"\n");

            Log(ConsoleColor.DarkYellow, "Code passed into the Profile function via an Action or Func<T>");
            Marker("Profile");
            Profile(String.Empty, numIterations, () => Math.Sqrt(123.456));
            Marker("ProfileWithConsume");
            ProfileWithConsume(String.Empty, numIterations, () => Math.Sqrt(123.456));
            Marker("ProfileWithConsumeValue");
            ProfileWithConsumeValue(String.Empty, numIterations, () => Math.Sqrt(123.456));
            Marker("ProfileWithConsumeNoInlining");
            ProfileWithConsumeNoInlining(String.Empty, numIterations, () => Math.Sqrt(123.456));
            Marker("ProfileWithStore");
            ProfileWithStore<double>(String.Empty, numIterations, () => Math.Sqrt(123.456));
            Marker("ProfileWithConsumeNoInliningUnrolledx20");
            ProfileWithConsumeNoInliningUnrolledx20(String.Empty, numIterations, () => Math.Sqrt(123.456));

            Log(ConsoleColor.DarkYellow, "Code DIRECTLY inside the Profile function");
            Marker("ProfileDirect");
            ProfileDirect(String.Empty, numIterations);
            Marker("ProfileDirectWithStoreBroken");
            ProfileDirectWithStoreBroken(String.Empty, numIterations);
            Marker("ProfileDirectWithStoreFixed");
            ProfileDirectWithStoreFixed(String.Empty, numIterations);
            Marker("ProfileDirectWithStoreAlternativeFix");
            ProfileDirectWithStoreAlternativeFix(String.Empty, numIterations);
            Marker("ProfileDirectWithConsume");
            ProfileDirectWithConsume(String.Empty, numIterations);
            Marker("ProfileDirectWithConsumeValue");
            ProfileDirectWithConsumeValue(String.Empty, numIterations);
            Marker("ProfileDirectWithConsumeNoInlining");
            ProfileDirectWithConsumeNoInlining(String.Empty, numIterations);

            Log(ConsoleColor.DarkYellow, "Code UNROLLED DIRECTLY inside the Profile function");
            Marker("ProfileDirectWithStoreUnrolledx10");
            ProfileDirectWithStoreUnrolledx10(String.Empty, numIterations);
            Marker("ProfileDirectWithStoreUnrolledx20");
            ProfileDirectWithStoreUnrolledx20(String.Empty, numIterations);

            Marker("END of profiling!");

            Console.WriteLine("Press any key to EXIT");
            Console.ReadLine();
        }

        // Taken from http://stackoverflow.com/questions/1047218/benchmarking-small-code-samples-in-c-can-this-implementation-be-improved
        static void Profile(string description, int iterations, Action action)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            action();

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                action();
            }
            watch.Stop();
            Console.WriteLine("Profile via an Action - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileWithConsume<T>(string description, int iterations, Func<T> func)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            func();

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                func().Consume();
            }
            watch.Stop();
            Console.WriteLine("ProfileWithConsume via a Func<T> - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileWithConsumeValue<T>(string description, int iterations, Func<T> func)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            func();

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                func().ConsumeValue();
            }
            watch.Stop();
            Console.WriteLine("ProfileWithConsumeValue via a Func<T> - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileWithConsumeNoInlining<T>(string description, int iterations, Func<T> func)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            func();

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                func().ConsumeNoInlining();
            }
            watch.Stop();
            Console.WriteLine("ProfileWithConsumeNoInlining via a Func<T> - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileWithStore<T>(string description, int iterations, Func<double> func)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            func();

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                resultDouble = func();
            }
            watch.Stop();
            Console.WriteLine("ProfileWithStore via a Func<T> - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileWithConsumeNoInliningUnrolledx20<T>(string description, int iterations, Func<T> func)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            func();

            var watch = new Stopwatch();
            var loops = iterations / 20;
            watch.Start();
            for (int i = 0; i < loops; i++)
            {
                #region unrolled 20 times
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                func().ConsumeNoInlining();
                #endregion
            }
            watch.Stop();
            Console.WriteLine("ProfileWithConsumeNoInliningUnrolled x20 via a Func<T> - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileDirect(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            var temp = Math.Sqrt(123.456);

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                Math.Sqrt(123.456);
            }
            watch.Stop();
            Console.WriteLine("ProfileDirect - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileDirectWithStoreBroken(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            var temp = Math.Sqrt(123.456);

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                resultObject = Math.Sqrt(123.456);
            }
            watch.Stop();
            Console.WriteLine("ProfileDirectWithStoreBroken - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileDirectWithStoreFixed(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            resultDouble = Math.Sqrt(123.456);

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                resultDouble += Math.Sqrt(123.456);
            }
            watch.Stop();
            Console.WriteLine("ProfileDirectWithStoreFixed - " + description);
            Console.WriteLine("Result: {0:N}", resultDouble);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static double ProfileDirectWithStoreAlternativeFix(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            var temp = Math.Sqrt(123.456);

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                temp += Math.Sqrt(123.456);
            }
            watch.Stop();
            Console.WriteLine("ProfileDirectWithStoreAlternativeFix - " + description);
            Console.WriteLine("Result: {0:N}", temp);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
            return temp;
        }

        static void ProfileDirectWithStoreUnrolledx10(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            var temp = Math.Sqrt(123.456);

            var watch = new Stopwatch();
            watch.Start();
            var loops = iterations / 10;
            for (int i = 0; i < loops; i++)
            {
                /// TODO Need a better way of doing this, the JITter is too clever!!
                #region unrolled 10 times
                temp += Math.Sqrt(123.450);
                temp += Math.Sqrt(123.451);
                temp += Math.Sqrt(123.452);
                temp += Math.Sqrt(123.453);
                temp += Math.Sqrt(123.454);
                temp += Math.Sqrt(123.455);
                temp += Math.Sqrt(123.456);
                temp += Math.Sqrt(123.457);
                temp += Math.Sqrt(123.458);
                temp += Math.Sqrt(123.459);
                #endregion
            }
            watch.Stop();
            Console.WriteLine("ProfileDirectWithStoreUnrolled x10 - " + description);
            Console.WriteLine("Result: {0:N}", temp);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileDirectWithStoreUnrolledx20(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            var temp = Math.Sqrt(123.456);

            var watch = new Stopwatch();
            watch.Start();
            var loops = iterations / 20;
            for (int i = 0; i < loops; i++)
            {
                /// TODO Need a better way of doing this, the JITter is too clever!!
                #region unrolled 20 times
                temp += Math.Sqrt(123.450);
                temp += Math.Sqrt(123.451);
                temp += Math.Sqrt(123.452);
                temp += Math.Sqrt(123.453);
                temp += Math.Sqrt(123.454);
                temp += Math.Sqrt(123.455);
                temp += Math.Sqrt(123.456);
                temp += Math.Sqrt(123.457);
                temp += Math.Sqrt(123.458);
                temp += Math.Sqrt(123.459);
                temp += Math.Sqrt(123.460);
                temp += Math.Sqrt(123.461);
                temp += Math.Sqrt(123.462);
                temp += Math.Sqrt(123.463);
                temp += Math.Sqrt(123.464);
                temp += Math.Sqrt(123.465);
                temp += Math.Sqrt(123.466);
                temp += Math.Sqrt(123.467);
                temp += Math.Sqrt(123.468);
                temp += Math.Sqrt(123.469);
                #endregion
            }
            watch.Stop();
            Console.WriteLine("ProfileDirectWithStoreUnrolled x20 - " + description);
            Console.WriteLine("Result: {0:N}", temp);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileDirectWithConsume(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            var temp = Math.Sqrt(123.456);

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                Math.Sqrt(123.456).Consume();
            }
            watch.Stop();
            Console.WriteLine("ProfileDirectWithConsume - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileDirectWithConsumeValue(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            var temp = Math.Sqrt(123.456);

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                Math.Sqrt(123.456).ConsumeValue();
            }
            watch.Stop();
            Console.WriteLine("ProfileDirectWithConsumeValue - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        static void ProfileDirectWithConsumeNoInlining(string description, int iterations)
        {
            // clean up
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            // warm up
            var temp = Math.Sqrt(123.456); 

            var watch = new Stopwatch();
            watch.Start();
            for (int i = 0; i < iterations; i++)
            {
                Math.Sqrt(123.456).ConsumeNoInlining();
            }
            watch.Stop();
            Console.WriteLine("ProfileDirectWithConsumeNoInlining - " + description);
            Console.WriteLine("{0:0.00} ms ({1:N0} ticks) (over {2:N0} iterations), {3:N0} ops/millisecond\n",
                            watch.ElapsedMilliseconds, watch.ElapsedTicks, iterations, (double)iterations / watch.ElapsedMilliseconds);
        }

        private static void CheckProgramState()
        {
            // Shamelessy stolen from MeasureIt
            // This equates to the "Optimise" flag on the Project -> Properties -> Build page
            DebuggableAttribute debugAttribute = (DebuggableAttribute)Attribute.GetCustomAttribute(Assembly.GetExecutingAssembly(), typeof(DebuggableAttribute));
            if (debugAttribute != null && debugAttribute.IsJITOptimizerDisabled)
            {
                Log(ConsoleColor.Red, "JIT Optimizer DISABLED\n\tIsJITOptimizerDisabled: {0}, IsJITTrackingEnabled: {1}", 
                                        debugAttribute.IsJITOptimizerDisabled, debugAttribute.IsJITTrackingEnabled);
            }
            else if (debugAttribute != null && debugAttribute.IsJITOptimizerDisabled == false)
            {
                Log(ConsoleColor.Green, "JIT Optimizer ENABLED\n\tIsJITOptimizerDisabled: {0}, IsJITTrackingEnabled: {1}",
                                        debugAttribute.IsJITOptimizerDisabled, debugAttribute.IsJITTrackingEnabled);
            }
            else // unknown
            {
                Log(ConsoleColor.White, "JIT Optimizer UNKNOWN");
            }

#if DEBUG
            Log(ConsoleColor.Red, "Running a DEBUG Build", ConsoleColor.Red);
#else
            Log(ConsoleColor.Green, "Running a RELEASE build");
#endif

            Log(ConsoleColor.Green, "Application is {0}-bit", Environment.Is64BitProcess ? "64" : "32");

            var assemblies = Assembly.GetExecutingAssembly().GetReferencedAssemblies()
                                .Where(x => x.FullName.StartsWith("NodaTime")).ToArray();
            foreach (AssemblyName assembly in assemblies)
            {
                // Have to re-fetch the info, otherwise all the fields are blank/empty
                var assemblyName = AssemblyName.GetAssemblyName(assembly.FullName.Split(',')[0] + ".dll");
                if (Environment.Is64BitProcess)
                {
                    if (assemblyName.ProcessorArchitecture == ProcessorArchitecture.IA64 ||
                        assemblyName.ProcessorArchitecture == ProcessorArchitecture.Amd64)
                        Log(ConsoleColor.Green, "{0} - {1}", assemblyName, assemblyName.ProcessorArchitecture);
                    else
                        Log(ConsoleColor.Red, "{0} - {1}", assemblyName, assemblyName.ProcessorArchitecture);
                }
                else
                {
                    if (assemblyName.ProcessorArchitecture == ProcessorArchitecture.X86)
                        Log(ConsoleColor.Green, "{0} - {1}", assemblyName, assemblyName.ProcessorArchitecture);
                    else
                        Log(ConsoleColor.Red, "{0} - {1}", assemblyName, assemblyName.ProcessorArchitecture);
                }

                var info = new AssemblyInformationLoader(Assembly.Load(assemblyName));
                if (info.JitOptimized == false)
                    Log(ConsoleColor.Red, "{0} is NOT Optimised", assemblyName.Name);
            }

            //var info = new AssemblyInformationLoader(Assembly.GetExecutingAssembly());
            //Log(ConsoleColor.Green, info.JitOptimized);

            Console.WriteLine("");
        }

        private void Normal()
        {
            Console.WriteLine("Normal");
            PrintStackTrace();
        }

        [MethodImpl(MethodImplOptions.NoInlining)]
        private void NotInlined()
        {
            Console.WriteLine("Not Inlined");
            PrintStackTrace();
        }

        [MethodImpl(MethodImplOptions.NoInlining)]
        private static void Marker(string text)
        {
        }

        [MethodImpl(MethodImplOptions.AggressiveInlining)]
        private static void PrintStackTrace()
        {
            Console.WriteLine(new StackTrace());
        }

        private static void Log(ConsoleColor colour, string format, params object[] args)
        {
            Log(colour, String.Format(format, args));
        }

        private static void Log(ConsoleColor colour, object @object)
        {
            Log(colour, @object.ToString());
        }

        private static void Log(ConsoleColor colour, string text)
        {
            var origColour = Console.ForegroundColor;
            Console.ForegroundColor = colour;
            Console.WriteLine(text);
            Console.ForegroundColor = origColour;
        }
    }
}