Tyler, When you profiled your app, was the VS debugger attached? I'm asking because there are known bugs in the VS debugger that slows down the profiling considerably. If it was attached, try to profile your app without having the debugger attached and see if it makes a huge difference.
Cheers John On Sep 18, 3:09 am, Tyler Burd <[email protected]> wrote: > 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://twitt... > > > 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 > > > > lotsofservices_profile.GIF > 44KViewDownload --~--~---------~--~----~------------~-------~--~----~ 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 -~----------~----~----~----~------~----~------~--~---
