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>
> 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
>
>
