Alex Pinsker: How interception affects performance in .NET

Recently I prepared a lecture on AOP & interception in .NET for my collegues.
As part of a lecture I created a small demo to demonstrate how interception could affect
the performance of the intercepted code. My original estimation was to obtain result
similar to one, obtained in that nice article (slowdown upto 300%
with ~~0,022 microsecond per call).
My test shows a quite different numbers - slowdown by 1099 times with timing of
about ~~19 microsecond per call. The only difference is that I created a complete simple
AOP scenario with context attribute, context property and a message sink (all of a no-op style).

Full test code is below ...


using System;
using System.Runtime.Remoting.Proxies;
using System.Runtime.Remoting.Messaging;
using System.Runtime.Remoting;
using System.Diagnostics;
using System.Threading;
using System.Runtime.Remoting.Activation;
using System.Runtime.Remoting.Services;
using System.Runtime.Remoting.Contexts;

namespace InteropTimingDemo
{
    public class NoOpProperty
        : IContextProperty
        , IContributeServerContextSink
    {
        internal NoOpProperty(){}

        // IContributeServerContextSink members
        public IMessageSink GetServerContextSink(IMessageSink next) 
        {
            return new NoOpSink( next);
        }

        // IContextProperty members
        public string Name { get { return "NoOpProperty"; }  }
        public bool IsNewContextOK(Context ctx) 
        {
            return true;
        }
        public void Freeze(Context ctx) { }
    }

    public class NoOpSink : IMessageSink 
    {
        [ ContextStatic ]
        readonly IMessageSink _next;

        public NoOpSink(IMessageSink next)
        {  this._next = next; }

        public IMessage SyncProcessMessage(IMessage r) 
        {
            return _next.SyncProcessMessage(r);
        }

        public IMessageSink NextSink
        {
            get{return _next;}
        }

        public IMessageCtrl AsyncProcessMessage(
                     IMessage msg, IMessageSink replySink)
        {
            return null;
        }
    }

    // Define our context-attrbute
    [ AttributeUsage(AttributeTargets.Class) ]
    public class NoOpAttribute : Attribute, IContextAttribute 
    {
        internal NoOpAttribute(){}

        // IContextProperty members
        public bool IsContextOK(
              Context current, IConstructionCallMessage ctor) 
        {
            object property = current.GetProperty("NoOpProperty");
            return (property != null);
        }

        public void GetPropertiesForNewContext(
              IConstructionCallMessage ctor )
        {
            IContextProperty prop = new NoOpProperty();
            ctor.ContextProperties.Add(prop);
        }
    }


    interface ITestClassInterface
    {
        double DoSomething(double paramA, double paramB);
    }

    [ NoOp ]
    public class InterceptedClass
              : ContextBoundObject, ITestClassInterface 
    {
        public double DoSomething(double paramA, double paramB) 
        {
            return paramA * paramB;
        }
    }

    public class OrdinaryClass : ITestClassInterface
    {
        public double DoSomething(double paramA, double paramB) 
        {
            return paramA * paramB;
        }
    }


    class MainClass
    {
        [STAThread]
        static void Main(string[] args)
        {
            InterceptedClass interceptedObj = new InterceptedClass();
            OrdinaryClass ordinaryObj = new OrdinaryClass();

            const int numIterations = 100000;

            CTimeMeasurement measure1 = new CTimeMeasurement();
            measure1.Start();
            //int start = Environment.TickCount;
            for( int i=0; i<numIterations; i++ )
            {
                interceptedObj.DoSomething(i,i+1);
            }
            //int stop = Environment.TickCount;
            measure1.Stop();
            Console.WriteLine(
              "{0} operations with intercepted object took {1}",
               numIterations, measure1.Duration()/*, stop-start*/ );

            CTimeMeasurement measure2 = new CTimeMeasurement();
            measure2.Start();
            //double d = 0.0;
            for( int j=0; j<numIterations; j++ )
            {
                /*d += */ordinaryObj.DoSomething(j,j+1);
            }
            measure2.Stop();
            Console.WriteLine(
               "{0} operations with simple object took {1}",
              numIterations, measure2.Duration() );

            Console.WriteLine(
              "Interception slows things down {0} times",
              measure1.Duration()/measure2.Duration() );
            Console.WriteLine(
              "It's about {0} microseconds per call",
               measure1.Duration()*1000000/numIterations );

            Console.ReadLine();
        }
    }
}

Alex Pinsker

Monday, August 22, 2005

How interception affects performance in .NET

No comments: