[BLOSSOM-194] Blossom SpecialAttributeRequestWrapper using excessive CPU Created: 27/Oct/14  Updated: 23/Jan/15  Resolved: 14/Nov/14

Status: Closed
Project: Blossom
Component/s: None
Affects Version/s: 3.0.1
Fix Version/s: 3.0.5

Type: Bug Priority: Major
Reporter: Declan Newman Assignee: Tobias Mattsson
Resolution: Duplicate Votes: 0
Labels: support
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Red Hat Enterprise Linux Server release 6.5 (Santiago) with Java HotSpot(TM) 64-Bit Server VM (build 24.65-b04, mixed mode)


Attachments: PNG File Screen Shot 2014-10-27 at 08.55.24.png     File magnolia-module-blossom-3.0.5-BLOSSOM-194.jar    
Issue Links:
duplicate
duplicates BLOSSOM-195 Performance improvements for forward ... Closed
relation
is related to BLOSSOM-130 Nesting the same JSP + Performance im... Closed
is related to BLOSSOM-187 Performance problem related to Specia... 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   

When profiling a Magnolia public instance, we're seeing excessive calls to info.magnolia.module.blossom.support.SpecialAttributeRequestWrapper.

From a handful of requests, we see more than 18,000,000 invocations.

I have read through BLOSSOM-130, and it could be a similar problem. However, we are using Thymeleaf as opposed to JSPs.

This has the side effect of limited performance on our production system, due to a CPU bottleneck.

Please let me know if you need any more information.



 Comments   
Comment by Tobias Mattsson [ 27/Oct/14 ]

Hi Declan,

Which version of Blossom are you using?

When profiling its common that tiny methods that are called often show up as hot spots. Profilers typically supports two modes, sampling, and tracing/instrumentation. When sampling the profiler repeatedly takes snapshots of what threads are doing and will see that threads are often in these small methods and will assume that the threads are still there even though the thread might have proceeded and done other things in between snapshots. When tracing the profiler adds bytecode that records the time spent in each and every method. For small and quick methods the added code can seriously outweigh the methods real code and so will overestimate them.

That's why its hard to accurately estimate the real performance impact of these calls with a profiler.

Are there circumstances that makes the problem more noticeable?

Do you have example code that you can share that illustrates the problem?

Comment by Declan Newman [ 28/Oct/14 ]

Hi Tobias,

Thanks for coming back to me. We're using Blossom 3.0.1 alongside Magnolia Enterprise 5.2.2. The container is Tomcat 7.0.53.

We're seeing very high CPU usage when running under load. We have 2 public instances running behind a loadbalancer and see it [CPU] bottleneck (100% CPU) when hitting approx. 350 concurrent users.

The screenshot attached is taken from JProfiler running against a local instance, hitting a simple page using Sampling, and as you mention, these are the areas that are being highlighted as Hot Spots. The page we're calling is one with little additional processing over-and-above a normal page. However, there are several components making up the page.

I'd expect to see an overhead when profiling, but I was very surprised to see it hit the number of invocations that we're seeing. In total there were 63,816,916 invocations on the SpecialAttributeRequestWrapper from just a few requests. I think it's fair to say, even with the overhead of a Sampler this will be very CPU intensive (ignoring the timings).

I don't have any example code to illustrate this, other than the code itself. We'd be more than happy to share what we have directly, if it helps diagnose the problem.

Please let me know if you need more info.

Thanks,

Dec

Comment by Tobias Mattsson [ 02/Nov/14 ]

Hi Declan,

I'm testing a possible solution, would you be able to run your tests again with the attached patched jar file and share the results? It needs additional testing still so please let me know of any problems or bugs you encounter.

Comment by Declan Newman [ 03/Nov/14 ]

Hi Tobias,

Thanks for this. I will try this today and let you know the outcome.

Cheers,

Dec

Comment by Declan Newman [ 03/Nov/14 ]

Hi Tobias,

I have profiled (Sampling) using a slightly more controlled method. These are the results based on three simple pages that do not have an extensive amount of logic behind them.

I have profiled using 3.0.1 (existing), 3.0.4, and 3.0.5-194 (the jar attached). I have not included timings, as these are likely to be misleading.

I have limited the results to those that have the most invocations, represented on the right of the method name:

Blossom 3.0.1
==== 1st Request ==
SpecialAttributeRequestWrapper.getAttributeNames() - 25,949
SpecialAttributeRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 25,949
SpecialAttributeRequestWrapper$1.hasMoreElements() - 20,003
SpecialAttributeRequestWrapper$1.nextElement() - 19,646
SpecialAttributeRequestWrapper$1.findNext() - 18,767
SpecialAttributeRequestWrapper.setAttribute(String, Object) - 17,978
SpecialAttributeRequestWrapper.getAttribute(String) - 14,595
SpecialAttributeRequestWrapper.shouldMasquerade() - 2,690
SpecialAttributeRequestWrapper.setSpecialAttribute(String, Object) - 620

==== 2nd Request ==
SpecialAttributeRequestWrapper.getAttributeNames() - 43,152
SpecialAttributeRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 43,152
SpecialAttributeRequestWrapper$1.hasMoreElements() - 30,565
SpecialAttributeRequestWrapper$1.nextElement() - 20,003
SpecialAttributeRequestWrapper$1.findNext() - 19,646
SpecialAttributeRequestWrapper.setAttribute(String, Object) - 18,767
SpecialAttributeRequestWrapper.getAttribute(String) - 14,595
SpecialAttributeRequestWrapper.shouldMasquerade() - 2,690
SpecialAttributeRequestWrapper.setSpecialAttribute(String, Object) - 1,085

==== 3rd Request ==
SpecialAttributeRequestWrapper.getAttributeNames() - 72,318
SpecialAttributeRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 72,318
SpecialAttributeRequestWrapper$1.hasMoreElements() - 51,316
SpecialAttributeRequestWrapper$1.nextElement() - 20,003
SpecialAttributeRequestWrapper$1.findNext() - 19,646
SpecialAttributeRequestWrapper.setAttribute(String, Object) - 18,767
SpecialAttributeRequestWrapper.getAttribute(String) - 14,595
SpecialAttributeRequestWrapper.shouldMasquerade() - 2,690
SpecialAttributeRequestWrapper.setSpecialAttribute(String, Object) - 1,085

Blossom 3.0.4
==== 1st Request ==
SpecialAttributeRequestWrapper.getAttributeNames() - 20,018
SpecialAttributeRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 20,018
SpecialAttributeRequestWrapper$1.hasMoreElements() - 20,004
SpecialAttributeRequestWrapper$1.nextElement() - 19,647
SpecialAttributeRequestWrapper$1.findNext() - 18,768
SpecialAttributeRequestWrapper.setAttribute(String, Object) - 17,978
SpecialAttributeRequestWrapper.getAttribute(String) - 14,590
SpecialAttributeRequestWrapper.shouldMasquerade() - 2,690
SpecialAttributeRequestWrapper.setSpecialAttribute(String, Object) - 620

==== 2nd Request ==
SpecialAttributeRequestWrapper.getAttributeNames() - 30,565
SpecialAttributeRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 20,018
SpecialAttributeRequestWrapper$1.hasMoreElements() - 20,018
SpecialAttributeRequestWrapper$1.nextElement() - 20,004
SpecialAttributeRequestWrapper$1.findNext() - 19,647
SpecialAttributeRequestWrapper.setAttribute(String, Object) - 18,768
SpecialAttributeRequestWrapper.getAttribute(String) - 14,590
SpecialAttributeRequestWrapper.shouldMasquerade() - 2,690
SpecialAttributeRequestWrapper.setSpecialAttribute(String, Object) - 1,085

==== 3rd Request ==
SpecialAttributeRequestWrapper.getAttributeNames() - 48,543
SpecialAttributeRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 20,018
SpecialAttributeRequestWrapper$1.hasMoreElements() - 20,018
SpecialAttributeRequestWrapper$1.nextElement() - 20,004
SpecialAttributeRequestWrapper$1.findNext() - 19,647
SpecialAttributeRequestWrapper.setAttribute(String, Object) - 18,768
SpecialAttributeRequestWrapper.getAttribute(String) - 14,590
SpecialAttributeRequestWrapper.shouldMasquerade() - 2,690
SpecialAttributeRequestWrapper.setSpecialAttribute(String, Object) - 1,705

3.0.5-194
==== 1st Request ==
AttributeOverrideRequestWrapper.getAttributeNames() - 25,949
AttributeOverrideRequestWrapper.getAttribute(String) - 20,007
AttributeOverrideRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 20,006
AttributeOverrideRequestWrapper.setAttribute(String, Object) - 17,978

==== 2nd Request ==
AttributeOverrideRequestWrapper.getAttributeNames() - 41,152
AttributeOverrideRequestWrapper.getAttribute(String) - 30,565
AttributeOverrideRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 20,027
AttributeOverrideRequestWrapper.setAttribute(String, Object) - 20,006

==== 3rd Request ==
AttributeOverrideRequestWrapper.getAttributeNames() - 69,101
AttributeOverrideRequestWrapper.getAttribute(String) - 48,543
AttributeOverrideRequestWrapper$1.<init>(AttributeOverrideRequestWrapper, iterator) - 20,027
AttributeOverrideRequestWrapper.setAttribute(String, Object) - 20,006

Comment by Tobias Mattsson [ 03/Nov/14 ]

Thanks Declan, looks promising, I will perform some further tests on my own before releasing it.

Comment by Tobias Mattsson [ 14/Nov/14 ]

I have created BLOSSOM-195 for this and other improvements. Attached to the issue is a new JAR with the changes applied.

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