Skip to main content

When all the little things sum up

Posted by rah003 on February 1, 2013 at 4:20 AM PST

Sometimes, life drops a house on your code. Sometimes, it's flying monkeys. Most of the time though, the damn stuff just stops working and it's nothing so obvious as being crushed by a Kansas farmhouse or being carried away by winged primates.

'The Monkeys caught Dorothy in their arms and flew away with her' – Illustration by William Wallace Denslow from 'The Wonderful Wizard of Oz' by L. Frank Baum. Public Domain.

For this last common case, there are a good number of great tools to help you out. JMeter may help you to reproduce the conditions under load, while profilers like JProfiler and VisualVM may give you insight into what is going on inside the code. However, there are cases when you can't (or don't want) to use these tools – maybe you can't get them in the environment where issue occurs or perhaps the instrumentation they perform obscures the problem. If this happens and you're running Magnolia CMS, there are built-in tools that can help you track down the cause.

DumpHeadFilters

For very basic info about your system, it might be enough to use DumpHeadersFilter to just know what is hitting the server and with what kind of params.

2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 uri: /magnoliaAuthor/demo-project/resources/templating-kit/themes/
    pop/css/print.2013-01-29-13-18-14-561.cache.css
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 session: true
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 parameters:
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 method: GET
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: host=localhost:8080
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: user-agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2)
    AppleWebKit/536.26.17 (KHTML, like Gecko)
Version/6.0.2 Safari/536.26.17
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: accept=text/css,*/*;q=0.1
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: cache-control=max-age=0
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: referer=http://localhost:8080/magnoliaAuthor/demo-project.html
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: accept-language=en-us
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: accept-encoding=gzip, deflate
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: cookie=JSESSIONID=A3B6DA6F1647E20C842863B99124FED4
2013-01-31 16:09:05,676 INFO  info.magnolia.debug:
    61 header: connection=keep-alive
2013-01-31 16:09:05,681 INFO  info.magnolia.debug:
    61 response status: 200
2013-01-31 16:09:05,681 INFO  info.magnolia.debug:
    61 response length: 903
2013-01-31 16:09:05,681 INFO  info.magnolia.debug:
    61 response mime type: text/css;charset=UTF-8
2013-01-31 16:09:05,681 INFO  info.magnolia.debug:
/magnoliaAuthor/demo-project/resources
/templating-kit/themes/pop/css/print.2013-01-29-13-18-14-561.cache.css
response: X-Magnolia-Registration = Registered

PerformanceTestFilter

Another option is enabling PerformanceTestFilter to see how long individual operations take to perform. This is particularly useful when dealing with the dynamic filter chain (which allows you to add, remove and even re-order filters at runtime) as it lets you see how time each filter in the chain needs for execution.

2013-01-31 19:42:23,896 INFO  info.magnolia.debug:
/auth/demo-project/resources/templating-kit/themes/pop/img/bgs/submit.png : performance: 4
2013-01-31 19:42:23,896 INFO  info.magnolia.debug:
/auth/demo-project/resources/templating-kit/themes/pop/img/bgs/nav-global-line.png : performance: 4
2013-01-31 19:42:23,896 INFO  info.magnolia.debug:
/auth/demo-project/resources/templating-kit/themes/pop/img/bgs/dotted-line.png : performance: 4
2013-01-31 19:42:23,897 INFO  info.magnolia.debug:
/auth/demo-project/resources/templating-kit/themes/pop/img/bgs/nav-global.png : performance: 5
2013-01-31 19:42:23,898 INFO  info.magnolia.debug:
/auth/demo-project/resources/templating-kit/themes/pop/img/icons/sprites.png : performance: 6
2013-01-31 19:42:23,898 INFO  info.magnolia.debug:
/auth/demo-project/resources/templating-kit/themes/pop/img/bgs/transparent.png : performance: 6
2013-01-31 19:42:23,946 INFO  info.magnolia.debug:
/auth/.resources/magnolia-templating-editor/img/bars/mgnl-bar.png : performance: 1
2013-01-31 19:42:23,947 INFO  info.magnolia.debug:
/auth/.resources/magnolia-templating-editor/img/preview/down-arrow-white.gif : performance: 1
2013-01-31 19:42:23,947 INFO  info.magnolia.debug:
/auth/.resources/magnolia-templating-editor/img/bars/mgnl-bar.component.png : performance: 2
2013-01-31 19:42:23,947 INFO  info.magnolia.debug:
/auth/.resources/soft-locking/icons/23/show_collaborating_users.png : performance: 2
2013-01-31 19:42:23,948 INFO  info.magnolia.debug:
/auth/demo-project/resources/templating-kit/themes/pop/img/bgs/teaser-paging.png : performance: 3
2013-01-31 19:42:23,948 INFO  info.magnolia.debug:
/auth/demo-project/resources/templating-kit/themes/pop/img/bgs/prev-next.png : performance: 3
2013-01-31 19:42:23,992 INFO  info.magnolia.debug:
/auth/.resources/magnolia-templating-editor/img/bars/mgnl-bar.area.end.png : performance: 2
2013-01-31 19:42:23,992 INFO  info.magnolia.debug:
/auth/.resources/magnolia-templating-editor/img/bars/area.buttons/delete.png : performance: 2
2013-01-31 19:42:23,992 INFO  info.magnolia.debug:
/auth/.resources/magnolia-templating-editor/img/bars/area.buttons/edit.png : performance: 2
2013-01-31 19:42:23,993 INFO  info.magnolia.debug:
/auth/resources/templating-kit/js/shims/form-native-fix.js : performance: 3

Using track() in the filter chain

Sometimes you run into even more complicated cases. I was looking over one such case recently and realized that I need to track the number of calls made to method executed very deep down in the hierarchy on a per-request basis. Analyzing this with JProfiler was very cumbersome. While I could easily see the total time required for the complete operation and see where each call came from, what I needed to know what request each thread was executing and how long that took. To get the data I needed in this case, I wrote an extra filter that analyzes the stacktrace and provides aggregated info about the call hierarchy at the end of fulfilling each request. With that info at hand, finding out the problem and solving it was a breeze.

I hope this approach is useful to others trying to find excessive invocations of any method. Like the filters above, you need need to enable the CallTrackingFilter in the filter chain. You will also need to call the track() method at the place where you want to see aggregated info from all the invocations. Once you do so, here is the code that will collect the trace info for you:


    public void track() {
        StackTraceElement[] trace = new Exception().getStackTrace();
        int count = 0;
        for (StackTraceElement el : trace) {
            String strTrace = el.toString();
            Map traceMap = traces[count];
            int nr = 1;
            if (traceMap.containsKey(strTrace)) {
                nr += traceMap.get(strTrace);
            }
            traceMap.put(strTrace, nr);
            count++;
            if (count >= traces.length) {
                break;
            }
        }
    }

and here is the piece that will actually print it out later:


    public String toString() {
        StringBuilder sb = new StringBuilder();
        sb.append("Total calls: ").append(totalCalls).append(", total time: ").append(totalTime).append("\n");
        String ind = "  ";
        for (Map trace : traces) {
            for (Map.Entry entry : trace.entrySet()) {
                sb.append(ind).append(entry.getValue()).append(";").append(entry.getKey()).append("\n");
            }
            ind += "  ";
        }
        return sb.toString();
    }

Finally, here is the output that shows the aggregated stacktrace from all invocations including counts of each execution path. With this information in hand, you can find (and hopefully fix) excessive calls.


2013-01-30 15:04:45,416 INFO  info.magnolia.debug:
/magnoliaAuthor/demo-project.html:inits: 54, total calls: 14714, total time: 191947000
    14714;info.magnolia.debug.TrackingStatus.track(TrackingStatus.java:82)
      14714;info.magnolia.cms.util.SimpleUrlPattern.match(SimpleUrlPattern.java:212)
        4;info.magnolia.voting.voters.URIPatternVoter.boolVote(URIPatternVoter.java:60)
        4;info.magnolia.cms.beans.config.DefaultVirtualURIMapping.mapURI(DefaultVirtualURIMapping.java:56)
        14706;info.magnolia.cms.security.PermissionImpl.match(PermissionImpl.java:89)
          4;info.magnolia.voting.voters.AbstractBoolVoter.vote(AbstractBoolVoter.java:62)
          4;info.magnolia.cms.beans.config.VirtualURIManager.getURIMapping(VirtualURIManager.java:107)
          14706;info.magnolia.cms.security.AccessManagerImpl.getPermissions(AccessManagerImpl.java:87)
            4;info.magnolia.cms.filters.VirtualUriFilter.getURIMapping(VirtualUriFilter.java:100)
            14706;info.magnolia.cms.security.AccessManagerImpl.isGranted(AccessManagerImpl.java:64)
            4;info.magnolia.voting.DefaultVoting.vote(DefaultVoting.java:56)
              14706;info.magnolia.cms.core.Access.isGranted(Access.java:63)
              4;info.magnolia.cms.filters.AbstractMgnlFilter.bypasses(AbstractMgnlFilter.java:121)
              4;info.magnolia.cms.filters.VirtualUriFilter.doFilter(VirtualUriFilter.java:66)
                3742;info.magnolia.cms.core.DefaultHierarchyManager.isGranted(DefaultHierarchyManager.java:422)
                4;info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:88)
                47;info.magnolia.cms.core.DefaultHierarchyManager.isExist(DefaultHierarchyManager.java:396)
                4;info.magnolia.cms.filters.AbstractMgnlFilter.matches(AbstractMgnlFilter.java:94)
                10915;info.magnolia.cms.core.DefaultContent.newNodeDataInstance(DefaultContent.java:229)
                2;info.magnolia.cms.security.URISecurityFilter.isAuthorized(URISecurityFilter.java:98)
                  2;info.magnolia.cms.security.URISecurityFilter.isAllowed(URISecurityFilter.java:82)
                  4;info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
                  246;info.magnolia.cms.core.DefaultContent.(DefaultContent.java:126)
                  4;info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:82)
                  47;info.magnolia.cms.beans.config.URI2RepositoryMapping.getHandle(URI2RepositoryMapping.java:104)
                  10915;info.magnolia.cms.core.AbstractContent.getNodeData(AbstractContent.java:130)
                  3496;info.magnolia.cms.core.DefaultContent.(DefaultContent.java:144)

As always, full code is in the Magnolia git repo.

Enjoy.