locked
Method call times not consistent RRS feed

  • General discussion

  • I have written a very small console application to test the average call times to simple methods that are 1) local to the entry class 2) methods inside of an instantiated class and 3) methods inside of a class loaded at runtime and accessed through an interface. I realize that the interface call is virtual and will take a small amount of extra time. I am accessing the methods in an loop that iterates 20 million times and an outer loop that runs for an arbitrary number of times. Average access for both the 'this.add' call and the instantiated class call over the 20M calls is 120ms. The average time for the loaded dll call through the interface is 175ms.

    However, about 1 of 5 tries yields this result:

    Notice that the times for the calls other than this.Add are consistent with the last group. Also notice that the >360ms time on the call is consistent for the life of the process and not just an outlier. I ran the 20M iteration inner loop twice here just to save space. A run of 10 or 20 will remain consistent throughout.

    What would cause this discrepancy? JIT Optimizations not consistent? Cache problems? Help me please I'm pulling all of my hair out.

    CODE:

    class Program
    {
    	private ModuleLoader _ml = new ModuleLoader();
     	private Stopwatch _swModule = new Stopwatch();
    	private Stopwatch _swThis = new Stopwatch();
    	private Stopwatch _swLocal = new Stopwatch();
    	private LocalAdder _localAdder = new LocalAdder();
    
    	static void Main(string[] args)
    	{
    		Program me = new Program();
    	}
    
    	private Program()
    	{
    		Process.GetCurrentProcess().PriorityClass = ProcessPriorityClass.RealTime;
    
    		// Use reflection to pull in the DLL
    		List<object> modList = _ml.GetModulesFromFile("../{path to dll}.dll", "IAdd");
    
    		if (modList.Count < 1)
    		{
    			Console.WriteLine("I didn't find any modules");
    		}
    		else
    		{
    			IAdd adder = modList[0] as IAdd;
    
    			Random r = new Random(0);
    			int iterations = 20000000;
    			int[] vals = new int[iterations * 2];
    			for (int i = 0; i < iterations * 2; i++)
    			{
    				vals[i] = r.Next();
    			}
    
    			double modResult = 0;
    			double thisResult = 0;
    			double localResult = 0;
    
    			for (int j = 0; j < 2; j++)
    			{
    				modResult = 0;
    				thisResult = 0;
    				localResult = 0;
    
    				_swModule.Restart();
    				for (int i = 0; i < iterations * 2; i += 2)
    				{
    					modResult += adder.Add(vals[i], vals[i + 1]);
    				}
    				_swModule.Stop();
    
    				_swThis.Restart();
    				for (int i = 0; i < iterations * 2; i += 2)
    				{
    					thisResult += Add(vals[i], vals[i + 1]);
    				}
    				_swThis.Stop();
    
    				_swLocal.Restart();
    				for (int i = 0; i < iterations * 2; i += 2)
    				{
    					localResult += _localAdder.Add(vals[i], vals[i + 1]);
    				}
    				_swLocal.Stop();
    
    				Console.WriteLine("Module Result: " + modResult);
    				Console.WriteLine("This Result:  " + thisResult);
    				Console.WriteLine("Class.Add Result:  " + localResult);
    
    				Console.WriteLine("DLL Interface.Add() time: " + _swModule.ElapsedMilliseconds);
    				Console.WriteLine("This.Add() time:  " + _swThis.ElapsedMilliseconds);
    				Console.WriteLine("Class.Add() time:  " + _swLocal.ElapsedMilliseconds);
    			}
    
    			Console.WriteLine("================\n");
    		}
    	}
    
    	private double Add(double x, double y)
    	{
    		double result = x + y;
    		return result;
    	}
    }

    Friday, July 27, 2012 4:59 PM

All replies

  • Even running with RealTime priority you can be prempted by other processes. (think drivers)  You can improve your results by averaging a larger sample, but timing software this way will always be a rough estimate. 

    If you need more accurate measurements you'd have to invest in a real performance analysis tool.  The only one I've used, I don't recommend becuase the company that sells it has license restrictions written by Nazi's


    This signature unintentionally left blank.

    Friday, July 27, 2012 6:45 PM
  • Thanks for the reply, Nick. I don't think the problem I'm seeing is preemption. When I run the outer loop, say, 20 times, the delay is pretty much constant the entire 20 loops. If what I saw was 19 good runs and 1 bad one I might assume preemption or maybe the garbage collector. However, I'm seeing that if it's bad one go round it will be bad the next but only on one of the 3 particular calling methods that I have. That's why I was wondering if the JIT optimizer had random results. All 3 of the methods are exactly the same.

    Any ideas?

    Maybe I'm not explaining my problem very well. Here I'll try to recap a play-by-play:

    Press 'Start without Debugging (Ctrl-F5)'

    Outer loop 100, inner loop 20-million:

    dll --> 175ms x 100 // DLL call took 175ms to iterate 20-million times in each of the outer 100 loops -- that's ok

    this --> 120ms x 100 // Same but only 120ms -- that's ok too

    class --> 120ms x 100 // Same as the this call -- still ok

    Run again, same thing.

    Run again, same thing.

    Run again:

    dll --> 175ms x 100 // Consistent with first trial

    this --> 385ms x 100 // What the heck? The delay is the same for all 100 outer loop iterations! Did the JIT optimizer not optimize the method?

    class --> 120ms x 100 // Consistent with first trial

    Please let me know if you don't understand my example.


    --JH

    Saturday, July 28, 2012 3:26 AM