Classworking toolkit: Putting aspects to werk

Can aspects clean up code pollution? Using the AspectWerkz framework for logging is a first step

Aspect-oriented programming (AOP) promises to keep code clean by separating out functionality that applies across the application, rather than to a particular class or package. Logging is one of the commonly used examples of this type of function. Can AOP help with logging? In this article, developer and AOP enthusiast Dennis Sosnoski looks at using the AspectWerkz framework to find out.

Share:

Dennis Sosnoski (dms@sosnoski.com), Java and XML consultant, Sosnoski Software Solutions Inc.

Dennis SosnoskiDennis Sosnoski is the founder and lead consultant of Seattle-area Java technology consulting company Sosnoski Software Solutions Inc., specialists in XML and Web services training and consulting. His professional software development experience spans 30 years, with the last several years focused on server-side XML and Java technologies. He is a frequent speaker at conferences nationwide. He's also the lead developer of the open source JiBX XML Data Binding framework built around the Java classworking technology.



08 March 2005

Back in my articles on Java programming dynamics (see Resources), I demonstrated how you can use classworking techniques to implement systematic changes to program behavior. This type of approach is the basis for most of the work being done with aspect-oriented programming (AOP) on the Java™ platform. In this article, I'm going to show you how to implement the same type of systematic changes to program behavior using an AOP framework that builds higher layers on top of the classworking to improve ease of use.

Introducing AspectWerkz

Many AOP frameworks are available for the Java platform. For this series of articles I've chosen to use the AspectWerkz framework, an open source project sponsored by BEA Systems. AspectWerkz isn't the oldest form of AOP for Java technology -- that distinction goes to the IBM-supported AspectJ extension of the Java programming language -- but AspectWerkz has been gaining increasing attention as a fast, powerful, and flexible framework for using AOP in combination with standard Java code. The AspectWerkz and AspectJ teams recently announced a merger of their efforts, so in the future we're going to see the best features of these two approaches to AOP for Java programming combined in a single product. I'll follow up on that later in this column, but for right now I'm going to stick to working with the base AspectWerkz framework.

Note: For an excellent introduction to the practical uses of AOP, don't miss the new AOP@Work column. Launched in February 2005 and penned by five leading AOP experts, each of the articles in this year-long series will provide knowledge you can put to use immediately.

Logging is one of the uses that always seems to come up when AOP proponents list AOP applications in everyday development. Logging is clearly a concern that applies across a large portion of a typical enterprise application's code. The logging code is irrelevant to the main purpose of the application, and it can also be very intrusive in the code. This combination of characteristics makes logging an excellent candidate feature to be structured as an aspect. I'm going to look at implementing a combined logging and performance metric aspect to see how well the aspect paradigm applies to this type of problem domain.

Ask the expert: Dennis Sosnoski on JVM and bytecode issues

For comments or questions about the material covered in this article series, as well as anything else that pertains to Java bytecode, the Java binary class format, or general JVM issues, visit the JVM and Bytecode discussion forum, moderated by Dennis Sosnoski.

AspectWerkz basics

The AspectWerkz Web site (see Resources) provides extensive documentation and usage examples, along with links to articles on using AspectWerkz. I'm not going to try to duplicate all that here, but I will give a brief introduction to what I see as the most important concepts: pointcuts, aspects, and advice.

A pointcut is basically just a place to interrupt the "normal" (as defined by the source code) flow of your application's execution and do something different. AspectWerkz supports many types of pointcuts tied to Java code structure, including method calls or executions, field gets/sets, and exception-handler execution, as well as combinations including code within a particular execution path.

In AspectWerkz terms, an aspect is just a Java class that can be applied as a target for crosscutting concerns. There's no special interface that needs to be implemented to make a class an aspect, but specific method signatures are required to access the class as an aspect. Generally, you'll want your aspect classes to reside outside your standard application class hierarchy because they're probably going to be used only through the AspectWerkz framework, but, again, there's no requirement that they be anywhere special (except in your run-time classpath).

An advice is a method in an aspect class that's used as the "something different" to be done at a pointcut. The default method signature for an advice is to take a single parameter, which provides information about the pointcut being intercepted. Listing 1 shows an example of an aspect class defining a pair of methods intended to be used as before-and-after advice on a method call.

Listing 1. A simple advice class and advice methods
package com.sosnoski.aspectwerkz;
public class TraceAspect
{
    public void beforeMethod(JoinPoint join) {
        System.out.println("Entering method");
    }
    
    public void afterMethod(JoinPoint join) {
        System.out.println("Leaving method");
    }
}

AspectWerkz also supports other method call signatures, though with a little added effort required in terms of the configuration. And speaking of the configuration, that's another item I should mention up front. AspectWerkz supports three forms of configuration:

  • Java 5.0 annotations embedded in source code
  • Javadoc-style annotations embedded in source code
  • An external XML file

Being an XML kind of guy myself (I also contribute regularly to the developerWorks XML zone), I'm going to use the XML option for this article. Listing 2 shows a sample XML configuration for the Listing 1 advice.

Listing 2. XML configuration example
<aspectwerkz>
  <system id="AspectWerkzExample">
    <package name="com.sosnoski.aspectwerkz">
      <aspect class="TraceAspect">
        <pointcut name="longMethod"
            expression="execution(long ..(..))"/>
        <advice name="beforeMethod" type="before"
            bind-to="longMethod"/>
        <advice name="afterMethod" type="after"
            bind-to="longMethod"/>
      </aspect>
    </package>
  </system>
</aspectwerkz>

The Listing 2 configuration defines a single aspect, as implemented in the class com.sosnoski.aspectwerkz.TraceAspect. For this aspect, it defines a single pointcut representing the execution of any method returning a long value (the ".." sequences in the expression to be matched are wildcards) and binds two separate pieces of advice to this pointcut. The first advice is implemented by the beforeMethod() in the advice class and is of type before (meaning the advice method will be called before the pointcut method is executed). The second advice is implemented by the afterMethod() and is of type after (so the advice method will be called after the pointcut method has executed).


Log on

Now that I've given you an idea of the basic AspectWerkz concepts, how can these concepts apply to logging functionality? The method call example in the last section seems like a good starting point. If I can configure AspectWerkz to execute beforeMethod() and afterMethod(), respectively, before and after every method call of interest, these will give a useful execution trace of the application.

Of course, to make the execution trace useful, I'll need to expand on the minimal information output by the Listing 1 methods. Fortunately, AspectWerkz provides easy ways of accessing information about the pointcut being intercepted. The Listing 3 version of the code shows how I can access the actual method information from the pointcut.

Listing 3. Advice methods reporting intercepted method
package com.sosnoski.aspectwerkz;
public class TraceAspect
{
    public void beforeMethod(JoinPoint join) {
        MethodSignature signature =
            (MethodSignature)join.getSignature();
        System.out.println("Entering method " +
            signature.getName());
    }
    
    public void afterMethod(JoinPoint join) {
        MethodSignature signature =
            (MethodSignature)join.getSignature();
        System.out.println("Leaving method " +
            signature.getName());
    }
}

To test this preliminary logging code, I'll use a nicely recursive method, an implementation of the Fibonacci sequence calculation, as shown in Listing 4.

Listing 4. Fibonacci sequence calculation
package com.sosnoski.aspectwerkz;
public class FiboTest
{
    private long fibo(int value) {
        if (value > 2) {
            return fibo(value-1) + fibo(value-2);
        } else {
            return 1;
        }
    }
    
    public static void main(String[] args) {
        FiboTest inst = new FiboTest();
        int value = Integer.parseInt(args[0]);
        System.out.println("Fibo[" + value + "] is " +
            inst.fibo(value));
    }
}

Just running this code directly is simple:

[dms]$ java -cp classes com.sosnoski.aspectwerkz.FiboTest 6
Fibo[6] is 8

Running it using AspectWerkz is a little more complicated. You've got two ways of implementing aspect handling using AspectWerkz: build-time class modification and run-time class modification. Throughout this article, I'm going to use the run-time alternative. This approach requires a custom classloader, supplied as part of the AspectWerkz framework. Using an environment variable for the home directory of the AspectWerkz installation and assuming the XML configuration (from Listing 2) is in the aspectwerkz.xml file, here's the Linux™ and UNIX® version of the Listing 4 code using AspectWerkz (with the command line wrapped to fit the width restrictions of this article):

[dms]$ $ASPECTWERKZ_HOME/bin/aspectwerkz
   -Daspectwerkz.definition.file=aspectwerkz.xml
   -cp classes com.sosnoski.aspectwerkz.FiboTest 6

The resulting output is also a lot longer. Here, and in the rest of the examples, I'm going to ignore the startup information printed by AspectWerkz and show the output generated by my advice. The output is shown in Listing 5.

Listing 5. Advised calculation results
Entering method fibo
Entering method fibo
Entering method fibo
Entering method fibo
Entering method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Entering method fibo
Entering method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Leaving method fibo
Entering method fibo
Entering method fibo
Entering method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Leaving method fibo
Fibo[6] is 8

Making it pretty

Listing 5 shows that the Listing 3 advice methods are being called, but doesn't present much useful information about the application being executed. I'm going to fix this shortcoming by changing my advice to show method call nesting by indentation, and also to print the values being passed and returned. For this purpose, I'll also change my advice to a different type: the around advice type. Listing 6 shows the modified code.

Listing 6. Advice method with indentation and value printing
private int m_nestingDepth;

private void indent() {
        for (int i = 0; i < m_nestingDepth; i++) {
            System.out.print(' ');
        }
    }
    
private void printCall(JoinPoint call) {
    MethodSignature signature =
        (MethodSignature)call.getSignature();
    System.out.print(signature.getName());
    System.out.print('(');
    MethodRtti rtti = (MethodRtti)call.getRtti();
    System.out.print(rtti.getParameterValues()[0]);
    System.out.print(')');
}

public Object traceLong(JoinPoint join) throws Throwable {
        
    // print entering information
    indent();
    System.out.print("Entering method ");
    printCall(join);
        
    // execute the joinpoint method
    m_nestingDepth++;
    Object result = join.proceed();
    m_nestingDepth--;
        
    // print exiting information
    indent();
    System.out.print("Leaving method ");
    MethodSignature signature =
        (MethodSignature)join.getSignature();
    System.out.print(signature.getName());
    System.out.print('<');
    System.out.println(result);
        
    // return result from method call
    return result;
}

As you might expect from the name, an around advice surrounds the pointcut execution. It's called when the pointcut is supposed to be executed and has the flexibility to decide when -- and even if -- the pointcut actually does execute. In the Listing 6 code, I've kept the around advice processing simple. Here, the advice code (the traceLong() method) starts off by printing the method name and argument value indented to the current nesting level. It then calls the method and saves the result, then finishes by printing the method name and return value indented to the current nesting level.

The XML configuration needs to be adjusted to use this new advice, but that's an easy change. Here's the aspect element from the file with the changes shown in bold:

    <package name="com.sosnoski.aspectwerkz">
      <aspect class="TraceAspect">
        <pointcut name="longMethod"
            expression="execution(long ..(..))"/>
        <advice name="traceLong" type="around"
            bind-to="longMethod"/>
      </aspect>
    </package>

Listing 7 gives the output generated using this new advice.

Listing 7. Output with indentation and value printing
Entering method fibo(6)
 Entering method fibo(5)
  Entering method fibo(4)
   Entering method fibo(3)
    Entering method fibo(2)
    Leaving method fibo<1
    Entering method fibo(1)
    Leaving method fibo<1
   Leaving method fibo<2
   Entering method fibo(2)
   Leaving method fibo<1
  Leaving method fibo<3
  Entering method fibo(3)
   Entering method fibo(2)
   Leaving method fibo<1
   Entering method fibo(1)
   Leaving method fibo<1
  Leaving method fibo<2
 Leaving method fibo<5
 Entering method fibo(4)
  Entering method fibo(3)
   Entering method fibo(2)
   Leaving method fibo<1
   Entering method fibo(1)
   Leaving method fibo<1
  Leaving method fibo<2
  Entering method fibo(2)
  Leaving method fibo<1
 Leaving method fibo<3
Leaving method fibo<8
Fibo[6] is 8

Making it smart

The Listing 7 output is starting to look useful, but suffers from a lack of selectivity. If you run this code with a larger number for the Fibonacci sequence index (say, 12), you'll end up watching output scroll by for a long time. As a final step in developing a useful logging aspect, I'm going to implement some smart filtering of the output.

I'd also like to end up with an aspect I can use for logging execution paths and associated performance metrics so I can see which method calls are taking the longest times to execute. The approach I'll use is similar to the one I demonstrated using direct classworking in my articles on Java programming dynamics (see Resources), based on the java.lang.System.currentTimeMillis() time value. This timer is not highly accurate -- on Microsoft® Windows®, the resolution is about 17 ms; on my Linux system, 1 ms -- but it's available on all versions of the standard Java platform, which makes it useful at least for demonstration purposes. (Next month, I'll discuss getting better timer resolution.) Filtering the execution trace based on the time taken for the method calls should show some interesting results.

To keep the same structure for my output, this time-based filtering gets a little complex. First, I need to delay printing the "entering" line for each method call until I can see if the time taken is enough to make it through my filter. That's not so bad in and of itself, but when I find I do need to print the method information, I first need to print the entering lines for each enclosing method call. To do this, I'll need to keep a list of the entry information for methods I haven't yet printed, then dump these all out, properly indented, before I print the entry information for the current method. Listing 8 shows a new advice method modified to use this list of unprinted methods.

Listing 8. Advice method with timing filter
private ArrayList m_unprintedCalls = new ArrayList();
    
private void indent(int depth) {
    for (int i = 0; i < depth; i++) {
        System.out.print(' ');
    }
}

public Object traceTimed(JoinPoint join) throws Throwable {
        
    // add joinpoint to list pending print
    m_pendingPrints.add(join);
        
    // time joinpoint execution
    long start = System.currentTimeMillis();
    m_nestingDepth++;
    Object result = join.proceed();
    m_nestingDepth--;
        
    // remove joinpoint if still on pending list
    //  (will always be last in list)
    boolean entered = true;
    if (m_pendingPrints.size() > 0) {
        m_pendingPrints.remove(m_pendingPrints.size()-1);
        entered = false;
    }
        
    // check if execution time above cutoff
    long time = System.currentTimeMillis() - start;
    if (time > 1) {
            
        // print all unprinted "entering" lines
        int count = m_pendingPrints.size();
        for (int i = 0; i < count; i++) {
                
            // print entering information for nesting call
            //  (nesting depth based on start of pendings)
            indent(m_nestingDepth-count+i);
            JoinPoint prior =
                (JoinPoint)m_pendingPrints.get(i);
            System.out.print("Entering ");
            printCall(prior);
            System.out.println();
        }
            
        // clear all pendings now that they're printed
        m_pendingPrints.clear();
            
        // print exiting information including time
        indent();
        System.out.print("Leaving ");
        printCall(join);
        System.out.print('=');
        System.out.print(result);
        System.out.print(" took ");
        System.out.print(time);
        System.out.println(" ms.");
    }
        
    // return result from joinpoint execution
    return result;
}

After modifying the XML configuration file to use the traceTimed() advice method in place of traceLong(), running this with the same argument value "6" doesn't show any trace information at all because the entire execution takes less than the minimum time. If I instead use the value "15," I get the output shown in Listing 9.

Listing 9. Output with timing filter
Entering fibo(15)
 Entering fibo(14)
  Entering fibo(13)
   Entering fibo(12)
    Leaving fibo(11)=89 took 2 ms.
    Leaving fibo(10)=55 took 2 ms.
   Leaving fibo(12)=144 took 11 ms.
   Entering fibo(11)
    Leaving fibo(10)=55 took 2 ms.
    Leaving fibo(9)=34 took 2 ms.
   Leaving fibo(11)=89 took 5 ms.
  Leaving fibo(13)=233 took 19 ms.
  Entering fibo(12)
   Leaving fibo(11)=89 took 2 ms.
   Entering fibo(10)
    Entering fibo(8)
     Entering fibo(6)
      Leaving fibo(4)=3 took 2 ms.
     Leaving fibo(6)=8 took 4 ms.
    Leaving fibo(8)=21 took 6 ms.
   Leaving fibo(10)=55 took 6 ms.
  Leaving fibo(12)=144 took 10 ms.
 Leaving fibo(14)=377 took 29 ms.
 Entering fibo(13)
  Entering fibo(12)
   Leaving fibo(11)=89 took 2 ms.
   Leaving fibo(10)=55 took 2 ms.
  Leaving fibo(12)=144 took 6 ms.
  Entering fibo(11)
   Leaving fibo(10)=55 took 2 ms.
  Leaving fibo(11)=89 took 3 ms.
 Leaving fibo(13)=233 took 9 ms.
Leaving fibo(15)=610 took 95 ms.
Fibo[15] is 610

The Listing 9 output is what I wanted to see, so it's time to leave Fibonacci behind and move on to a real application. I'll do just that in next month's column.


Until next time

In this column, you've seen how AspectWerkz can be used to implement a basic execution trace enhanced with performance metrics. Next month's column takes this concept further, extending the trace aspect and applying it to a complex real-world framework with its own built-in logging to see where the aspect approach works well -- and where it doesn't. Can aspects save us from logging code pollution? Check back soon to find out.


Download

DescriptionNameSize
Source codecwt-source.zip6.72 KB

Resources

  • Be sure to read all the installments in the Classworking toolkit series by Dennis Sosnoski
  • For more information about AspectWerkz, go staight to the project Web site for comprehensive documentation and links to myriad articles.
  • Learn about the AspectJ aspect-oriented extension to the Java language in Improve modularity with aspect-oriented programming, by Nicholas Lesiecki (developerWorks, January 2002).
  • Nicholas Lesiecki leads the writing team in the new AOP@Work series, which focuses on the practical uses with AOP.
  • Find out how AOP can add teeth to binding agreements between components in Contract enforcement with AOP, by Filippo Diotalevi (developerWorks, July 2004).
  • Are your components suffering from a lack of flexibility? Then Andrew Glover's AOP banishes the tight-coupling blues (developerWorks, February 2004) may be just what you need to help shake out the kinks.
  • A look at aspect-oriented programming, by Gary Pollice (developerWorks, January 2004), looks beyond the details of AOP to consider its effect on the software development process and the barriers to acceptance faced by AOP.
  • For help in understanding and maintaining existing systems, check out Use AOP to maintain legacy Java applications, by Abhijit Belapurkar (developerWorks, March 2004), to see how AOP can help.
  • Collect the whole Java programming dynamics series by author Dennis Sosnoski, taking you on a tour of the Java class structure, reflection, and classworking.
  • To learn more about Java technology, visit the developerWorks Java zone. You'll find technical documentation, how-to articles, education, downloads, product information, and more.
  • Visit New to Java technology for the latest resources to help you get started with Java programming.
  • Get involved in the developerWorks community by participating in developerWorks blogs.
  • Browse for books on these and other technical topics.

Comments

developerWorks: Sign in

Required fields are indicated with an asterisk (*).


Need an IBM ID?
Forgot your IBM ID?


Forgot your password?
Change your password

By clicking Submit, you agree to the developerWorks terms of use.

 


The first time you sign into developerWorks, a profile is created for you. Information in your profile (your name, country/region, and company name) is displayed to the public and will accompany any content you post, unless you opt to hide your company name. You may update your IBM account at any time.

All information submitted is secure.

Choose your display name



The first time you sign in to developerWorks, a profile is created for you, so you need to choose a display name. Your display name accompanies the content you post on developerWorks.

Please choose a display name between 3-31 characters. Your display name must be unique in the developerWorks community and should not be your email address for privacy reasons.

Required fields are indicated with an asterisk (*).

(Must be between 3 – 31 characters.)

By clicking Submit, you agree to the developerWorks terms of use.

 


All information submitted is secure.

Dig deeper into Java technology on developerWorks


static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=1
Zone=Java technology
ArticleID=52701
ArticleTitle=Classworking toolkit: Putting aspects to werk
publish-date=03082005