Profiling Spring Tiles with Custom Aspects

Introduction

One way of "componentizing" a web page is by composing it out of "tiles". Each tile encapsulates the logic needed to render itself. Once the tiles are built, they can be easily mixed and matched to provide different page renderings using different groupings of tiles. The Spring Framework provides support for tiles via the Apache Struts Tiles subproject.

With Spring, the page itself is controlled by a Spring Controller. When a request comes in, the controller instantiates a Model object, optionally does some pre-processing on it, sticks the model into the request, and sends off the request to its JSP. The JSP contains one or more tiles:insert calls referencing named tiles in the tiles-def.xml file. Each named tile is associated with a Tile Controller and a JSP. As the main JSP renders, it calls upon each of its tiles to render themselves, which invokes the associated Tile Controller. Each Tile Controller grabs the model off the request, does its own processing to populate the model, then sticks the model back into the request, where it is picked up by its JSP for rendering.

Motivation

Recently, one such page some of us have been working on was rendering real slow. So I figured it would be useful to get some timing information on how long each individual Tile Controller was taking, and optimize them. Unfortunately, I could not think of a good way to do this with the standard Spring approach of wrapping beans with interceptor proxies, since the Tile Controllers are defined as class names in the tiles-def.xml configuration, not bean references.

So the solution I came up with was to write an AspectJ aspect that would be woven into the application's JAR file at compile time to produce the "profiling" version of the JAR. This "profiling" JAR would be swapped into the WEB-INF/lib sub-directory of the servlet container's (in our case Tomcat) context directory for the application, along with the AspectJ Runtime JAR, followed by a container restart.

With this approach, there is no change to the application code. The aspect code is in a completely different project. Once profiling is done and we have our data, we simply replace the application's JAR file with the original one.

Since I was new to AspectJ, I had to do a bit of reading and experimenting before I got this stuff to work. There is a lot of AspectJ information available on the web, but none of them describes in detail how one would go about doing something like this. It seems to me that a lot of people would want to do this if they knew how, so hopefully this post would help someone. If you can think of other ways to do this, would appreciate hearing from you.

Steps

Here are the steps to build and compile-time weave an aspect into a web application's JAR file.

• Install AspectJ and configure (one time).
• Create an AspectJ project and write the Aspect.
• Generate the source JAR (ant jar) from the web application to be profiled.
• Compile and Weave the Aspect into the source JAR to produce a woven version of the JAR.
• Generate web application WAR file and deploy to Tomcat.
• Stop Tomcat, replace the JAR file in /webapps/${app}/WEB-INF/lib with the woven version of the JAR.
• Copy the aspectjrt.jar into the same /webapps/${app}/WEB-INF/lib directory.
• Restart Tomcat.
• Execute HTTP GETs against the application, profiling output is captured into the log file.

AspectJ Installation

I downloaded the latest AspectJ JAR (1.6.10 for me) from the AspectJ Download site. Following the instructions on the site, I just ran the downloaded JAR (java -jar) to install AspectJ under my /opt/aspectj1.6 (ASPECTJ_HOME) directory.

I then added $ASPECTJ_HOME/bin to my PATH environment variable so the AspectJ commands (ajc, the AspectJ analog of javac) are available on the command line.

I also had to increase the -Xmx setting for ajc (a shell script in $ASPECTJ_HOME/bin) from 64M to 256M because it was running out of memory during a compile. The resulting JAR is only slightly larger after weaving.

Creating the Aspect

I initially planned on building this as a private little hack for my own use, so I could tell how the code changes I was doing affected overall performance, so I thought of using the Spring StopWatch to report on this. The diagram below illustrates the setup I was trying to profile:

As you can see, there is a single Spring controller which hands off to a Tiles view with three tiles A, B and C. I wanted to find how much time was being spent overall, and how much time was being spent in each of the three tiles.

Capturing the elapsed time for each tile was easy. The problem was to track when all the tiles were done, so I could print the contents of the stopwatch. Since the Spring controller hands off control to the Tiles view, which then calls the Tiles Controller for each tile, the only way to do this was to do it at the beginning of the next request. Also the static StopWatch reference is not thread-safe, so its state can get corrupted if you hit the application too fast (so one request may not have finished before you hand it another one). So its kind of useful, as long as you are willing to live with its warts. Here is the aspect code.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46

// Source: src/profilers/MyAspect1.aj package profilers; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import org.springframework.util.StopWatch; /** * MyController Tile Profiler for individual use. This dumps out the * stopwatch contents for a matched request on the request /following/ * the one that was profiled. Because it uses a static StopWatch instance, * it is not thread safe, so be sure to wait a bit between calls, otherwise, * you will get errors. */ public aspect MyAspect1 { private static StopWatch stopwatch = null; pointcut handleRequestInternal(HttpServletRequest request, HttpServletResponse response) : execution(public * com.myco.myapp.MyController.handleRequestInternal(..)) && args(request, response); pointcut doPerform() : execution(public * com.myco.myapp.tiles..*.doPerform(..)); before(HttpServletRequest request, HttpServletResponse response) : handleRequestInternal(request, response) { if (stopwatch != null) { System.out.println(stopwatch.prettyPrint()); } String q1 = request.getParameter("q1"); stopwatch = new StopWatch(q1 == null ? "UNKNOWN" : q1); } before() : doPerform() { stopwatch.start(thisJoinPoint.getTarget().getClass().getSimpleName()); } after() : doPerform() { if (stopwatch.isRunning()) { stopwatch.stop(); } } }

Applying this aspect to the JAR file and running the web application gave me output in my logs that looked like this. As you can see, the output (with names and data changed to protect the innocent and not-so-innocent) is pretty but the information is not.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

StopWatch 'Some Query': running time (millis) = 12000 ----------------------------------------- ms % Task name ----------------------------------------- 00870 007% TileAController 00265 002% TileBController 00059 000% TileCController 00002 000% TileDController 00003 000% TileEController 00000 000% TileFController 08880 074% TileGController 00031 000% TileHController 00209 002% TileIController 00118 001% TileJController 00965 008% TileKController 00000 000% TileLController 00003 000% TileMController 00592 005% TileNController 00003 000% TileOController

To get around the two limitations of the implementation above, I decided to forego the convenience of the Spring StopWatch and capture plain elapsed times into the log file (with additional information to tie the elapsed time entries together), and then use scripts to post-process this information. My new setup looks something like this:

I use the fact that a call to Spring's modelAndView.addObject(name, value) is really the same as request.setAttribute(name, value). Before the handleRequest() call in the Spring controller, I generate a unique UUID for the request and stick it into the attribute so it can be picked up by the before() and after() advice in the Tile Controllers. Here is the second version.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57

// Source: src/profilers/MyAspect2.aj package profilers; import java.util.UUID; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import org.apache.commons.lang.StringUtils; import org.apache.struts.tiles.ComponentContext; /** * Tile Profiler for batch use. We just capture elapsed times for * each tile as a CSV formatted string in the logs. The logs need to be * post-processed to get profiling information. */ public aspect MyAspect2 { private static final String ATTR_REQ_UUID = "_req_uuid"; private static final String ATTR_START_TIME = "_start_time"; private static final String PROFILER_NAME = MyAspect2.class.getSimpleName(); pointcut handleRequestInternal(HttpServletRequest request, HttpServletResponse response) : execution(public * com.myco.myapp.MyController.handleRequestInternal(..)) && args(request, response); pointcut doPerform(ComponentContext context, HttpServletRequest request, HttpServletResponse response) : execution(public * com.myco.myapp.tiles..*.doPerform(..)) && args(context, request, response); before(HttpServletRequest request, HttpServletResponse response) : handleRequestInternal(request, response) { UUID uuid = UUID.randomUUID(); request.setAttribute(ATTR_REQ_UUID, uuid.toString()); } before(ComponentContext context, HttpServletRequest request, HttpServletResponse response) : doPerform(context, request, response) { Long startTime = System.currentTimeMillis(); request.setAttribute(ATTR_START_TIME, startTime); } after(ComponentContext context, HttpServletRequest request, HttpServletResponse response) : doPerform(context, request, response) { Long endTime = System.currentTimeMillis(); Long startTime = (Long) request.getAttribute(ATTR_START_TIME); String requestUuid = (String) request.getAttribute(ATTR_REQ_UUID); String query = request.getParameter("q1"); System.out.println(StringUtils.join(new String[] { PROFILER_NAME, requestUuid, query, thisJoinPoint.getTarget().getClass().getSimpleName(), String.valueOf(endTime - startTime) }, "|")); } }

Running this with a batch of URLs produces output in the Tomcat logs, which can be grepped using the PROFILER_NAME into a text file. You could then feed it into your data analysis tool of choice and slice and dice the data to produce actionable information. Here is some sample data from the file (I added the header line to make it a bit easier to read):

1 2 3 4 5 6

# aspect_name|request_uuid|query|tile_name|elapsed_time_millis MyAspect2|ed9ce777-263e-4fe5-a8af-4ea84d78add3|some query|TileAController|132 MyAspect2|ed9ce777-263e-4fe5-a8af-4ea84d78add3|some query|TileBController|49 MyAspect2|ed9ce777-263e-4fe5-a8af-4ea84d78add3|some query|TileCController|2 MyAspect2|ed9ce777-263e-4fe5-a8af-4ea84d78add3|some query|TileDController|3 ...

Compiling and Weaving

The aspect source code needs to be compiled and woven into the web application's JAR file. You will need all the JARs referenced by the web application in the classpath when you do this. I did this manually by making a copy of the build.xml or pom.xml, then creating a CLASSPATH declaration, then putting it into a bash script that looks something like this:

1 2 3 4 5 6 7 8

#!/bin/bash CP=$ASPECTJ_HOME/lib/aspectjrt.jar:\ $ASPECTJ_HOME/lib/aspectjweaver.jar:\ #other classes in your web application's CLASSPATH ... ajc -classpath $CP -1.6 -inpath myapp.jar -outjar myapp-woven.jar \ src/profilers/MyAspect1.aj

Here myapp.jar is the JAR file for my web application myapp, and the output of this script is myapp-woven.jar, which you must copy to $TOMCAT_HOME/webapps/myapp/WEB-INF/lib.

References

I found these resources very helpful as I was developing the aspects described in this post.

• AspectJ Project Documentation: I mostly read the Getting Started Guide, which gave me enough background to start reading/writing basic AspectJ code.
• AspectJ Cookbook: I bought this book couple years ago hoping to use it to learn AspectJ, but did not have a problem to solve, so it ended up gathering dust. The shell script and the two aspects described are heavily based on recipes in this book. Better late than never, I guess :-).

Conclusion

So anyway, here is a poor man's profiler which you can whip up quickly if you know AspectJ well enough (it took me a while for the first one, but not so much time for the second one). Its also light on resources. My experience with profilers is that it takes a very long time to set up and run, since its busy collecting all sorts of information which you would probably never use. Knowing AspectJ gives you the ability to profile code in a very focused manner - definitely a useful skill to have at your disposal in my opinion.