[Mono-devel-list] JIT profiling/benchmarking

[ppham at mit.edu]

Hi all,

I am interested in profiling/benchmarking the JIT compiler in the Mono runtime
to see how long JITting takes as a function of method length (in IL 
instructions). My objective is to find (roughly) the break-even point where
pure interpretation and JIT compilation are equally fast.

My benchmark program includes several methods of varying length, which generate
from 2000 IL instructions to about 20,000, and I am measuring times (crudely)
using System.DateTime.Now.Milliseconds within the program. Each method is
designed to take the same amount of time to execute but increasing amounts of
time to compile (through manipulation of loops and the time spent in each loop).
 
It was my assumption that the first time a method is run, it is JIT compiled and 
cached, and for every call after that the cached/compiled version is run.
However, that seems not to be the case as I cannot measure any significant
difference between the first time a method is run and every subsequent time.

Also, mint, the Mono interpreter, appears to run these methods faster than
mono, which has JIT by default. I am further puzzled by mint's profiling
output which includes statistics such as "Time spent in compilation" and
"Slowest method to compile", which shouldn't be in an interpreted CLR at all.

If someone could explain how to better benchmark JIT times in Mono, or even
in .NET on Windows for comparison, I would greatly appreciate it.
Snippets of my benchmarking program are below.

The full source code and the profiling results under both mint and mono are
at

http://web.mit.edu/ppham/www/clr/

Many thanks,
Paul

>>

using System;

public delegate void DoMathDelegate();

public class JITTest {

  static Int64 TOTAL_LOOP_COUNT = 1000;

  static void doMath10a() {
    Decimal j = Decimal.MaxValue;
    Int64 LOOP_COUNT = TOTAL_LOOP_COUNT;
    for (Int64 i = 0; i < LOOP_COUNT; i++) {
      try { j = j * j / 3.0M; j = (j * 3.141592653956M) / j;
      j = j * j / 3.0M; j = (j * 3.141592653956M) / j; }
      catch (OverflowException oe) { bool dummy = oe.Equals(oe); }
    }
  }

...

  static void doMath50a() {
    Decimal j = Decimal.MaxValue; Int64 LOOP_COUNT = TOTAL_LOOP_COUNT / 5;
    for (Int64 i = 0; i < LOOP_COUNT; i++) {
      try { j = j * j / 3.0M; j = (j * 3.141592653956M) / j;
      j = j * j / 3.0M; j = (j * 3.141592653956M) / j; }
      catch (OverflowException oe) { bool dummy = oe.Equals(oe); }
    }
    for (Int64 i = 0; i < LOOP_COUNT; i++) {
      try { j = j * j / 3.0M; j = (j * 3.141592653956M) / j;
      j = j * j / 3.0M; j = (j * 3.141592653956M) / j; }
      catch (OverflowException oe) { bool dummy = oe.Equals(oe); }
    }
    for (Int64 i = 0; i < LOOP_COUNT; i++) {
      try { j = j * j / 3.0M; j = (j * 3.141592653956M) / j;
      j = j * j / 3.0M; j = (j * 3.141592653956M) / j; }
      catch (OverflowException oe) { bool dummy = oe.Equals(oe); }
    }
    for (Int64 i = 0; i < LOOP_COUNT; i++) {
      try { j = j * j / 3.0M; j = (j * 3.141592653956M) / j;
      j = j * j / 3.0M; j = (j * 3.141592653956M) / j; }
      catch (OverflowException oe) { bool dummy = oe.Equals(oe); }
    }
    for (Int64 i = 0; i < LOOP_COUNT; i++) {
      try { j = j * j / 3.0M; j = (j * 3.141592653956M) / j;
      j = j * j / 3.0M; j = (j * 3.141592653956M) / j; }
      catch (OverflowException oe) { bool dummy = oe.Equals(oe); }
    }
    //50
  }

...

  readonly static int ITERATIONS = 20;
  readonly static int TYPE_COUNT = 21;
  readonly static int SUBTYPE_COUNT = 5;

  public static void Main() {
    Console.WriteLine("JIT Test");
    DateTime start;
    int[] times = new int[ITERATIONS];
    int total;
    DoMathDelegate[,] delegates = 
      new DoMathDelegate[TYPE_COUNT,SUBTYPE_COUNT];
    delegates[0,0] = new DoMathDelegate(doMath10a);
    delegates[0,1] = new DoMathDelegate(doMath10b);
    delegates[0,2] = new DoMathDelegate(doMath10c);
    delegates[0,3] = new DoMathDelegate(doMath10d);
    delegates[0,4] = new DoMathDelegate(doMath10e);

...

    for (int j = 0; j < TYPE_COUNT; j++) {
      total = 0;

      for (int k = 0; k < SUBTYPE_COUNT; k++) {
        start = DateTime.Now;
        delegates[j,k]();
        total += DateTime.Now.Subtract(start).Milliseconds;
      }
      double first = total * 1.0 / SUBTYPE_COUNT;
      total = 0;
      for (int i = 0; i < ITERATIONS; i++) {
        start = DateTime.Now;
        delegates[j,0]();
        times[i] = DateTime.Now.Subtract(start).Milliseconds;
        total += times[i];
      }
      double avg = total * 1.0 / ITERATIONS;
      Console.WriteLine("Test " + (j*50) + " First " + first + ", Avg:" + avg +
                        ", Diff:" + (first - avg));
    }
  }