[.net] profiling method calls

Started by
2 comments, last by Ridge 18 years, 1 month ago
I did a little test to see if different ways of calling methods had a significant impact on the execution time of that method call. Here is my code for scrutiny:

using System;

namespace Test
{
	interface InterfaceA
	{
		void Execute();
	}
	class A : InterfaceA
	{
		public long a_count = 0;
		public void Execute()
		{
			a_count++;
		}
	}
	delegate void DelegateB();
	abstract class AbstractD
	{
		public abstract void Execute();
	}
	class D : AbstractD
	{
		public long d_count = 0;
		public override void Execute()
		{
			d_count++;
		}
	}
	class E
	{
		public long e_count = 0;
		public virtual void Execute()
		{
			e_count++;
		}
	}
	class F : E
	{
		public long f_count = 0;
		public override void Execute()
		{
			f_count++;
		}
	}

	/// <summary>
	/// Summary description for Class1.
	/// </summary>
	class Class1
	{
		private long b_count = 0, c_count = 0;
		private void B()
		{
			b_count++;
		}

		private void C()
		{
			c_count++;
		}
		public Class1(long len)
		{
			InterfaceA a = new A();
			DelegateB b = new DelegateB(B);
			this.b_count = 0;
			this.c_count = 0;
			AbstractD d = new D();
			E e = new E();
			E f = new F();

			long startTime,endTime;
			
			startTime = DateTime.Now.Ticks;
			endTime = startTime;
			while(endTime - startTime < len)
			{
				a.Execute();
				endTime = DateTime.Now.Ticks;
			}
			Write("A", ((A)a).a_count, len);

			startTime = DateTime.Now.Ticks;
			endTime = startTime;
			while(endTime - startTime < len)
			{
				b();
				endTime = DateTime.Now.Ticks;
			}
			Write("B", this.b_count, len);

			startTime = DateTime.Now.Ticks;
			endTime = startTime;
			while(endTime - startTime < len)
			{
				C();
				endTime = DateTime.Now.Ticks;
			}
			Write("C", this.c_count, len);

			startTime = DateTime.Now.Ticks;
			endTime = startTime;
			while(endTime - startTime < len)
			{
				d.Execute();
				endTime = DateTime.Now.Ticks;
			}
			Write("D", ((D)d).d_count, len);

			startTime = DateTime.Now.Ticks;
			endTime = startTime;
			while(endTime - startTime < len)
			{
				e.Execute();
				endTime = DateTime.Now.Ticks;
			}
			Write("E", e.e_count, len);

			startTime = DateTime.Now.Ticks;
			endTime = startTime;
			while(endTime - startTime < len)
			{
				f.Execute();
				endTime = DateTime.Now.Ticks;
			}
			Write("F", ((F)f).f_count, len);

			Console.WriteLine();
		}
		private void Write(string p, long a, long b)
		{
			Console.WriteLine("{0}.) {1} iterations per {2} ticks. Iterations per tick:{3}", p, a, b, ((double)a/(double)b).ToString("#.###"));
		}
		/// <summary>
		/// The main entry point for the application.
		/// </summary>
		[STAThread]
		static void Main(string[] args)
		{
			for(long len = 100; len <= 100000000; len *= 10)
			{
				new Class1(len);
			}
		}
	}
}



And here are the results. I tried a few runs where I varied the run order and no matter the calling technique, the very first run after startup is always bad. A is a method called through an Interface B is a method called through a Delegate C is a regular method call D is a method called through an Abstract class E is a virtual method called from an instance of a parent class F is a virtual method of a subclass called from a handle through the parent class.

//startup garbage, first run is always bad, no matter the type of method call
A.) 15981 iterations per 100 ticks. Iterations per tick:159.81
B.) 244711 iterations per 100 ticks. Iterations per tick:2447.11
C.) 349202 iterations per 100 ticks. Iterations per tick:3492.02
D.) 337687 iterations per 100 ticks. Iterations per tick:3376.87
E.) 337220 iterations per 100 ticks. Iterations per tick:3372.2
F.) 333611 iterations per 100 ticks. Iterations per tick:3336.11

A.) 334738 iterations per 1000 ticks. Iterations per tick:334.738
B.) 251012 iterations per 1000 ticks. Iterations per tick:251.012
C.) 350070 iterations per 1000 ticks. Iterations per tick:350.07
D.) 338606 iterations per 1000 ticks. Iterations per tick:338.606
E.) 339915 iterations per 1000 ticks. Iterations per tick:339.915
F.) 337030 iterations per 1000 ticks. Iterations per tick:337.03

A.) 326402 iterations per 10000 ticks. Iterations per tick:32.64
B.) 269786 iterations per 10000 ticks. Iterations per tick:26.979
C.) 343209 iterations per 10000 ticks. Iterations per tick:34.321
D.) 339750 iterations per 10000 ticks. Iterations per tick:33.975
E.) 335457 iterations per 10000 ticks. Iterations per tick:33.546
F.) 338993 iterations per 10000 ticks. Iterations per tick:33.899

A.) 333997 iterations per 100000 ticks. Iterations per tick:3.34
B.) 258025 iterations per 100000 ticks. Iterations per tick:2.58
C.) 350273 iterations per 100000 ticks. Iterations per tick:3.503
D.) 158170 iterations per 100000 ticks. Iterations per tick:1.582
E.) 325737 iterations per 100000 ticks. Iterations per tick:3.257
F.) 304673 iterations per 100000 ticks. Iterations per tick:3.047

A.) 2287327 iterations per 1000000 ticks. Iterations per tick:2.287
B.) 1867621 iterations per 1000000 ticks. Iterations per tick:1.868
C.) 2429217 iterations per 1000000 ticks. Iterations per tick:2.429
D.) 2324748 iterations per 1000000 ticks. Iterations per tick:2.325
E.) 2285776 iterations per 1000000 ticks. Iterations per tick:2.286
F.) 2335654 iterations per 1000000 ticks. Iterations per tick:2.336

A.) 21131154 iterations per 10000000 ticks. Iterations per tick:2.113
B.) 17114207 iterations per 10000000 ticks. Iterations per tick:1.711
C.) 22322870 iterations per 10000000 ticks. Iterations per tick:2.232
D.) 21537869 iterations per 10000000 ticks. Iterations per tick:2.154
E.) 21582894 iterations per 10000000 ticks. Iterations per tick:2.158
F.) 21581786 iterations per 10000000 ticks. Iterations per tick:2.158

A.) 210926479 iterations per 100000000 ticks. Iterations per tick:2.109
B.) 168268727 iterations per 100000000 ticks. Iterations per tick:1.683
C.) 219268502 iterations per 100000000 ticks. Iterations per tick:2.193
D.) 211795242 iterations per 100000000 ticks. Iterations per tick:2.118
E.) 213377592 iterations per 100000000 ticks. Iterations per tick:2.134
F.) 215243191 iterations per 100000000 ticks. Iterations per tick:2.152

The results seem to show that calling a method through an interface is marginally slower than normal, calling a delagte is significantly slower than normal, and all others are nearly identical to normal. [Edited by - capn_midnight on March 16, 2006 1:01:52 PM]

[Formerly "capn_midnight". See some of my projects. Find me on twitter tumblr G+ Github.]

Advertisement
The first call being slower is probably due to the initial compiling of the code. I'd be interested in seeing your numbers contrasted with the same assembly that has been ngen'ed. I would expect the initial run time to drop and the others to remain consistent.

Your results are consistent with what I'd expect. I'd love to see the CIL output of the assembly (might do it myself here at work unless I can kick it in gear and start thinking) of the different method calls. The Framework erects additional scaffolding around a finalizer, for instance, wrapping user code in a try..finally block that you don't even know is there.
..what we do will echo throughout eternity..
as far as I can tell from the CIL output, the calls all look virtually identical, with the exception of the regular method and the delegate. Everything uses a call to an op "callvirt" and then the method name in question. The normal method uses just a "call" op, and the delegate uses "callvirt" on an Invoke method of the delegate object, which I assume is the extra overhead.

I was very suprised to see that an interfaced method, an abstract method, and a virtual method were all the exact same code.

[Formerly "capn_midnight". See some of my projects. Find me on twitter tumblr G+ Github.]

You may find the following MSDN article useful, it's a little old (obviously there'll be perf differences between runtimes) but it makes a fine reference. These kinds of small synthetic benchmarks are always frought with caveats and the like, but they help shed some light on various perf scenarios. As always, profile... :)

Writing Faster Managed Code: Know What Things Cost
--Ridge

This topic is closed to new replies.

Advertisement