Published on dev2dev (http://dev2dev.bea.com/)
http://dev2dev.bea.com/pub/a/2005/04/enterprise_aop.html
See this if you're having trouble printing code examples
by David Teare
04/05/2005
Today, aspect-oriented programming (AOP) frameworks are trying to gain a foothold in the enterprise environment. In order for them to be widely adopted, these frameworks must integrate well with the other frameworks that are already being used within enterprise systems. This article shows developers how to integrate the AspectWerkz AOP framework with a few of today's popular frameworks: Log4J, the Atlassian performance profiler, Hibernate, and Tapestry.
This article starts with an existing Tapestry web application that implements two separate concerns: logging and performance profiling. Every project has these needs, with many leveraging Log4J for logging and the Atlassian profiler framework for performance analysis. The original non-AOP implementation is then refactored to use the AspectWerkz framework to separate each concern's implementation. The resulting application code will be simpler, easier to maintain, and, most important, more natural and expressive.
All applications and source code described in this article are available for download.
To demonstrate the power of AOP we start with a non-AOP web application and refactor it to use AOP. Having a before and after image of the application will show how easy AOP is to apply and how useful aspects are as extensions to the Java language.
The sample application implements a simple blog that allows users to post new articles and comment on existing articles. It is implemented using a variety of frameworks, including Tapestry for the web tier, Hibernate as the O/R Mapping solution, and the Spring framework to tie everything together. Logging is implemented using the Log4J framework, and performance is monitored using the Atlassian profiler.
For demonstration purposes, the blog application was kept as simple as possible. Despite its simplicity, the blog application contains enough functionality to make it resemble a "real" application, and therefore the code in this article should be applicable to existing enterprise projects.
This article assumes a basic understanding of AOP concepts. Those who are new to AOP should review the articles and tutorials referenced below. All examples will be implemented using AspectWerkz 2.0, running on BEA WebLogic JRockit 1.4.2 SDK. For alternative environments, see the main AspectWerkz site.
To run the sample application you will need a database and a servlet container. This article assumes MySQL will be used.
After installing the requisite software, download and unpack the sample code into a temporary directory. You will find three files in the distribution:
First, set up MySQL to have the required database. Name the database "blog" and set up a user id "blog" with password "password." Next, define the schema by executing
the blog-ddl.sql script (type source blog-ddl.sql from a MySQL prompt).
Now we can deploy the applications. Both versions of the blog application come packaged as a WAR file, so deployment to your servlet container should be straightforward.
You should now be able to run the application by visiting http://localhost:7001/blog-preaop/blog and
http://localhost:7001/blog-postaop/blog. Play with the application for a while and check out the source code
in the WEB-INF/classes directory. The remainder of the article will dissect both implementations and highlight the strengths of the AOP approach.
The blog application implements two cross-cutting concerns: logging and profiling. These concerns needed to be implemented in every class throughout the entire application. Let's see how they were implemented using the standard Java tools that were available before AOP arrived.
The goal for logging is to be able to debug a production application without turning on the debugger. What has proven most valuable to me on my projects has
been including tracing in my code by logging the entry and exit of each method. For example, in the HibernateEntryDao class, we have the following code for finding
all the blog entries:
private static final Log log = Log.getLog(EntryHibernateDao.class);
public Entry[] findAll() {
log.enter("findAll");
List entries = getHibernateTemplate().find("from Entry");
log.exit("findAll");
return (Entry[])entries.toArray(new Entry[] {});
}
When used consistently throughout the code, the following log output is generated for a complete user request:
com.tss.blog.web.ApplicationServlet INFO : >service: '/blog' com.tss.blog.service.BlogSvcImpl INFO : >findAllEntries com.tss.blog.persistence.EntryHibernateDao INFO : >findAll com.tss.blog.persistence.EntryHibernateDao INFO : <findAll com.tss.blog.service.BlogSvcImpl INFO : <findAllEntries com.tss.blog.web.ApplicationServlet INFO : <service: '/blog'
While this is very verbose, it has been very helpful for debugging production systems. Log4J does a good job optimizing the writing of this log, so performance rarely
becomes an issue. Since all the enter/exit calls are given the priority of INFO, if performance of the web tier does become an issue, all you have to do is change the
logging priority threshold in log4j.properties to WARN or above, and Log4J will discard the trace information.
Another concern implemented by the blog application is profiling. In many projects application profiling is done prior to production and is only repeated if a user complains.
Thanks to the Atlassian profiler, we can take a much more proactive approach, keeping track of time spent in each method and reporting
the results at the end of each request. If any request takes more time than expected, we log the profiling information as an ERROR to raise attention. With Log4J configured to send an
email to the development team for any logged errors, we know immediately if the application is running too slowly. In my experience, this has proven invaluable for finding application
programming issues such as deadlocks and poorly written transactions.
To implement the profiler, we could follow the approach used by the tracing code. In each method, you surround your code with calls to start and stop the profiler. Combining this with the trace code, we have the following:
public Entry[] findAll() {
log.enter("findAll");
Profiler.push("findAll");
List entries =
getHibernateTemplate().find("from Entry");
Profiler.pop("findAll");
log.exit("findAll");
return (Entry[])
entries.toArray(new Entry[] {});
}
This yields the following log output for a complete user request:
com.tss.common.Profiler INFO :
[2373ms] - service: '/blog'
[150ms] - findAllEntries
[150ms] - findAll
While this information is helpful, you can see how verbose the code has become. The profiler has made itself so intrusive that it will be nearly impossible to get the entire development team to use it. Since we are not using AOP yet, we have no choice but to introduce a little hack - we incorporate the call to the profiler in the logging code. The following Log methods will now handle the profiling for us:
public void enter(Object method) {
if (!l.isInfoEnabled()) return;
l.info(">" + method);
Profiler.push(method.toString());
}
public void exit(Object method) {
if (!l.isInfoEnabled()) return;
l.info("<" + method);
Profiler.pop(method.toString());
}
While this works, and developers now only need to call the logging code, we have tightly coupled the profiling concern with the logging concern. This tight coupling hampers our flexibility.
|
I have hinted at a few of the issues with the implementation of the blog application, but I would like to highlight them again and explain why they are a problem:
Verbosity
For our logger and profiler to work properly, we must include the enter/exit code in every method. In some cases you need to change your code style to allow an exit to be called before returning from a method. For example, if you want the profiler to properly time your method, you must call exit before throwing an exception or returning from the method. This is a burden on developers and causes the code to become bloated.
Inability to easily refactor code
Refactoring code to become more natural is a best practice, and anything that makes refactoring more difficult can cause developers to avoid it entirely. Changing method names is a regular occurrence that leaves the statically declared enter/exit method names incorrect. At best, this will require a manual update; at worst, the incorrect names will be accidentally left in the code and cause confusion during debugging.
Inability to enforce proper usage without code reviews
Apart from conducting regular code reviews, there is no way to ensure that everyone on the team is following the project's logging guidelines. If these are not consistently followed, the profiling and trace information loses its value.
Tight coupling of logging and profiling concerns
Having the profiling concern baked into the logging code makes it very difficult to profile only certain code paths. For example, it is desirable to profile all ServletRequests and to log an error if any request takes more than five seconds. Other tasks such as initializing the Application servlet should be allowed to take more than five seconds without triggering an error, but we would still like to log it for informational purposes. If an error is generated during initialization, it is likely that the logging code will be commented out or the maximum elapse time will be increased to 10 seconds. (Unfortunately, this is a true story from one of my non-AOP projects where initialization took eight seconds.)
Points 1, 2, and 3 can be a real burden for developers. Developers have enough to worry about without the added concern of logging and profiling. Of course, developers will define templates for auto-completion of enter/exit method calls, but they must remember to do this consistently and fix errors caused by refactoring.
To illustrate how much of a burden this type of implementation can be, consider how much time per class you will spend implementing logging over the lifetime of a project. At a recent conference, Adrian Coyler, a core committer to AspectJ, speculated on the amount of development time that is invested in implementing logging consistently on a medium- to large-sized project. He estimated that a developer spends 15 minutes per class implementing logging over the course of a project. (Even when using code completion, one must consider the impact of refactoring.) On a relatively small project with 500 classes, an astonishing 3.5 weeks of the project schedule is spent implementing logging! Let's fix this by introducing some aspects to handle it for us.
Before using AOP we need to decide which framework we want to use. There are several competing AOP frameworks in existence today, and in my opinion, AspectWerkz and AspectJ are the most compelling, based on their functionality and overall popularity. For this article I will demonstrate how to leverage the AspectWerkz framework, using the new 2.0 release.
Having to choose between AspectJ and AspectWerkz was a tough decision. Thankfully, AspectJ and AspectWerkz recently agreed to join forces and collaborate on the release of AspectJ 5. The current AspectWerkz 2.0 release will be the final release, and all new development will be done in the AspectJ branch. Consolidation in the AOP space is ultimately a good thing for developers, as the current variety of platforms can make it intimidating for new users. Furthermore, having two strong development teams and communities consolidated into a single, stronger unit will help push forward the boundaries of AOP.
Before we dive into applying aspects to our code base, we need to make some decisions on how we want to use AspectWerkz.
AspectWerkz gives you two options when it comes to defining your pointcuts: annotations within your Java class files, or using XML defined in an external file named
aop.xml. Defining your pointcuts directly in code using annotations is very nice, but if you are not using JDK 5 you will be forced to include an additional build step
to generate the aop.xml file. When using JDK 5, I prefer to define the aspects in XML and use annotations for the pointcuts. This way the pointcuts are coupled with the code, while
the aspects may easily be changed (or removed) simply by editing aop.xml. I wanted this article to be immediately applicable to the widest audience possible, so JDK
5 is assumed not to be readily available.
Since I have a real distaste for requiring compile-time steps during development, I elected to define everything directly in aop.xml. This decision forces us to define rather complex
pointcuts using the aop.xml notation, but in my opinion this is better than slowing down the development cycle. This article will use aop.xml
definitions exclusively.
A great deal of AspectWerkz's flexibility comes from its ability to run in both online and offline modes. In the online mode AspectWerkz weaves your classes dynamically at runtime. With the offline mode, an additional compilation step is required to weave your classes during the build phase. This flexibility provides developers with the ability to pick the best mode for a specific task.
For example, during development time, online mode is a great choice. It doesn't require a compilation or weaving step during the development cycle. Also, since it is development time, you have full control over the JVM runtime and therefore don't mind customizing the JVM startup, which is required by online weaving.
When needed, you can switch to offline mode. There are two main reasons why you would want to do this. First, pre-weaved classes are very performant; they perform similar to "normal" classes that contain the same functionality. Second, there is no need to change the JVM settings. This is important for hosted environments or when dealing with conservative administrators. The downside to offline mode is that you can only apply your aspects to code you package yourself. This means that you cannot have your aspects applied to any third-party libraries that you may be using (unless you repackage them).
I use online mode during the development phase and then switch to offline mode for deployments. This allows me to avoid an extra build step, and since it's development, I am not worried about performance or changing the JVM settings. For this article, offline weaving was used on the packaged WAR file so that readers don't need to customize their JVM to test the application.
To weave your classes offline using AspectWerkz, integrate the following target into your ant script:
<target name="weave">
<property name="AW_LIB"
value="c:/opt/aspectwerkz-2.0/lib"/>
<taskdef name="awc"
classname="org.codehaus.aspectwerkz.compiler.AspectWerkzCTask">
<classpath>
<pathelement
path="${AW_LIB}/aspectwerkz-2.0.jar"/>
<pathelement
path="${AW_LIB}/aspectwerkz-core-2.0.jar"/>
<pathelement
path="${AW_LIB}/aspectwerkz-extensions-2.0.jar"/>
</classpath>
</taskdef>
<awc verbose="true"
targetdir="web\WEB-INF\classes">
<classpath>
<fileset dir="lib"/>
</classpath>
</awc>
</target>
We have all seen the simple tracing aspect that epitomized AOP in the early days. It simply wrapped all method calls with a call to System.out.println() before and after
each method invocation. Of course, this is completely useless for a production environment. We want to use Log4J for its many benefits.
As shown in the previous sample code, to log with Log4J you need to instantiate the logger with a category name. The usual convention is to use the fully qualified class as the category name as follows:
private static final Log log = Log.getLog(EntryHibernateDao.class);
We want an aspect that has the same characteristics as the above definition, namely:
To achieve the above requirements, we need to do more than just apply our logging aspect to our pointcuts. We must "inject" the log definition into our classes using a mixin. Mixins provide
a way of adding additional functionality to a set of classes and are especially useful for situations where boilerplate code is required to be implemented in multiple classes. Using a mixin,
we can instruct AspectWerkz to modify our classes to add behavior to the classes. In this case, we will have AspectWerkz modify our classes to implement a Loggable
interface that will be used to return a Log instance that meets the above requirements. The following code defines the Loggable interface and its implementation:
public interface Loggable {
Log getLog();
}
public class LoggableImpl implements Loggable {
private final Log log;
public LoggableImpl(Class targetClass) {
log = Log.getLog(targetClass);
}
public Log getLog() { return log; }
}
We now want to instruct AspectWerkz to modify our classes to implement the Loggable interface; to do this we add the following XML definition to aop.xml:
<mixin class="com.handyware.aop.LoggableImpl"
deployment-model="perClass"
bind-to="within(com.tss..*)
AND avoidTrace"/>
This mixin is instructing AspectWerkz to add a LoggableImpl field to each class in our system that we want to log. To see what this does, we can decompile the
generated class. The following code is what the weaved EntryHibernateDao class contains:
public class EntryHibernateDao
extends HibernateDaoSupport
implements Loggable, IEntryDao
{
private static final LoggableImpl aw$MIXIN_0;
public Log getLog() {
return aw$MIXIN_0.getLog();
}
static {
aw$clazz = Class.forName(
"com.tss.blog.service.EntryHibernateDao");
aw$MIXIN_0 = (LoggableImpl)Mixins.mixinOf(
"com.tss.blog.aop.LoggableImpl",
aw$clazz);
}
....
}
As you can see, AspectWerkz has modified the original class to include a LoggableImpl static field and has initialized it to a Log instance that is specific
to the class. Now that we have a getLog() method in each of our classes, defining the Log4J logging aspect is very straightforward:
public class LoggingIdiom {
public Object traceWithParams(
JoinPoint jp, Loggable loggable)
throws Throwable {
loggable.getLog().enter(enterTrace(jp));
Object result = jp.proceed();
loggable.getLog().exit(exitTrace(jp, result));
return result;
}
}
And to weave this aspect into our code, we add the following to our aop.xml definition:
<aspect class="com.tss.aop.LoggingIdiom">
<pointcut name="p2"
expression="execution(* com.tss..*.*(..))
AND avoidTrace" />
<advice name="traceWithParams(JoinPoint jp,
com.tss.aop.Loggable loggable)"
type="around"
bind-to="p2 AND target(loggable)" />
</aspect>
You'll notice in the logging aspect definition above that we defined an avoidTrace pointcut that allowed us to exclude those classes that we didn't want to log. The
pointcut model is very powerful as it allows you to be very selective in how your aspects are applied.
For example, Hibernate uses a dynamic subclassing technique and by default, the logging aspect will be applied to these new classes, which you likely don't want. We can exclude these from our logs to simplify them. To do this, we simply exclude all point cuts that are related to Hibernate. Other examples include JavaBean accessors and the logging aspect itself—otherwise we could get in an infinite loop logging the logger!
|
StaticJoinPointAspectWerkz 2.0 supports the concept of a StaticJoinPoint, which unlike a normal JoinPoint, does not provide access to Runtime Type Information (RTTI).
By eliminating RTTI, the weaver is able to optimize calls to the aspect, as it is no longer required to collect and make available the dynamic data for that JoinPoint.
For example, the logging aspect in the previous section logged the parameter values of each method call and therefore needed access to the RTTI. If we were not interested in logging
the parameters, we could use a StaticJoinPoint to improve performance. The following aspect code and definition do just that:
public class LoggingIdiom {
public Object trace(StaticJoinPoint jp,
Loggable loggable)
throws Throwable {
CodeSignature cs =
(CodeSignature) jp.getSignature();
loggable.getLog().enter(
methodSignature(cs));
Object result = jp.proceed();
loggable.getLog().exit(
exitTrace(jp, result));
return result;
}
}
...
<aspect class="com.tss.aop.LoggingIdiom">
<pointcut name="p2"
expression="execution(* com.tss..*.*(..))
AND avoidTrace" />
<advice name="trace(StaticJoinPoint jp,
com.tss.aop.Loggable loggable)"
type="around"
bind-to="p2 AND target(loggable)" />
</aspect>
Implementing the profiling aspect is much easier than implementing the logging aspect because the profiler can be called statically. This allows us to define the following simple aspect, without any need for mixins:
public Object profile(StaticJoinPoint jp)
throws Throwable {
Profiler.push(methodSig(jp));
Object result = jp.proceed();
Profiler.pop(methodSig(jp));
return result;
}
This code is very straightforward. The aspect definition in aop.xml, however, is more interesting. We only want to profile those pointcuts specific to web requests, and so we use
the cflow expression when selecting our pointcuts.
<aspect class="com.tss.aop.ProfilingIdiom">
<pointcut name="p3" expression="cflow(
execution(* com.tss.blog.web.
ApplicationServlet.service(..)))
AND execution(* com.tss..*(..))
AND avoidTrace"/>
<advice name="profile(StaticJoinPoint jp)"
type="around" bind-to="p3"/>
</aspect>
The cflow expression allows us to select only those pointcuts that are in the flow of control of the Tapestry pages. In other words, any call made within the execution
of a web request will be profiled. This is a very powerful expression that allows us to solve the issue of avoiding profiling the initialization code; we are able to profile only those items that
are of interest to us. In fact, we could have defined multiple profiler instances that have different behaviors based on what is being profiled. For example, web requests that take more than 5
seconds could trigger an error, while any scheduled background tasks that take longer than 10 seconds could also generate an error.
We have seen how applying AOP to a sample application makes the code base much easier to write, as well as more flexible and consistent. By implementing the logging and profiling concerns using separate aspects, we have solved all the problems outlined in the original application. Developers no longer need to be responsible for incorporating these concerns directly into their code. After reading this article and browsing the accompanying source code, it should take less than a day to incorporate these aspects into your code base. If this is done early enough in your project, you will realize a large cost savings, and developers on your team will thank you.
It is important to be pragmatic in the use of AOP and not apply it unnecessarily, especially in situations where an equally good non-AOP alternative already exists. That being said, if one is constrained to thinking without aspects for too long, implementation hacks like the tying of the profiler to the logger start to seem normal. When code starts to become tightly coupled simply because you get tired of typing the same code throughout all your classes, AOP can really help to simplify the code base.
The upcoming AspectJ 5 version will support all the features used in this article. Everything described will have a natural migration path to AspectJ 5. The first release should be available later this year.
The source code for the applications used in this article is available for download: enterprise_aop.zip (13MB)
David Teare is a graduate of The University of Western Ontario. He and his wife currently live in the Greater Toronto Area, where their company Teare Software Solutions is based
Return to dev2dev.