This was my log message before: Container created and all services registered in 51876ms.
This is my log message NOW: Container created and all services registered in 1969ms. Amazing what a difference this makes. And within a day of me reporting the issue. Castle and Ayende will both be getting a donation. From: [email protected] [mailto:[email protected]] On Behalf Of Ayende Rahien Sent: Thursday, September 17, 2009 6:13 PM To: [email protected] Subject: Re: long startup time How long does it takes now? On Fri, Sep 18, 2009 at 2:56 AM, Tyler Burd <[email protected]<mailto:[email protected]>> wrote: Indeed it is! Thank you very much, Ayende. This is a HUGE improvement! Waiting 1+ minutes to see the result of a controller change was an enormous drag on productivity. Again, thank you, and I am very impressed with the solution. From: [email protected]<mailto:[email protected]> [mailto:[email protected]<mailto:[email protected]>] On Behalf Of Ayende Rahien Sent: Thursday, September 17, 2009 5:44 PM To: [email protected]<mailto:[email protected]> Subject: Re: long startup time No, it doesn't. It is easier with code. Test code is interesting, it shows a pathological case of adding only invalid components. And the problem only show up when we have a large number of invalid components. var kernel = new DefaultKernel(); for (int i = 0; i < 500; i++) { kernel.AddComponent("key" + i, typeof(string), typeof(string)); } Before optimization, this runs in 9.2 seconds After optimization, this runs in 0.5 seconds. Raising the number of components to 5,000 leads to about: 44.5 seconds (no idea how much before optimization, don't have the patience. Using this approach, however: var kernel = new DefaultKernel(); using(kernel.OptimizeDependencyResolution()) { for (int i = 0; i < 300; i++) { kernel.AddComponent("key" + i, typeof(string), typeof(string)); } } Resolve everything in 1.9 seconds. The OptimizeDependencyResolution defer dependency resolution to the Dispose part, and allow us to both gain significant optimization in registering component while at the same time work nicely with all the usual tools and facilities. I also optimized GetHandlers(Type) and GetAssignableHandlers(Type) I think that this is good enough for now :-) On Fri, Sep 18, 2009 at 1:44 AM, Tyler Burd <[email protected]<mailto:[email protected]>> wrote: I fully accept that. Does this mean that the startable facility will not be usable with this feature? From: [email protected]<mailto:[email protected]> [mailto:[email protected]<mailto:[email protected]>] On Behalf Of Ayende Rahien Sent: Thursday, September 17, 2009 3:53 PM To: [email protected]<mailto:[email protected]> Subject: Re: long startup time Hm, that is a bit complex, though. In particular, it effect the way the startable facility behaves. I think that I will make this an opt in feature. On Thu, Sep 17, 2009 at 10:55 PM, Ayende Rahien <[email protected]<mailto:[email protected]>> wrote: Tyler, No, it isn't. Basically, I think we need to restructure the way we do this so we will defer that as late as possible (to the first resolve call, I think.). On Thu, Sep 17, 2009 at 8:09 PM, Tyler Burd <[email protected]<mailto:[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]> [mailto:[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]<mailto:[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<http://devlicio.us/blogs/tuna_toksozhttp:/tunatoksoz.comhttp:/twitter.com/tehlike> > > > > On Wed, Sep 16, 2009 at 12:59 PM, Ayende Rahien > <[email protected]<mailto:[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]<mailto:[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]> > >> [mailto: > >> [email protected]<mailto:[email protected]>] > >> On Behalf Of James Curran > >> Sent: Wednesday, September 16, 2009 10:31 AM > >> To: > >> [email protected]<mailto:[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]<mailto:[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]> > >> > [mailto:[email protected]<mailto:[email protected]>] > >> > On Behalf Of Ayende > >> Rahien > >> > Sent: Wednesday, September 16, 2009 3:00 AM > >> > To: > >> > [email protected]<mailto:[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]<mailto:[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 -~----------~----~----~----~------~----~------~--~---
