[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: |
|
||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||
| 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 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 ==== 2nd Request == ==== 3rd Request == Blossom 3.0.4 ==== 2nd Request == ==== 3rd Request == 3.0.5-194 ==== 2nd Request == ==== 3rd Request == |
| 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 |