New subject: [ATTN] GWT Debug mode is now 2x faster!

Wednesday, 30 July 2014

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

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

Re: [ovirt-devel] GWT debug slowness.