Attached is the profiling screenshot for a VERY simple console app (code below). It took so long to profile that I didn't have the patience to wait until all 1000 services were registered, but this clearly shows where the problem lies.
Total calls to AddComponent: 409
Total calls to AbstractHandler.DependencySatisfied: 83,773
If I try to profile my original app, it times out and causes a profiler error
even when left overnight to finish starting up. When I stopped the profiler
after 30 minutes of running I saw over 600,000 calls to DependencySatisfied.
Am I wrong in thinking that 1000 services is not THAT many in a well designed
app? I have a large financial app that has many complicated processes, so I
split out every process into isolated services. I also use a service to
encapsulate ever query with a dedicated service interface. The number of
services registered adds up fast, but it sure seems like the right,
maintainable, and testable way to do things.
Profiled code:
var container = new WindsorContainer();
var kernel = container.Kernel;
for (int i = 0; i < 1000; i++)
{
kernel.AddComponent("key" + i, typeof(string), typeof(string));
}
Console.ReadLine();
-----Original Message-----
From: [email protected]
[mailto:[email protected]] On Behalf Of Mauricio Scheffer
Sent: Wednesday, September 16, 2009 8:28 PM
To: Castle Project Users
Subject: Re: long startup time
It's definitely the HandlerRegistered event, or more likely
AbstractEventHandler.DependencySatisfied()... here's a little test:
import System
import System.Diagnostics
import Castle.Windsor from Castle.Windsor
import Castle.MicroKernel from Castle.MicroKernel
import Castle.MicroKernel.Handlers from Castle.MicroKernel
import Castle.MicroKernel.SubSystems.Naming from Castle.MicroKernel
import Castle.MicroKernel.ModelBuilder from Castle.MicroKernel
def KernelAddComponent(k as IKernel):
for i in range(1000):
w = Stopwatch()
w.Start()
k.AddComponent("key${i}", typeof(string), typeof(string))
w.Stop()
print "${i} took ${w.ElapsedMilliseconds}"
class CustomKernel(DefaultKernel):
override def RaiseHandlerRegistered(h as IHandler):
pass
KernelAddComponent(DefaultKernel())
Change the DefaultKernel() to CustomKernel() and the perf hit goes
away.
On Sep 16, 2:00 pm, Tuna Toksoz <[email protected]> wrote:
> N! times? How?
>
> Tuna Toksöz
> Eternal sunshine of the open source mind.
>
> http://devlicio.us/blogs/tuna_toksozhttp://tunatoksoz.comhttp://twitter.com/tehlike
>
>
>
> On Wed, Sep 16, 2009 at 12:59 PM, Ayende Rahien <[email protected]> wrote:
> > IIRC, the culprit is the ComponentRegistered event, that is being raised N!
> > times
> > We had to do that when we use the AddComponent model, but with Register, we
> > can probably optimize this.
>
> > On Wed, Sep 16, 2009 at 7:54 PM, Tyler Burd <[email protected]> wrote:
>
> >> I'm not sure how feasible that idea could be. SO much of an application
> >> depends on having everything registered and ready to go before any actual
> >> services are invoked. For instance, my project uses Rhino Service Bus,
> >> which depends heavily on the GetAssignableHandlers and similar methods on
> >> the kernel. If a critical message came in and we weren't finished
> >> registering services (AKA Message Consumers), that message could be lost
> >> forever since GetAssignableHandlers would not return all of the expected
> >> handlers.
>
> >> I'd much rather have some form of lazy initialization of handlers and
> >> dependencies to amortize whatever this startup cost is, but I'm not sure
> >> right now how that might look.
>
> >> -----Original Message-----
> >> From: [email protected] [mailto:
> >> [email protected]] On Behalf Of James Curran
> >> Sent: Wednesday, September 16, 2009 10:31 AM
> >> To: [email protected]
> >> Subject: Re: long startup time
>
> >> This leads to interesting question. Since, one presumes you won't
> >> need all 1000 service immediately, could building the container be
> >> spun off as a background task? This of course would lead to some
> >> interesting race conditions, but if most of those services are for
> >> corner cases (ie, say 90% of your functionality could be handled by
> >> 10% of the services), then it just become a case of filling it in th
> >> eproper order, and releasing semaphores as you go.
>
> >> On Wed, Sep 16, 2009 at 12:05 PM, Tyler Burd <[email protected]> wrote:
> >> > I have another similar project that has around 300 services, and the
> >> average
> >> > AddComponent time there is 20ms, so that would make sense. I'll try to
> >> get
> >> > profile results today (have to buy dotTrace first).
>
> >> > From: [email protected]
> >> > [mailto:[email protected]] On Behalf Of Ayende
> >> Rahien
> >> > Sent: Wednesday, September 16, 2009 3:00 AM
> >> > To: [email protected]
> >> > Subject: Re: long startup time
>
> >> > IIRC,
>
> >> > We saw something like that previously, I think that there is an O(N)
> >> > operation in Windsor somewhere.
>
> >> > On Wed, Sep 16, 2009 at 7:19 AM, Tyler Burd <[email protected]> wrote:
>
> >> > Hi all,
>
> >> > I've got a large application that takes about 1 minute to start up. I
> >> > investigated today what could be the cause of this very long delay, and
> >> > narrowed it down to the WindsorContainer.AddComponent method. I have
> >> about
> >> > 1000 service classes, each with an interface (the service type). The
> >> > average time to call WindsorContainer.AddComponent is 52ms on my system.
> >> > 52ms * 1000 is 52 seconds, which is the vast majority of the app's
> >> startup
> >> > time.
>
> >> > My system is a Quad Core, 2.66GHz Core2 running Windows XP. The same
> >> > approximate startup time can be verified on multiple machines, servers,
> >> and
> >> > OS's.
>
> >> > Is this normal? Do I have to just bite the bullet on a long startup
> >> time,
> >> > or is there something I can do to help this?
>
> >> > Here is the block of code in a small executable I used to calculate the
> >> > times. I can provide a profile report if necessary. I normally use
> >> > AllTypes along with the fluent registration, but I wanted to get as
> >> > low-level as possible. This code outputs:
>
> >> "Called AddComponent 957 times. Average AddComponent time:
> >> 52.0267175572519ms"
>
> >> > var container = new WindsorContainer();
>
> >> > //calculates the time for each AddComponent call
>
> >> > var watch = new Stopwatch();
>
> >> > var totalAddComponentCalls = 0;
>
> >> > //keeps track of the average ms to call AddComponent
>
> >> > var allAddComponentTimes = new List<long>(1000);
>
> >> > foreach (var classType in
> >> > typeof(TheBigApplicationThingyWithAllTheServices).Assembly.GetTypes())
>
> >> > {
>
> >> > if (classType.IsInterface)
>
> >> > continue;
>
> >> > if (classType.Namespace == null)
>
> >> > continue;
>
> >> > if (!classType.Namespace.Contains("Services"))
>
> >> > continue;
>
> >> > var interfaces = classType.GetInterfaces();
>
> >> > if (interfaces.Length == 0)
>
> >> > continue;
>
> >> > var firstInterface = interfaces[0];
>
> >> > var serviceName = totalAddComponentCalls.ToString();
> >> > //simple way to get unique name
>
> >> > watch.Start();
>
> >> > container.AddComponent(serviceName, firstInterface,
> >> > classType);
>
> >> > watch.Stop();
>
> >> > allAddComponentTimes.Add(watch.ElapsedMilliseconds);
>
> >> > watch.Reset();
>
> >> > ++totalAddComponentCalls;
>
> >> > }
>
> >> > var avgAddCompTime = (from ms in allAddComponentTimes select
> >> ms).Average();
>
> >> > Console.Out.WriteLine(string.Format("Called AddComponent {0} times.
> >> Average
> >> > AddComponent time: {1}ms", totalAddComponentCalls, avgAddCompTime));
>
> >> --
> >> Truth,
> >> James
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Castle Project Users" group.
To post to this group, send email to [email protected]
To unsubscribe from this group, send email to
[email protected]
For more options, visit this group at
http://groups.google.com/group/castle-project-users?hl=en
-~----------~----~----~----~------~----~------~--~---
<<attachment: lotsofservices_profile.GIF>>
