[ovirt-devel] [ATTN] GWT Debug mode is now 2x faster!

From: "Vojtech Szocs" <vszocs(a)redhat.com&gt; To: devel(a)ovirt.org Cc: awels(a)redhat.com, ecohen(a)redhat.com, gshereme(a)redhat.com Sent: Wednesday, July 30, 2014 11:19:46 AM Subject: Re: GWT debug slowness. Hi Alex, (adding devel list to share it with others) I really appreciate that you took the time to analyze GWT EventBus activity! As we discussed on IRC, @ProxyEvent in AbstractSubTabPresenter is the most likely cause of overall UI slowness after successful user authentication. Fix for this should be rather easy and harmless, please add me as reviewer once you come up with the relevant patch. Another thing is "refresh on logout" for all (both) GWT applications. This is mainly due to planned SSO changes (there will be a dedicated interactive login page for entire Engine); for us it means that "login" section of all GWT applications will be unnecessary. Before that, however, we can already implement "refresh on logout". As a nice side effect, we can remove some of our infra (UiCommonInitEvent & friends) to make it more simple. Please find some more comments below (inline). Thanks, Vojtech ----- Original Message ----- > From: "Alexander Wels" <awels(a)redhat.com&gt; > To: vszocs(a)redhat.com > Cc: ecohen(a)redhat.com, gshereme(a)redhat.com > Sent: Friday, July 25, 2014 7:59:56 PM > Subject: Re: GWT debug slowness. > > On Friday, July 25, 2014 09:28:33 AM Alexander Wels wrote: > > Vojtech, > > > > I know you suggested that maybe the event bus was getting overloaded with > > events might be the cause of the slowness in the GWT debug mode. So I > > modified the event bus implementation to record the number of events, > > their > > handlers, and the occurrences of those events. > > > > This is right after the login page is loaded. > > +---------------------------------------------------+-----------+----------- > > + > > |Type |handlers |fired > > || > > +---------------------------------------------------+-----------+----------- > > + > > |event: ApplicationFocusChangeEvent: |0 |2 > > || event: LockInteractionEvent: |2 |2 > > | | event: NavigationEvent: |0 |1 > > | | event: PlaceRequestInternalEvent: |111 |1 > > | | event: ResetPresentersEvent: |1 > > | | |1 > > | | event: RevealRootLayoutContentEvent: |1 > > ||1 | > > +---------------------------------------------------+-----------+----------- > > + Just for clarification: * ApplicationFocusChangeEvent - fired by our infra whenever browser/window gains or looses focus (we use this to throttle UiCommon model refresh timers, i.e. when out of focus, lower the refresh rate) * LockInteractionEvent - fired by GWTP infra, indicates that UI interaction should be avoided because the application is currently in transition from one place to another (in practice, invisible "glass" <div> element covers the entire viewport during transition, see RootPresenter.RootView) Note: we had plans to provide some "In progress..." label (just like you see in Gmail) to make this obvious to end users, there's also RFE on this * NavigationEvent - fired by GWTP infra, it's a hook we don't use * PlaceRequestInternalEvent - fired by GWTP infra, PlaceManagerImpl fires this event to ask all proxies: "which one of you can reveal a presenter with name token xxx" (i.e. "dataCenters-clusters") Note: handler count is high because EACH presenter proxy adds handler for this event. * ResetPresentersEvent - fired by GWTP infra, after transition to new place is complete, trigger "onReset" lifecycle method on all presenters present on "reveal path" (from leaf to root) * RevealRootLayoutContentEvent - fired by GWTP infra, this makes GWTP root presenter/view reveal within the browser/window viewport > > > > This is right after you login, and the VM main tab is displayed > > +---------------------------------------------------+-----------+----------- > > + > > |Type |handlers |fired > > || > > +---------------------------------------------------+-----------+----------- > > + > > |event: UiCommonInitEvent: |715 |1 > > || event: RestApiSessionAcquiredEvent: |1 |1 > > | | event: UserLoginChangeEvent: |3 |1 > > | | event: ApplicationFocusChangeEvent: |80 |2 > > | | event: LockInteractionEvent: |2 > > | | |3 > > | | event: NavigationEvent: |0 > > ||1 | event: PlaceRequestInternalEvent: |205 > > | |2 | event: InitializeEvent: |167 > > | |170 | event: SSOTokenChangeEvent: |1 > > | |1 | event: ResetPresentersEvent: > > | ||1 > > | |1 | event: RevealRootLayoutContentEvent: > > ||1 |1 | > > +---------------------------------------------------+-----------+----------- > > + Most of these events are fired by our own infra. UiCommonInitEvent has so many handlers due to following components: * TabModelProvider (access to UiCommon models) * AbstractActionPanel (for each "action button" definition!) * UiCommandButtonDefinition (button bound to UiCommon model "command") * AbstractRefreshManager (controlling refresh of list models) * ModelBoundTab (tab's properties bound to UiCommon model properties) * AbstractActionTable (added recently, for search string change stuff) * some more classes (UserPortalConfigurator, WebAdminConfigurator, SearchPanelPresenterWidget) Each component mentioned above needs to be notified when relevant UiCommon model changes. As you might know, on each login, current CommonModel (root model) instance is thrown away (if any) and new CommonModel instance is created. CommonModel in turn creates its "child" models, which create their "child" models, etc. This is, in my opinion, one of the BIGGEST flaws of UiCommon code design; it makes models tightly coupled with all subsequent consequences. (As with any kind of design, once it's put to use on a bigger scale, it's really hard to change in a way that's consistent, safe and not too invasive.) I was, for a very long time, convinced that we can still have a nice single-page AJAX GWT UI application that doesn't need "refresh on logout", i.e. application that properly handles UiCommon. In light of upcoming SSO changes, however, we should do "refresh on logout". This will allow us to: * (future) eliminate GWT login screen entirely, in favor of SSO interactive login page * (now) eliminate complex infra (UiCommonInitEvent & friends) in order to properly use UiCommon in single-page application scenario (BTW, PlaceRequestInternalEvent handler count increased from 111 to 205, not sure what is the exact cause of this, I'd have to dig deeper into GWTP infra code.) > > > > As you can see the number of events fired is not all that high, the only > > somewhat strange thing, is that there are a huge number of > > UiCommonInitEvent handlers. Doing a quick search reveals that every tab > > provider, every refresh manager (refresh button) and a whole bunch of > > other > > widgets all have handlers, which does explain the huge number of > > handlers. Yup. All of this is needed to properly use UiCommon in single-page scenario, i.e. UI components need to be notified whenever UiCommon model instances change (typically due to UI login). If UiCommon wasn't designed to instantiate whole model tree right on successful login (replacing old instances with new ones), we wouldn't have to deal with this issue. The whole UiCommonInitEvent infra is to ensure we use UiCommon in a way it was designed to be used. > > > > In short I don't think the slowness is related to the EventBus at this > > point > > in time and I will have to look else where for the problem. > > > > To respond to myself (isn't talking to yourself a sign of insanity?). Nah :) re-thinking what you thought previously is a good thing. > I did > some profiling > while running in GWT debug mode, and I discovered the following sequence of > events > which seems to be related to the huge number of UiCommonInitEvent handlers. > > I found that most of the time was taken during the UiCommonInitEvent > firing. > which > led me to see which one of the handlers was taking so long. So I profiled > the > time each > handler took to complete. I noticed something really strange, the tab > providers all > took between 0 and 1ms. It's because TabModelProvider#onCommonModelChange is not special in any way. > But every single sub tab presenter for every single > sub tab > was taking between 500 and 3000ms depending on the presenter. It's because creation of presenter triggeres creation of view, and creation of view triggers HTML DOM operations which can be expensive, depending on the complexity of the view/HTML. It's very important to realize that presenter must be first created and bound (presenter's proxy takes care of this) and only THEN presenter is able to deal with events such as UiCommonInitEvent. @ProxyEvent causes event handler to be registered on proxy itself - whenever such event occurs, proxy will create & bind presenter and call corresponding @ProxyEvent method on presenter. This is also why you're observing 500 .. 3000ms times. > Since we have > like > 200 of those presenters, every single one of them was being > called/initialized and > taking time, even if we never used them. It turns out we had a ProxyEvent > on > AbstractSubTabPresenter, which would cause every single sub tab presenter > to > load > (since they were code splitted, this takes a lot of requests). > > @ProxyEvent > public void onUiCommonInit(UiCommonInitEvent event) { > ...initialize some handlers... > } Correct! @ProxyEvent is a "lazy" programmer's trick to ensure that presenter never misses on any event of given type. The downside is that when such event (UiCommonInitEvent) happens, possibly TONS of presenters (and associated views) will be created & bound. As we discussed, we can improve this by moving relevant code into onBind() presenter lifecycle callback. > > So what I did to solve the problem, I removed the @ProxyEvent, and renamed > it > initializeHandlers. Then instead of them being called in response to the > onUiCommonInit event, I put the call in onBind of the presenter. If I > understand the > GWTP life cycle correctly this should have the same effect as before (the > handlers are > initialized before they are needed) and thus everything should work the > same. onBind() is called once per lifetime of bound object. All presenters are singletons, so onBind() is called once in their lifetime. A common trick is to do following in onBind(): // For any future occurences of event registerHandler(eventBus.addHandler(..foo()..)); // For the first time, if needed foo(); (Assuming foo() contains init logic sensitive to given event.) > > The results that I have observed so far from these changes: > - GWT debug mode login takes ~50s instead of 4:30. > - The number of requests to the engine dropped from around 80 to around 20. > - In compiled mode the login is much much faster. > - I haven't checked the memory usage, but I am guessing it will be much > lower > with all > presenters not being in memory until they are needed. Great stuff! Maybe we could squeeze this in 3.5 too :) > > My only concern at this point, is that I am not aware of a particular > sequence that > requires the presenters to be present somewhere, and now they are not, and > something doesn't work. Communication is mostly done through events, so EventBus is essentially the only direct dependency between all presenters. In practice, there might be exceptions, but in general, events are to decouple presenters. As for your concern - I don't think we should worry about it. GWTP infra will always load presenters when they are needed (i.e. for the reveal of requested place). Our code CAN load them even earlier, if needed (like with @ProxyEvent). > In my limited testing everything worked the same as > before, > but obviously I haven't touched every single tab and sub tab. > > One more thing to note, the proxy event has been like that since before I > joined Red > Hat, so again this is NOT the cause for the recent slowdown, but something > in > the > presenters could have added some time to each of them causing the huge > number > of > them combined to have a large impact. The number of sub tabs (and associated UiCommon models) grew over time, so there's (I think) cumulative performance impact of @ProxyEvent in AbstractSubTabPresenter. Sure, there might be other bottlenecks, but we can improve this right now and gain substantial speed/performance improvement. (Great job!) > > Alexander > > > Alexander > >