aspectj's load-time instrumentation

Aspectj implements the functionality also using the asm tool.

As it provides neat aspect grammars and is supported extensively by the community, I would like to switch to it. Better than Btrace , right?

Now let us see the details （shown later）.

Basically， there are two steps:

1) make aspect agent jar with the command ajc.

2) run it with aspectjweaver.jar as the javaagent, and with the aspectjrt.jar and agent jar as the classpath (also the path of the main class).

you can unzip the aspect agent jar with the command "jar xvf the aspect agent jar" and modify the aop-ajc.xml to modify options.

then use  the command "jar cvfm time.jar META-INF/MANIFEST.MF META-INF/aop-ajc.xml Simple.class"  to repack the aspect agent jar.

Detailed commands are attached as a screenshot.

[copy from others' blog]

Today I'm going to show a basic AspectJ load-time weaving setup and which configuration options can be used to debug a scenario that just doesn't seem to be working as expected.

Here is a trivial application:

public class Simple {

  public static void main(String[]argv) {
    countFast(1000);
    countSlow(1000);
  }

  public static void countSlow(int value) {
    count(value,5);
  }

  public static void countFast(int value) {
    count(value,0);
  }

  private static void count(int value, int delay) {
    for (int i=0;i<value;i++) {
      try {Thread.sleep(delay);} catch (Exception e) {}
    }
  }
}

Awesome eh? Rather contrived, but I've introduced a delay down one of the execution paths so I can do some LTW profiling and pinpoint the problematic code.

Pure java so it can be compiled and run normally:
javac Simple.java
java Simple

Now to build a suitable profiling aspect.

aspect WhereDoesTheTimeGo {

  pointcut methodsOfInterest(): execution(* *(..)) &&
                              !within(WhereDoesTheTimeGo);

  private int nesting = 0;

  Object around(): methodsOfInterest() {
    nesting++;
    long stime=System.currentTimeMillis();
    Object o = proceed();
    long etime=System.currentTimeMillis();
    nesting--;
    StringBuilder info = new StringBuilder();
    for (int i=0;i<nesting;i++) {
      info.append("  ");
    }
    info.append(thisJoinPoint+" took "+(etime-stime)+"ms");
    System.out.println(info.toString());
    return o;
  }
}

This aspect could be compiled and woven at source time, but it is more likely something to only be used occasionally when the code is run. To include at source time:

ajc WhereDoesTheTimeGo.java Simple.java
java Simple

    execution(void Simple.count(int, int)) took 2ms
  execution(void Simple.countFast(int)) took 4ms
    execution(void Simple.count(int, int)) took 5049ms
  execution(void Simple.countSlow(int)) took 5049ms
execution(void Simple.main(String[])) took 5054ms

But I want to show load-time weaving. Now load time weaving needs me to do two things:

- launch the VM with the AspectJ agent registered
- provide an xml file to configure the weaver

The AspectJ agent is a simple JVMTI agent that can get involved in the class loading process and weave any types before they are defined in the VM. In either source compilation or binary weaving, the AspectJ compiler knows the set of aspects involved, either by being given the source for them or the jars containing them. In a load time weaving setup they could be anywhere on the classpath and so to save a very costly scan of all the classpath contents, it relies on an xml config file to name the aspects it should use. There are a lot of potential options that can be specified in the xml file, but a minimal one suitable for my needs here is:

<aspectj>
 <aspects>
   <aspect name="WhereDoesTheTimeGo"/>
 </aspects>
</aspectj>

It just defines one aspect called WhereDoesTheTimeGo (the weaver will expect to find the class for this type on the classpath). In fact for a simple case like this, the compiler can produce suitable xml just by specifying a flag at compile time. So now I'll use that flag and build the aspect into a reusable aspect library jar.

ajc WhereDoesTheTimeGo.java -outxml -outjar timing.jar

The timing.jar will now contain an aop-ajc.xml (in a META-INF directory) and the class file for the compiled aspect.

jar -tvf timing.jar
  55 Wed Feb 25 22:06:30 GMT 2009 META-INF/MANIFEST.MF
5149 Wed Feb 25 22:06:32 GMT 2009 WhereDoesTheTimeGo.class
  85 Wed Feb 25 22:06:32 GMT 2009 META-INF/aop-ajc.xml

The one generated by -outxml is called META-INF/aop-ajc.xml (being in the META-INF folder is important!). That name is chosen for the generated one so it does not clash with (or overwrite) any aop.xml I might be working on separately that contains more advanced options. The agent is going to merge together the contents of all the xml config files it finds and use the combination to configure the weaver.

It is ready to go, I just need to launch the VM with the AspectJ agent, see the -javaagent option here:

java -javaagent:<pathToAspectj>/lib/aspectjweaver.jar
     -classpath "code;timing.jar;<pathToAspectj>/lib/aspectjrt.jar" Simple

   execution(void Simple.count(int, int)) took 1ms
 execution(void Simple.countFast(int)) took 6ms
   execution(void Simple.count(int, int)) took 5114ms
 execution(void Simple.countSlow(int)) took 5114ms
execution(void Simple.main(String[])) took 5121ms

The Simple class is woven as the VM loads it. The classpath requires: my Simple class (now in the code directory), the aspect library (containing the aspect .class and the xml) and finally the aspectj runtime jar. Running without either the agent specified or the aspect library on the classpath will execute Simple program normally.

Now that's a nice simple scenario, but what about when things aren't going so well... What on earth should I do if just don't see the aspect weaving anything? How do I know what is going on at load time?

To explore what the system is doing, I need to expand my aop-ajc.xml file. Firstly I just want to know the basics about what AspectJ is up to. The xml file can have a weaver section where various options can be configured - many of which match the options that can be specified when calling the compiler on the command line. AspectJ will merge together any suitable aop xml files it discovers on the classpath in order to define the behaviour of a weaver, so I can either modify my existing aop-ajc.xml inside the jar or create another one just for trying out some options.

For now I will modify the existing one - so I extract it from the jar, update it and pack it back into the jar. Here is the new one:

<aspectj>
 <aspects>
   <aspect name="WhereDoesTheTimeGo"/>
 </aspects>
 <weaver options="-verbose"/>
</aspectj>

I've turned on verbose mode for the weaver. Now on running it I will see:

[AppClassLoader@9fbe93] info AspectJ Weaver Version DEVELOPMENT 
                        built on Wednesday Feb 25, 2009 at 21:17:03 GMT
[AppClassLoader@9fbe93] info register classloader sun.misc.Launcher$AppClassLoader@9fbe93
[AppClassLoader@9fbe93] info using configuration
                        file:/C:/blog/timing.jar!/META-INF/aop-ajc.xml
[AppClassLoader@9fbe93] info register aspect WhereDoesTheTimeGo
[AppClassLoader@9fbe93] info processing reweavable type WhereDoesTheTimeGo: 
                        WhereDoesTheTimeGo.java

   execution(void Simple.count(int, int)) took 0ms
 execution(void Simple.countFast(int)) took 3ms
   execution(void Simple.count(int, int)) took 5003ms
  execution(void Simple.countSlow(int)) took 5003ms
execution(void Simple.main(String[])) took 5007ms

What does it all mean? Firstly all weaver messages are prefixed with the classloader the weaver instance is attached to - in a multi classloader setup this can really help me understand the mixed up verbose output. The first message gives the version number of the weaver being used then it tells me the xml configuration file that will be used for this weaver ( file:/C:/blog/timing.jar!/META-INF/aop-ajc.xml) and then the messages tell me which aspects have been defined based on that configuration.

Running with the verbose option can at least tell me if the weaver is being created and that the agent setup is correct. But it still will not tell me if any weaving is occurring. For that I would use the additional option ' -showWeaveInfo' exactly the same as I would on the command line.

<aspectj>
 <aspects>
   <aspect name="WhereDoesTheTimeGo"/>
 </aspects>
 <weaver options="-verbose -showWeaveInfo"/>
</aspectj>

[AppClassLoader@9fbe93] info AspectJ Weaver Version DEVELOPMENT 
                        built on Wednesday Feb 25, 2009 at 21:17:03 GMT
[AppClassLoader@9fbe93] info register classloader sun.misc.Launcher$AppClassLoader@9fbe93
[AppClassLoader@9fbe93] info using configuration 
                        file:/C:/blog/timing.jar!/META-INF/aop-ajc.xml
[AppClassLoader@9fbe93] info register aspect WhereDoesTheTimeGo
[AppClassLoader@9fbe93] weaveinfo Join point 
                        'method-execution(void Simple.main(java.lang.String[]))'
                        in Type 'Simple' (Simple.java:3) advised by around advice
                        from 'WhereDoesTheTimeGo' (WhereDoesTheTimeGo.java:7)
[AppClassLoader@9fbe93] weaveinfo Join point 
                        'method-execution(void Simple.countSlow(int))' 
                        in Type 'Simple' (Simple.java:8) advised by around advice
                        from 'WhereDoesTheTimeGo' (WhereDoesTheTimeGo.java:7)
[AppClassLoader@9fbe93] weaveinfo Join point 
                        'method-execution(void Simple.countFast(int))' 
                        in Type 'Simple' (Simple.java:12) advised by around advice
                        from 'WhereDoesTheTimeGo' (WhereDoesTheTimeGo.java:7)
[AppClassLoader@9fbe93] weaveinfo Join point 
                        'method-execution(void Simple.count(int, int))' 
                        in Type 'Simple' (Simple.java:16) advised by around advice 
                        from 'WhereDoesTheTimeGo' (WhereDoesTheTimeGo.java:7)
[AppClassLoader@9fbe93] info processing reweavable type WhereDoesTheTimeGo: 
                        WhereDoesTheTimeGo.java
    execution(void Simple.count(int, int)) took 1ms
  execution(void Simple.countFast(int)) took 3ms
    execution(void Simple.count(int, int)) took 5005ms
  execution(void Simple.countSlow(int)) took 5005ms
execution(void Simple.main(String[])) took 5016ms

See the new messages prefixed 'weaveinfo' - just as I would expect to see on the command line if weaving via ajc.

The weaver section of the xml configuration can also define which types should be included in or excluded from weaving. Although pointcuts can limit where aspects apply, it is sometimes useful to write these specifications in the xml configuration. As a simple example I can exclude my Simple class from being woven:

<aspectj>
 <aspects>
   <aspect name="WhereDoesTheTimeGo"/>
 </aspects>
 <weaver options="-verbose -showWeaveInfo">
   <exclude within="Simple">
 </weaver>
</aspectj>

Running with that configuration, I can see no weaving messages. Although it might have been nice for the weaver to tell me it excluded my class... and that brings us to the '-debug' option. If it looked like my code was not getting woven even though the right aspects were being defined - I would use the debug option:

<aspectj>
 <aspects>
   <aspect name="WhereDoesTheTimeGo"/>
 </aspects>
 <weaver options="-debug">
   <exclude within="Simple">
 </weaver>
</aspectj>

Now when I run it (notice I've removed -verbose and -showWeaveInfo to limit the output):

[AppClassLoader@9fbe93] debug not weaving 'Simple'

This message indicates the load time weaving infrastructure chose not to weave Simple - and that is due to the include/exclude constraints specified. Finally I will remove my exclude section from the xml and re-run:

[AppClassLoader@9fbe93] debug weaving 'Simple'
[AppClassLoader@9fbe93] debug generating class 'Simple$AjcClosure1'
[AppClassLoader@9fbe93] debug generating class 'Simple$AjcClosure3'
[AppClassLoader@9fbe93] debug generating class 'Simple$AjcClosure5'
[AppClassLoader@9fbe93] debug generating class 'Simple$AjcClosure7'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.Factory'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.SourceLocation'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.MethodSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.MethodSignature'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.CodeSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.MemberSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.SignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.ConstructorSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.ConstructorSignature'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.UnlockSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.UnlockSignature'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.LockSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.LockSignature'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.AdviceSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.AdviceSignature'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.InitializerSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.InitializerSignature'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.CatchClauseSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.CatchClauseSignature'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.FieldSignatureImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.reflect.FieldSignature'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.JoinPoint'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.SignatureImpl$Cache'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.JoinPointImpl$StaticPartImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.SourceLocationImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.JoinPointImpl'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.ProceedingJoinPoint'
[AppClassLoader@9fbe93] debug weaving 'WhereDoesTheTimeGo'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.NoAspectBoundException'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.internal.Conversions'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.StringMaker'
[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.runtime.reflect.SignatureImpl$CacheImpl'
    execution(void Simple.count(int, int)) took 1ms
  execution(void Simple.countFast(int)) took 5ms
    execution(void Simple.count(int, int)) took 5001ms
  execution(void Simple.countSlow(int)) took 5002ms
execution(void Simple.main(String[])) took 5008ms

Due to the weaver now actually doing something, a few more types got loaded during the application run. The debug output is telling me important information:

[AppClassLoader@9fbe93] debug cannot weave 'org.aspectj.lang.ProceedingJoinPoint'
'cannot weave' - indicates the type is in a package for which weaving is forbidden. By default org.aspectj, java. and javax. are all forbidden (so I don't need to exclude them myself). The latter two packages can be woven by the use of extra options in the weaver section.

[AppClassLoader@9fbe93] debug weaving 'Simple'
- the weaver got a chance to process the specified type. IT DOES NOT MEAN THE WEAVER ACTUALLY CHANGED IT (I ought to change that message really, to indicate this). To also see if the type was modified during weaving, I would use -showWeaveInfo in addition to -debug

Armed with those 3 options I can investigate any basic wierdness I see when trying to get started with load time weaving. Even more advanced options can involve turning on weaver trace or dumping the bytecode (before and after it is woven) - but those tend to be used when an AspectJ compiler developer is asking for diagnostics.

More info?
- load time weaving configuration documentation: http://www.eclipse.org/aspectj/doc/released/devguide/ltw-configuration.html
- enabling weaving of java. and javax. packages: https://bugs.eclipse.org/bugs/show_bug.cgi?id=149261#c11