2.1.2 Performance regression in Messages

[barakka]

Hi,

I believe some recent changes in the Messages class class have reintroduced a performance problem that was previously solved.

In particular, the implementation of ContainsKey in the AbstractMap introduce by JBSEAM-2192 has been removed to solve  JBSEAM-4131.

Moreover, I believe the due to the use of ContainsKey in SeamELResolver resolveInMap, introduced for JBSEAM-3916, the performarce hit is felt on any page accessing the Messages.

As anybody else experienced the problem?

I've posted a comment to        JBSEAM-4131, should I open a separate issue for this?

Thanks,
Riccardo.

[norman]

Pete opened JBSEAM-4244 for this.  Could you explain the problem you are seeing?  I created a 7500 item messages.properties to test, and I am not observing any performance issues.

[barakka]

Hi,

well, the problem is the following: I've been profiling my application and since I switched to 2.1.2 I've noticed a huge amount of calls to Messages.AbstractMap.entrySet() and the related performance problem, as this method creates the entry set recurring all entries of all entry sets of the underlying properties maps. As a result, I get this method as the first one in the profiler in terms of consumed time.

After looking at the code, I noticed that:
1) the implementation of containsKey that was included in 2.1.1 has been removed. This implementation used the faster get() method instead of the slower entrySet() method, which is used by the default AbstractMap implementation, to determine if the key is present.

2) The method resolveInMap in the SeamELResolver is now using a call to containsKey before trying to access the value.

So, to test if my theory was correct, I've replaced the Messages class with my own, which extends the default one and adds the containsKey implementation copied from 2.1.1. Profiling results has gone back to normal.

To test, I guess you can just try to profile the execution of a containsKey on the current implementation, then put back the previous containsKey override and profile again. You should be noticing the gain.

If you need, I can retrieve the profiling results in the two cases and post it.

Thanks,
Riccardo. 

[barakka]

Uhm...

it looks like that just adding the previous implementation of containsKey creates other problems, as now I have properties which uses an EL expression pointing to messages not working any more (e.g.

org.jboss.seam.loginFailed=\#{messages[loginFailReason]}

).

I don't know why, but calling get(key) within the containsKey method makes the above case not working, even if the result from super.containsKey(key) is returned.

Hope this helps somehow.

Riccardo.

[norman]

Yes, I can believe that the changes to SeamELResolver may be slowing things down.  Looking at the code, I see an obvious way to improve that.  Unfortunately, since I don't have any code which demonstrates the performance issue you are seeing, I'm not sure how measurable any change in performance will be.

As you can see by your attempt to fix the problem, there are some very tricky EL issues in this that had to be worked through, and the error you encountered with your fix was one of them. 

[barakka]

Thanks for the fix, it works great. Have a look at the JIRA issue for more comments (and some data that shows a big the improvement is, at least with my test page).

Riccardo.

[norman]

I investigated the double interpolation issue a bit too.  That was my mistake - I mixed the code from the two prior revisions incorrectly.  I'm not quite sure why.  In any event, I've resolved that issue. 

The only remaining issue is the lack of a containsKey method. I can certainly add one, but the best I can do is call call getKeys() and test the keys directly, short circuiting the creation of the entrySet.  We can't call get(key) directly, because that could trigger an unrelated interpolation, which would clobber that state of any interpolation we happen to be in.  If that's not enough performance, then it might be possible to add code to SeamResourceBundle to do a faster containsKey.  Does your profiling suggest that this is still a hot enough area that we should try that? 

[barakka]

Hi,

well, I've tried implementing the containsKey using getKeys as you suggested and, as expected, the performance gain is very small. I guess the only way to do that fast enough would be to include a faster containsKey in SeamBundle.

I don't have a use case for that, so I can't say how much in general it could be relevant. For sure the performance gain for that specific method, and for those who use it, would be huge. My guess would be that if it doesn't take to much time, it might be worth (and if you want I can give it a try and submit a patch).

Speaking for myself, I'd rather hope that someone with inside knowledge would spend some time trying to figure out a clever way to improve the performances of the other SeamELResolver method, resolveBase. This method alone takes up 50% of the total time of my requests and I guess is  responsible for the thousands of calls to Contexts.lookupInStatefulContexts, tens of thousands calls to Component.forName and hundreds of thousand calls to BasicContext.get (for a single page request) which net time sums to the 20% of a single request time.

Riccardo.

[norman]

Riccardo Serafin wrote on Jun 17, 2009 18:56:

well, I've tried implementing the containsKey using getKeys as you suggested and, as expected, the performance gain is very small. I guess the only way to do that fast enough would be to include a faster containsKey in SeamBundle.

Implemented the faster containsKey method and improved performance for containsKey initial access from 31ms to 21ms and later calls from 4ms to <1ms. That's probably as good as we can do here.  I suppose I should commit it as having that code there shouldn't hurt anything. 

Speaking for myself, I'd rather hope that someone with inside knowledge would spend some time trying to figure out a clever way to improve the performances of the other SeamELResolver method, resolveBase. This method alone takes up 50% of the total time of my requests and I guess is  responsible for the thousands of calls to Contexts.lookupInStatefulContexts, tens of thousands calls to Component.forName and hundreds of thousand calls to BasicContext.get (for a single page request) which net time sums to the 20% of a single request time.

This is quite reasonable.  I'm not a whiz with profiling, but performance is something definitely worth spending some time on.

[swd847]

The only way I can really see to improve this is to do a lookup in the JSF RequestMap, SessionMap and ApplicationMap before going nuts looking through all the imported namespaces. This seems like a massive hack and will change semantics slightly.

The <import> tag does not appear to be documented anywhere, and users shouldn't be installing components into org.jboss.seam.whatever so we can probably get away with modifying the semantics slightly, if we were to restrict the use of namespaces to proper components (not outjected variables etc) then at startup we could figure out which components are in the imported namespaces and reduce the massively expensive loop to a simple map lookup.

What do you think? I like the second option better, off the top of my head I don't think that anything gets outjected or created via factory in any of the imported namespaces, but please correct me if I am wrong.

[barakka]

Implemented the faster containsKey method and improved performance for containsKey initial access from 31ms to 21ms and later calls from 4ms to <1ms. That's probably as good as we can do here.  I suppose I should commit it as having that code there shouldn't hurt anything. 

I'd be very happy to test it out :-).

[barakka]

The only way I can really see to improve this is to do a lookup in the JSF RequestMap, SessionMap and ApplicationMap before going nuts looking through all the imported namespaces. This seems like a massive hack and will change semantics slightly.

This is something that i don't understand and I'd be glad if you could explain it: which one of the EL resolvers in the chain is responsible to look into those Maps? I got the impression that the event, session and application scope of seam where backed by those maps, such that when seam issues the first lookupInStatefulContexts it should already find the property to be resolved if it is there (the overhead of checking if it is an instance of a component is still quite some, but at least the lookup does not escalate).

The <import> tag does not appear to be documented anywhere, and users shouldn't be installing components into org.jboss.seam.whatever so we can probably get away with modifying the semantics slightly, if we were to restrict the use of namespaces to proper components (not outjected variables etc) then at startup we could figure out which components are in the imported namespaces and reduce the massively expensive loop to a simple map lookup.

What do you think? I like the second option better, off the top of my head I don't think that anything gets outjected or created via factory in any of the imported namespaces, but please correct me if I am wrong.

From what I got looking at the code so far, it looks like a good option... but I guess the question was directed to Norman ;-)

Anyway, I will try to continue my profiling adventures today, to try to understand how many of those thousands of calls derive from the lookup into the imported namespaces.

[swd847]

I was wrong about import not being documented behavior, I was looking through an older version of the documentation.

Performance wise this is a killer, if a user adds another 10 namespaces its twice as slow again.

[barakka]

Maybe what could be done is to use the put in a map all known imported names approach first and then scan all imported namespaces as it is done now (therefore no semantic change). In this way, we should get a quite big advantage as the imported namespaces get not looked up sequentially for seam components saving a whole bunch of full scans.

In any case, I've discover part of the problem that is affecting me and it was that I had a lot of attempted resolutions for properties that were never set. I feel a bit of a fool, as this was in fact one of Dan's suggestions. I didn't notice it before, cos it was caused by some properties that we created on facelets user components we created, and that we made optional. I've spent the day finding a cleverer way to deal with this optional properties (which involved a lot of facelets inside wrestling) and now I've seen a certain improvement. Now I don't have a lot less miss from the SeamELResolver, which means that almost all properties resolutions are resolved within it.

Two things still bugs me; one of the properties that is still getting a miss from the SeamELResover is the invalid virtual property added by s:decorate. When the content is not invalid, the variable is not set but the EL that tries to evaluate it is still there in my facelets templates and creates quite some troubles. Tomorrow I'll look into s:decorate code and check if there is a way to solve this problem.

The second is that the most expensive methods are still the lookupInStatefulContexts and forName, mostly because at each page render i have an awful lot of el resolutions going on. Having a look at the behavior (from the profiler) i see that roughly half of the lookups get to the application scope. Which is strange, as most of my components are conversation scoped. So, some of this will come from real application scoped components, but many (I guess) are the results of lookup that hit the imported namespaces or that are namespaces themselves. Tomorrow I'll try to get more details, and I'll let you know.

[barakka]

So, I've digged a little more and tried to implement the approach suggested by Stuart, and this are my findings:

1) Invalid and required: there are two problems with these properties injected by seam s:decorate. The first is that to decide their value the DecorateRenderBase checks if any child UIComponent has messages, and to check that first it verifies if the child UIComponent is rendered. As in the template I have an image which is rendered only if invalid is true and an * which is rendered only if required is true, both this elements trigger an EL evaluation to understand if their rendered attribute is true, which depends on the two variables we are trying to evaluate in the first place, which results in a full lookup for an obviously missing variable. I (almost) solved this problem by setting the value of those variable before calling hasMessages. This is the relevant code in DecorateRenderBase.doEncodeBegin method:

      ...

      storeOriginalValues(storeOriginals, Contexts.getEventContext());
      
      // Set it to false in order to avoid a missing variable lookup while
      // evaluating the rendered property
      // of any child element, if this property depends on invalid.
      Contexts.getEventContext().set("invalid", true);
      Contexts.getEventContext().set("required", true);
      
      Contexts.getEventContext().set("invalid", Decoration.hasMessage(decorate, context));
      Contexts.getEventContext().set("required", Decoration.hasRequired(component, context));
      
      final boolean hasMessage = decorate.hasMessage();

      ...

This seems to work well for normal requests, but for ajax requests there is a moment when those EL expression are evaluated and the related properties are not yet set by the decorator. Which means several full scope lookup, once for each imported namespace plus the global one.
My guess is that it is related to one of the earlier JSF phases, but I've always been a bit lost about them. Any idea on how those lookups could be avoided? Notice that this affects each decorate on a form (In my case one for each form field...)

2) The imported namespaces: I believe the problem is quite relevant as I've counted 18 imported namespaces in seam alone, which means that any miss in SeamELResolver generates at least 19 full context lookups. But the problem is even worse: there are some seam components (and factories) used very often that are in the imported namespaces. One for all the messages. Notice that even if the messages map has been already created and ready in the event scope, SeamELResolver will perform several full lookups every time messages is used in an EL expression (the number depends on the position of the messages namespace in the list). On my test page I generate around 70 messages EL resolutions, which I believe is kind of normal... you do the math. However, all this was just to justify that something should be done about it.

So, I've tried with success to implement the approach proposed by Stuart. At startup, I generate map of all components and factories names belonging to imported namespaces. In the resolveBase I first check the root namespace, then check my resolution map and in case of a hit i go directly to the interested namespace. It seems to work pretty well, as now the resolveBase is responsible for only 20% total time of a page refresh (compared to 50% without the mapping).

Notice however that looking up an imported component, like messages above, still requires at least a full context lookup (the one of the root namespace), possibly two. And of course any miss still involves the 19 contexts lookups. If anyone is interested I could try to submit a patch with what I've done, and anyway I'd love to see someone from the core team address the issue.

3) One thing that bugged me in these days is that there is no (easy) way to extended the SeamELResolver or even just include a custom resolver before the Seam one (in my tests, the resolver I define in my faces-config.xml gets always added after the seam one). So, I've tried to code such an extension, to manage special properties resolutions that are either critical for seam (like the messages above) or for my application. Basically I've provided the SeamELResolver with a list of custom resolvers for special properties, which I setup with some static calls. The code seams to work, and I was able to remove some more unneeded contexts lookups.   

4) A suggestion for the performance chapter in the seam documentation: maybe it could be worth to explain that is always a good idea to specify the scope if possible and known, both in @In and in Component.getInstance, especially if the target is factory or if the scope is stateless. Not doing so might very well lead to a full scope lookup (for stateless it always does). Actually, a lot of seam core component that define and instance() method use an un-scoped Component.getInstance call, which involves a scope lookup.

Moreover, I have a bunch of factories that might return null values (on some occasions). Every time I use one of these, full lookups occur... and it gets worse if they are accessed from jsf pages (due to the imported namespaces). Is there some kind of design pattern to avoid the problem?

5) Again a suggestion, of which I'm not totally sure: seam code is full of snippets like:

      if ( !Contexts.isApplicationContextActive() )
      {
         throw new IllegalStateException("No application context active");
      }
      return (Component) Contexts.getApplicationContext().get( name + ".component" );

(this one is taken from Component.forName). I was wondering if something like:

      try
      {
         return (Component) Contexts.getApplicationContext().get(name + ".component");
      }
      catch (final NullPointerException e)
      {
         throw new IllegalStateException("No application context active");
      }

would not be faster. I know the difference is minimal but, for instance in the case of Component.forName or Init.instance, the methods get called tens of thousands of times (for each request).