[BLOSSOM-130] Nesting the same JSP + Performance impact Created: 13/Sep/13  Updated: 25/Jul/16  Resolved: 23/Jan/15

Status: Closed
Project: Blossom
Component/s: None
Affects Version/s: 2.0.1, 3.0
Fix Version/s: 2.0.2, 3.0

Type: Bug Priority: Neutral
Reporter: TLN Assignee: Tobias Mattsson
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File BlossomDispatcherServlet.java     Text File IncludeRequestWrapper.java     Text File SimulatedDispatchRequestWrapper.java     Text File SpecialAttributeRequestWrapper.java    
Issue Links:
relation
is related to BLOSSOM-194 Blossom SpecialAttributeRequestWrappe... Closed
is related to BLOSSOM-187 Performance problem related to Specia... Closed
is related to BLOSSOM-195 Performance improvements for forward ... Closed
Template:
Acceptance criteria:
Empty
Task DoD:
[ ]* Doc/release notes changes? Comment present?
[ ]* Downstream builds green?
[ ]* Solution information and context easily available?
[ ]* Tests
[ ]* FixVersion filled and not yet released
[ ]  Architecture Decision Record (ADR)
Bug DoR:
[ ]* Steps to reproduce, expected, and actual results filled
[ ]* Affected version filled
Date of First Response:

 Description   

The problem I'm going to describe is a little complex and seems to have enough potential to cause you some headache just to understand what's going on, not to mention any attempts to fix it safely.
It's unlikely you'll understand it in just a few minutes, but please try to dig in it, it seems to point to a notable performance implication at the very least, and a functional bug in any case.

The original reason why I investigated on this problem was that I usually want to use the same JSP for most of my areas (a 3-liner that simply iterates over all components in the area and displays them one by one).
However each time I try this kind of thing, embedding the file named componentIterator.jsp twice in the hierarchy of components and areas, I get an exception saying something like this:

javax.servlet.ServletException: File "/startPageSlider" not found.

This is the functional bug I mentioned above.
I spent hours trying to figure out how Blossom is even getting the idea to look for a file named "/startPageSlider" which is the request mapping of the component containing the area and shouldn't have much to do with the path of the JSP rendering the area. And even if it did have anything to do with it, ... why is Blossom trying to look for an actual file there, and why only under these conditions (two nested areas using the same JSP)?

While investigating on this I soon came across the class

info.magnolia.module.blossom.support.SpecialAttributeRequestWrapper

which seems to be the culprit in at least two ways.

The main problem that became apparent and which I'm going to mention first is that the two methods getAttribute() and shouldMasquerade() create huge recursion stacks in real life because they call each other back and forth all the time. Granted, shouldMasquerade() calls the super version, so it seems harmless at first glance, but since that one in turn calls the getAttribute() of the parent request object, which is usually another instance of SpecialAttributeRequestWrapper, the result is a huge "explosion" of requests from getAttribute() to shouldMasquerade() and from shouldMasquerade() back to getAttribute() and so on. This effect is even aggravated by two factors:
1. Even when shouldMasquarade() has already determined the result of a super.getAttribute(xxx), the calling getAttribute(xxx) calls super.getAttribute(xxx) again, causing another cycle through a dozen to a couple of hundreds of calls of getAttribute() and shouldMasquarade() back and forth.
2. shouldMasquarade() doesn't just check the attribute at hand for modifications but ALL attributes, causing up to 15 calls to getAttribute() from each single call to shouldMasquarade(). (I'm not sure this in itself is intended because shouldMasquarade() isn't using its method argument, which it probably should do.)

To verify what I'm saying, please do the following:
1. Create some simple hierarchy of areas and components, something like this:
page (p.jsp) -> area (a1.jsp) -> component (c1.jsp) -> area (a2.jsp) -> component (c2.jsp) -> area (a3.jsp) -> component (c3.jsp)
and create a page where this structure is populated with actual instances.
(Two or three component levels are sufficient to demonstrate the problem, but it'll really explode if you have more than three levels since the problem has exponential complexity.)
2. Now just create some simple log statements in the source code to log how many times you're iterating over the specialNames in class SpecialAttributeRequestWrapper within just one page request, i.e. insert a log statement in getAttribute() and one in shouldMasquarade().
3. Then run the page and watch the log.
4. You will be surprised by the hundreds of iterations/recursive calls there, given this simple page configuration. And you might note you're just computing the same values again and again, visiting the same recursion branches again and again.

The performance implications should be obvious, it's a huge waste of CPU like this. And it makes it really hard to understand, to debug, and to maintain, too.

I tried to find out WHY the class was coded the way it is, and to be frank, I still have no idea. It just doesn't seem to make any sense to me, and the behaviour at hand suggests that some error in reasoning was involved when coding it like it is, because I just can't believe it was wanted to behave like this.
Since I don't understand the class (and didn't manage to extract the intended behaviour in the first place), I'm sorry I don't have a fix or suggestion.

At least I checked the sources in tag "magnolia-module-blossom-3.0-alpha1" before filing this bug. Class info.magnolia.module.blossom.support.SpecialAttributeRequestWrapper doesn't seem to be modified at all from the version I am using, so the problem should still be there.

Now, back to the beginning. The bug with the nested areas referring the same JSPs where the page request suddenly fails with a weird exception originates from line 104 in SpecialAttributeRequestWrapper.java where it says:

if (localValues[i] != null && !ObjectUtils.equals(super.getAttribute(specialNames[i]), originalValues[i])) {

This line of code is executed dozens or hundreds of times per request and compares many things from the different processing stages in all conceivable combinations, so at one point it also compares the name of the JSP file name attached to one area with the JSP file name attached to the other area.
If there is a difference, shouldMasquarade() returns false, so there is no masquarading and the correct JSP path is ultimately used and the page is rendered correctly.
If however there is no difference, shouldMasquarade() returns true, so the correct JSP path which would make the page to be rendered correctly is masked by a value that doesn't work ("/startPageSlider" in my case, as said in the exception mentioned earlier).
I'm 99% sure that this behaviour is a side effect of the problems mentioned earlier with this class and is not based on any logical or functional requirement as such.

I hope my effort is helping you to develop Blossom further. Thank you.



 Comments   
Comment by TLN [ 20/Sep/13 ]

Others seem to have the same problem:
http://forum.magnolia-cms.com/forum/thread.html?threadId=c7819b82-fb26-4a60-86a6-f46c8cd58d1d

Comment by Tobias Mattsson [ 20/Sep/13 ]

Thanks, I'm troubleshooting this one, will get back to you.

Comment by Tobias Mattsson [ 01/Oct/13 ]

Let me explain what this class does. SpecialAttributeRequestWrapper serves as a base class for IncludeRequestWrapper and ForwardRequestWrapper. These are used to simulate include and forward dispatches. They modify getRequestURI(), getContextPath(), getServletPath(), getPathInfo() and a number of attributes to achieve this. They need to do fulfil the requirements in the servlet specification and do this in a way that doesn't interfere with the servlet container, be it Tomcat, Jetty or something else.

They're used in BlossomDispatcherServlet when its invoked from the rendering engine, via BlossomTemplateRenderer.

To understand the complexity you need to understand how a servlet container implements forwards and includes. As already stated the request object changes when these happens. The request object is actually a chain of wrappers, the first object in the chain is provided by the servlet container and the application is free to add as many as it needs in front of it as the filter chain progresses. When the application does a forward or an include, the servlet container does NOT add a wrapper to the front of the request chain. Instead it adds it near the start. Usually after any other request objects from the container and before any added by the application.

[servlet container request objects][application request objects]

Tomcat adds a request object for each forward and include, Jetty however has a single request object that it reconfigures each time.

Therefore SpecialAttributeRequestWrapper has to check what happens behind it to know if it should masquerade or not. It has to check every time it's called because it can't know or observe when something changes behind it. It also has to check if any of the attributes changed behind it. It is not enough to check only if the request attribute its being queried for has changed (in the case of getAttribute()).

I don't think that the complexity is a substantial performance problem.

There is indeed a problem with nesting the same area jsp multiple times. I haven't come up with a solution that solves it adequately yet.

The workaround of using dedicated JSPs for areas solves the issue for the time being.

I will continue to look for a solution. A solution that can handle the case of an area having an area where both use the same JSPs.

Comment by TLN [ 01/Oct/13 ]

Thanks for getting back on this with this detailed explanation. I must admit I still haven't completely understood why the masquerading has to be conditional, but I'm getting an idea that it has to be because JSPs may perform includes outside of the Blossom framework with conventional tags (<%@include and <jsp:include), and Blossom should continue to work correctly also in the included file, even if the servlet container didn't chain the sub-request at the end of the request chain. That's why you have to notice changes in the request context as they happen at the beginning of the request chain when the servlet container adds new requests there.
Okay, this is very tricky.
I will contemplate on this, too, because after many hours of stepping through this with the debugger I also have an idea how awfully complex it is, but I also have gotten a feeling about how things work under the hood (only on Tomcat though), and perhaps I can give some useful input. I wouldn't bet on it though.

In the meantime the original problem has extended beyond area JSPs to component JSPs as well. My current project has to use a toolbox of very simple but very versatile components that can be nested in many conceivable ways, so you might have a column component that has a frame component nested with several smaller frame components in it, each with other components (images, texts, etc.). Now, the problem is also present with nesting a frame in a frame (just to give one example), and here it's not easily possible to work with several JSP files containing the same code. Neither do I know how components will be nested later, nor the number of levels I need to be safe. And even if, ... I can't have each of my JSP files in ten or twenty copies in my project without messing it up forever.

This really got me rather desparate at some point because it was so horribly difficult to find a workaround. I tried tricking Blossom into thinking the same JSP was several different files by returning different view names, one time "components/frame", another time "components/./frame", just as an example. But, ... unfortunately Tomcat canonicalizes JSP paths before they actually get in effect causing the bug. To cut it short, I spent many hours on this, testing many, many ideas (some of them actually really crazy), and none of them worked, and I was just about to give up.

Yet, finally I found a solution that seems to be working on Tomcat on Windows at least (has yet to be tested on Linux for possible problems due to user rights). It's not a perfectly clean approach, that's why I hesitated to think in this direction for quite some time. But I want to share it with you and others, perhaps it will help someone:

The basic idea is to have Spring inject a subclass of info.magnolia.module.blossom.view.TemplateViewResolver in the project instead of the default one you're providing. The special implementation returns instances of a special subclass of info.magnolia.module.blossom.view.TemplateView. The instances of this subclass keep track of the JSP files already in use in the request chain (using ThreadLocal to get it done without having to bother about traversing the request chain each time). If a duplicate JSP include is about to happen, the view creates a copy of the JSP file in the same directory on the disc (i.e. it copies request.getServletContext().getRealPath(sourceJSPPath) to request.getServletContext().getRealPath(targetJSPPath) if the copy isn't existing yet) and redirects the include to the copy, so no collision will occur.
This works well in a development environment, but by the approach just described the views have become mutable, so occasional problems are up in production due to the caching:
The Blossom view resolver extends org.springframework.web.servlet.view.AbstractCachingViewResolver, and it caches views across threads, so if one of my special views directs the request to a particular JSP file due to the needs of one thread, another thread using the same view instance from the same cache at the same time may experience problems (JSP collision). I could synchronize this in my view class as a quick'n dirty solution, but it would kill performance especially under high load. So I guess I have to override org.springframework.web.servlet.view.AbstractCachingViewResolver#resolveViewName(String, Locale) to get an implementation that uses separate caches for each thread.

If solving the problem is too complicated with a clean and proper solution and once my workaround is tested better, I will share the code here.

Thanks again for your concern and your continuous efforts on Blossom in general and in this instance. It's a great framework, and I'm praying for a solution here that will make it even more useful in many scenarios.

Comment by Tobias Mattsson [ 02/Oct/13 ]

A simpler option would be to use freemarker for areas and components that can be nested.

Comment by TLN [ 02/Oct/13 ]

That's probably true, but I don't know Freemarker, and from what I've seen I'd prefer Blossom/JSP as the templating engine of choice in the project. Magnolia + Blossom is such an awesome combo (really, congratulations, I don't defend frameworks easily, but with this one I do!). I'd rather invest my time into finding a good a solution here than to learn Freemarker.

Right now I'm quite sure there is a clean workaround when you modify the Blossom source code just a little bit. For instance, if you're really just interested in what's happening in the requests of the servlet container, info.magnolia.module.blossom.support.SpecialAttributeRequestWrapper#shouldMasquerade() could stop relying on super.getAttribute() and rather traverse back the chain first to find the first request in the chain that's not an instance of info.magnolia.module.blossom.support.SpecialAttributeRequestWrapper and call getAttribute() on that one instead. Not only would this solve the performance issue I brought up (I still think it's there) but it should also fix the nesting bug or at least change the scenario considerably so that a solution to the nesting bug is easier to find.

Also, if this shouldn't be an option, you could add additional markers to your requests (setAttribute("marker", markerSpecificToThatOneTimeAParticularJSPIsGettingIncluded)), so that shouldMasquerade() could test these markers to prevent it from getting confused by the same JSP several times in the chain. If you know what I mean. It's a little hard to explain.

Comment by Tobias Mattsson [ 02/Oct/13 ]

I have attached two files, could you test them in your project and see it they solve your problem?

Comment by TLN [ 02/Oct/13 ]

Indeed, they do! Thank you so much, Tobias. I checked both areas and components, they all work well with your classes, even when nesting them wildly.
If I disable the new code (just to make sure), the exceptions are back once a particular JSP is on the rendering stack twice.

Do you recommend using the changed classes already, or were they just a first test, and I should wait for an improved/tidier version?

Comment by Tobias Mattsson [ 03/Oct/13 ]

These classes are going into the next release, and will be backported to 2.0.x. Until they're releases you can keep using them.

Thanks for reporting this issue, and for your thorough analysis, i appreciate how much time you've committed to this.

Cheers, Tobias

Comment by TLN [ 04/Oct/13 ]

Now that you said it was complete I looked into your solution, and I must admit I like its elegance, and logically it should have solved the problem thoroughly.
Thank you very much again. I'm very happy you found something simple.

Let me point you to the performance problem once again with some numbers to stress the significance better and to make sure you don't miss my point completely:

This is how I temporarily modified your fixed SpecialAttributeRequestWrapper:

    ...

    @Override
    public Object getAttribute(String name) {
        if (enabled) {
            for (int i = 0; i < SPECIAL_ATTRIBUTE_NAMES.length; i++) {
                count();
                if (localValues[i] != null && SPECIAL_ATTRIBUTE_NAMES[i].equals(name)) {
                    if (shouldMasquerade(name)) {
                        return localValues[i];
                    } else {
                        break;
                    }
                }
            }
        }
        return super.getAttribute(name);
    }

    protected boolean shouldMasquerade(String name) {
        for (int i = 0; i < SPECIAL_ATTRIBUTE_NAMES.length; i++) {
            count();
            if (localValues[i] != null && !ObjectUtils.equals(super.getAttribute(SPECIAL_ATTRIBUTE_NAMES[i]), originalValues[i])) {
                return false;
            }
        }
        return true;
    }
	
    private static long counter=0;
    private static void count()
    {
        counter++;
        if (counter%100==0)
        {
            System.out.println("############# counter: "+counter);
        }
    }

    ...

I.e. I added the new method count() and two calls to this method.

Now I start the app server (counter==0 then) and open one typical magnolia+blossom page from my project (just one page opened just once). It's neither artificially simple nor artificially complex, it's really just an average page with about 15 components on it.

Without your latest bugfix the counter ended at an incredible 1031600 (more than a million!)
With the bugfix this value has improved indeed, but it's still 178000.

Given the simple setup I think this number is too high. I agree, modern processors and architectures perform very well with such loops compared to former times, but given your skill and feeling for complex computer science challenges seeing this thing probably hurts you as much as me and it'll naturally make you think for a better approach.
(I also repeat: The complexity of the current implementation is exponential in a very nasty form, so with each additional nesting level the number I quoted above multiplies, and it might reach a million and more very easily again if I change my page a little bit.)

I already noticed a great performance shift through your bugfix, and I'm sure this can be improved even more by finding a more efficient algorithm (or a more friendly complexity type like quadratic or logarithmic for that matter) for getting the challenges done which you're successfully tackling with the current implementation already.

Comment by Tobias Mattsson [ 04/Oct/13 ]

The way it works now is you'll have one ForwardRequestWrapper and then a number of IncludeRequestWrapper depending on how deep in the hierarchy you are. Only the last one is enabled. The ForwardRequestWrapper adds a certain cost, the last one also adds a cost, the ones in between have very little cost since all they do is check a flag and then delegate backwards. The deeper you get you will see this cost being added each time, linearly. When a second, third and so on IncludeRequestWrapper is added you will NOT see more calls to your counter.

The complexity is linear since time spent is increased by a constant amount as more disabled IncludeRequestWrappers are added.

I've done measurements on my MacBook Pro and see these timings:

With the fix in place and 4 wrappers applied (2 disabled) I'm measuring a call to getAttribute at 181 nanoseconds (time spent in container wrappers subtracted).

The ForwardRequestWrapper adds 51 nanoseconds.
The first IncludeRequestWrapper adds 76 nanoseconds.
Adding a disabled IncludeRequestWrapper adds 27 nano seconds to each getAttribute call.

The formula is hence:

Level 1 : 51 ns.
Level 2 : 51 + 76 ns.
Level 2+N : 51 + 76 + N * 27 ns.

Linear.

Having said that I am still looking for a simpler solution. I don't see the current implementation as a performance problem.

Comment by TLN [ 04/Oct/13 ]

My guess was that these high numbers (even with the enabled/disabled fix still 178000 in my example) are mostly fueled by a request chain after all requests have been enabled again. I wouldn't presume that calls to getAttribute() happen only while RequestDispatcher.include() is handling things or that all references to the end of the chain are lost forever right after RequestDispatcher.include() finishes (there may be surrounding methods calling getAttribute(), too), but obviously I'm not as familiar with these things as you are.

Or let's put the times you measured aside for a second and let me ask you: How do you explain my counter in the hundreds of thousands after just one request? I may have been wrong assuming it was still exponential as it used to be, but if it's not exponential anymore the counter I got is very surprising to me. And even if it's linear, ... isn't 178000 iterations through these loops still a noteworthy waste of CPU cycles, irrespectively of the time that is spent in this?

If you are right and it's really just a few nanoseconds, I understand it's not highest priority to you, and I don't want to be nagging.
But as a developer I can't help but raise my eyebrows if a simple CMS website iterates through some kind of loop many thousand times. You probably understand that I brought it up. If you're sure it's not a problem, ... okay, I trust you. You still have much more insight into all of this.

Thanks for your professional approach to this. I was really excited to see this.

Comment by Tobias Mattsson [ 10/Oct/13 ]

I have attached the simpler solution I've been working on, it needs to be thoroughly tested in all the major containers before it could go in. Just in case you want to test it out.

I've measured it to 8 nanoseconds per call when faking only a forward, and 16 nanoseconds when faking a forward and any number of includes. After the first include there's no extra time spent, so its constant after the first include.

Comment by TLN [ 10/Oct/13 ]

I will certainly help you test it by developing with the new classes until I encounter any problems (using Tomcat 7 here).
One question though: Do I have to keep your previous solution intact when adding the new classes to the project, or do the new classes replace it?

Comment by Tobias Mattsson [ 10/Oct/13 ]

Thanks! The new classes replaces the old ones.

Comment by TLN [ 10/Oct/13 ]

I can't start testing yet, getting 2 compiler errors:

info\magnolia\module\blossom\render\BlossomDispatcherServlet.java:77: error: getHandlerAdapter(Object) in DispatcherServlet cannot implement getHandlerAdapter(Object) in BlossomDispatcher
public class BlossomDispatcherServlet extends DispatcherServlet implements BlossomDispatcher, BeanFactoryPostProcessor {
  attempting to assign weaker access privileges; was public
info\magnolia\module\blossom\render\BlossomDispatcherServlet.java:146: error: method does not override or implement a method from a supertype
    @Override

The second error refers to method executeChain()

Comment by Tobias Mattsson [ 11/Oct/13 ]

Should work with latest sources from master (3.0.1-SNAPSHOT) and 2.0.x branch (2.0.2-SNAPSHOT).

Comment by TLN [ 22/Oct/13 ]

We may be going a little bit off-topic, but I really want to help you test your solution, and I'm sorry I'm still not getting it compiled.
I downloaded the branch, at least I think the sources you just mentioned, from http://git.magnolia-cms.com/gitweb/?p=modules/blossom/blossom.git;a=commit;h=b303a993e0ea533b8cc354598e2f83fb43d65a1e
Trying to compile it it throws the following error:

The project info.magnolia:magnolia-module-blossom:2.0.2-SNAPSHOT (C:[...]\blossom-b303a99-Bug130\pom.xml) has 1 error
Non-resolvable parent POM: Failure to find info.magnolia:magnolia-parent-pom-community-module:pom:24 in http://repo.maven.apache.org/maven2

I have to admit I'm not so much a Maven expert. I just opened the snapshot in Netbeans, it obviously used the pom.xml that was there, I didn't configure anything on top. But I can't resolve/download the dependencies, and it doesn't compile.
Speaking of it, ... I'm using Blossom 2 with Magnolia 4.5.11, and Magnolia 4.5.11 ships with Spring 3 in the 'lib' directory. Your Blossom module, however, seems to be using Spring 2, which might explain the second compiler error I got earlier.

Edit: Thinking about it: I'm using the 'lib' directory as a colleague has prepared it for our current project. Spring 3 may not be included in the Magnolia 4.5.11 distribution at all, but he added it himself. In either case it would be great if Blossom could keep working with Spring 3.

To summarize this I must say I'm a little bit lost here. I'm not getting the pieces connected so that I can compile and integrate your snapshot into my current project. Am I missing anything obvious?

Comment by Tobias Mattsson [ 22/Oct/13 ]

Blossom 2.x is compiled against Spring 2.5 because that's the lowest supported version. It will work fine with Spring 3.

Spring is not included in Magnolia. Blossom declares the Spring dependencies as provided, which means that they're not included in your project automatically, they need to be specified explicitly. Your colleague have decided for Spring 3 when he did this.

To compile it you need to follow the instructions on http://documentation.magnolia-cms.com/display/DOCS/Maven+init.

Comment by Jan Haderka [ 08/Dec/14 ]

Any reason for reverting copyright in affected files back to 2012?

Comment by Tobias Mattsson [ 08/Dec/14 ]

Not seeing it, which commit is this?

Comment by Jan Haderka [ 09/Dec/14 ]
/**
- 	 * This file Copyright (c) 2010-2013 Magnolia International
+	 * This file Copyright (c) 2010-2012 Magnolia International
	 * Ltd.  (http://www.magnolia-cms.com). All rights reserved.

... in IncludeRequestWrapper ... first file in cumulative change view (the git-code-review tab on top of the issue).

Comment by Tobias Mattsson [ 09/Dec/14 ]

How weird, not seeing it in GitX, with git show or on gitweb. Suspect the cumulative change view includes one commit too many.

Comment by Jan Haderka [ 25/Jul/16 ]

Bulk close of all old resolved tickets.

Generated at Sun Feb 11 23:30:26 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.