Create a gist now

Instantly share code, notes, and snippets.

What would you like to do?
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;
}
}
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment