PerfSpy 8 -- PerfSpyUI, Navigate Java method invocation tree

The spying part is done. Now comes the hard part: you need to play the role of a detective. Spying gives you a lot of information, perhaps too much. If you do not have a detective’s hunch and imagination, you will be drowned in the sea of information. PerfSpy UI won’t be able to help you develop hunch and imagination (reading Agatha might), but it can help you navigate the information and aid you in your detective job. 

The main control in PerfSpyUI is a table tree written with Netbeans OutlineView.

First config perfspy-ui-config.xml:

<?xml version="1.0" encoding="UTF-8"?>

<perfspy>

       

                1)<connection provider="com.perfspy.monitor.dao.SimpleConnectionProvider">   

                        <url>jdbc:oracle:thin:@127.0.0.1:1521:ORCL</url>                       

                        <user>PerfSpyDemo</user> 

                        <password>PerfSpyDemo </password>

               

                </connection>

               

                <ui>

                        2)<tree nodeLimit="1000000"/>  

                        3)<poll frequency="5"/> <!-- pool db every # seconds -->

                </ui>          

       

</perfspy>

1): the database where the spying information is stored.

2): In order not to occur out of memory, if the method invocation tree exceeds 1 million nodes, do not show the tree, just show the summary information.

3): PerfSpyUI can be used to monitor the spying progress. It polls the database every 5 seconds.

The main class for PerfSpyUI is com.perfspy.ui.PerfSpyAdmin. 

Now start up PerfSpyUI and you will see this:

PerfSpy assembles method invocation into a tree structure and present it in a tree control. The tree control is written with Netbeans OutlineView.

It shows: this spying job caught 19 methods. 5 method invocations are not healthy (colored red): one method was invoked repeatedly 5 times with the total execution time 5 seconds. Using the right-clicking menus, you can expand nodes, hide nodes or mark nodes. If a method's return or parameter values start with (More...), you can double click it and view the details. If a value is not primitive, PerfSpy shows it as ClassName@SystemHashCode.

Double click on dolphin:Dolphin@2982dc66 pops up the details of this object. An object is shown as a tree, with the fields as nodes:

Load & Event Overview tab:

Most operations are self-explanatory. The “Save” panel needs some explanation. As a detective, you’ve processed the crime scene, dusted finger prints and taken photos, now you’d like to bag the evidence. In PerfSpy terms, you can navigate the method invocation tree through the contextual menus, filter uninteresting methods, select and mark interesting methods until you have a tree that contains only the most relevant information. You can save this tree into a file. You can load the tree from the file or you can apply the investigation process into the loaded tree: applying the filtering on the loaded tree, marking and selecting nodes etc.

This concludes the basic tutorial of PerfSpy. In later blogs, I will share some tips and tricks on AspectJ. AspectJ, if you are not familiar with it, can cause hair-tearing frustrations. I have gone through quite some while writing this tool, hope you do not have to suffer. 

PerfSpy 7 -- Run AspectJ applications in Eclipse “load-time weaving” style

PerfSpyDemo and PerfSpyAspectDemo are two separate projects. When PerfSpyDemo is running, PerfSpyAspectDemo peeks into PerfSpyDemo (this is called load-time weaving) and spies on Dolphin’s actions. This blog shows you how to run an AspectJ application in Eclipse using "load time weaving".

Compare with compile-time weaving:

• Compile-time weaving: AspectJ weaves aspects into application classes at compile time.
• Load-time weaving: AspectJ weaves aspects into application classes when they are loaded. 

PerfSpyDemo’s dependent libraries are:

To enable load-time weaving, configure PerfSpyDemo’s runtime: 

Run PerfSpyDemo as “AspectJ Load-Time Weaving Applcation”:

Add aspectjwearver.jar into JVM arguments:

Add PerfSpy libraries into LTW AspectPath:

Before you run PerfSpyDemo, you will need to create these Oracle objects for PerfSpy to dump spying information to:

• perfspyseq.sql : sequence for every spied event
• perfspyevent.sql :spied event
• perfspyops.sql : spied method
• perfspyopdetail.sql : detailed information for every spied method

Now, when you start up PerfSpyDemo, PerfSpyAspectDemo sneaks in. PerfSpyAspectDemo manipulates application classes and makes them do things outside their authors’ knowledge (fortunately, it just spies, not steals.)

PerfSpy 6 -- PerfSpy-Config.xml

This is the file that is used by PerfSpy, and you can tweak this file to get the information you need:

Snippet 1:

<!-- you can skip capturing certain methods -->

        <!-- <skip>com.yourcompany.zoo.animal.Dolphin.backflip</skip> -->

       

        1)<entry target="com.yourcompany.zoo.animal.Dolphin">  

                <!-- you can skip capturing certain methods -->

                <!--  <skip>com.yourcompany.zoo.animal.Dolphin.backflip</skip> -->

                2)<detailOps parts="all" all="true">   

  <!-- <detailOp parts="param,return">-->

                  <!--<detailOp>com.yourcompany.zoo.animal.People.Trainer.award</detailOp>-->                        

                 </detailOps> 

                3)<connection provider="com.perfspy.monitor.dao.SimpleConnectionProvider">

                        <url>jdbc:oracle:thin:@127.0.0.1:1521:ORCL</url>               

                        <user>PerfSpyDemo</user>

                        <password>PerfSpyDemo</password>

                </connection>

        </entry>

1): <entry target="com.yourcompany.zoo.animal.Dolphin"> 
Recall PerfSpyDemoAsepct defines cflowOps as:

@Pointcut("cflow(execution(*  com.yourcompany.zoo.animal.Animal.playTricks(..)  ) )")

        public void cflowOps() {

        }

cflowOps captures Animal.playTricks, so it can spy on both Dolphin and Panda. Panda is cute, but everyone knows what it does: eat, sleep and refuse to have babies, so it is not very interesting.  Dolphin, on the other hand, will be really interesting to see. So you can specify the target to be “com.yourcompany.zoo.animal.Dolphin”.

This flexibility is very useful, in a real application, a lot of common functions are taken care of by frameworks. For example, my legacy application uses Struts1, I define cflowOps() to capture org.apache.struts.action.Action.execute(), and in PerfSpy-Config.xml, I configure which specific action I’d like to capture at will. And I can go further and map between a page and a Struts action, and spy on a page through configuration.

2): <detailOps parts="all" all="true"/>

Specify how much information you’d like to capture. It is not always the more, the better. For one thing, the more you capture, the more performance overhead PerSpy imposes. But for this demo application, we can indulge our innate greedy nature, and capture every input parameter and return value (parts="all") of all methods (all="true"). PerfSpy serializes objects into JSon format.

3):     <connection provider="com.perfspy.monitor.dao.SimpleConnectionProvider">

Defines where PerfSpy stores the captured information. PerfSpy uses Oracle, for one simple reason: Oracle has “connect by” feature, which is very convenient for querying hierarchical data. Method invocation is such a hierarchical structure.

Snippet 2:

<analysis>

                <analyzer>com.perfspy.monitor.analyze.SlowAnalyzer</analyzer>

                <analyzer>com.perfspy.monitor.analyze.DuplicationAnalyzer</analyzer>

                <slow>2</slow> <!--in seconds -->

        </analysis>

By default, PerfSpy has 2 code analyzers: SlowAnalyzer (analyze if a method innovation takes too long – exceeding 2 seconds, e.g.), DuplicationAnalyzer (analyze if a method is repeatedly invoked).

Snippet 3:

          <logToDb>

                <queuesize simple="10" detail="3"/>

                <batchsize simple="4" detail="2"/>

        </logToDb> 

This defines how PerfSpy logs information to the database. While PerfSpy is busy spying on every method, it doesn’t log information immediately to the database. PerfSpy weaves around the application flow, once it gets the information it requires, in order not to impede the application flow, it dispatches writing-to-database tasks to a queue, and writing-to-database is done in a separate thread:

queuesize specifies the size limit of the queue. If detailed logging is configured, the task becomes heavier and you should keep fewer tasks in the queue to save memory. detail refers to the queue size when detailed logging is configured.  simple refers to the queue size when detailed logging is not configured.

batchsize specifies how many tasks to be written before committing to the database . If detailed logging is configured, the task becomes heavier and you should commit more often to save memory.

Snippet 4:

<perfspyio>    

<Types>

        1)      <include within="com.yourcompany.zoo"/>                

        </Types>

               

        2) <collection limit="5"/>     

</perfspyio>

1): <include within="com.yourcompany.zoo"/>            

Serialize objects that belong to classes inside package  com.yourcompany.zoo. JDK classes (inside java packages) will be written as well.               

2): <collection limit="5">

If an object is an array, of java.util.Collection type, or of java.util.Map type, specifies how many elements to write. The more you want to capture, the more performance overhead.

PerfSpy 5 -- AOP.xml

AOP.xml defines to the Aspect engine what aspects to use in load-time, and weave options:

<aspectj>

        <aspects>

                <aspect name="com.yourcompany.zoo.PerfSpyDemoAsepct"/>

        </aspects>

        <weaver options="-verbose -showWeaveInfo -debug">

                <include within="com.yourcompany.zoo.animal..*"/>

                <include within="com.yourcompany.zoo.people..*"/>      

               <dump beforeandafter="true" within="com.yourcompany.zoo.animal..*"/>

               <dump beforeandafter="true" within="com.yourcompany.zoo.people..*"/>       

        </weaver>

</aspectj>

“weave” is a vivid word to describe the process that injects your actions (the “what” part of the aspect) into the defined places (the “where” part of the aspect) of the binary classes. Check the loggings:

1) [AppClassLoader@203ba002] debug not weaving 'com.yourcompany.zoo.Show'         

2) [AppClassLoader@203ba002] debug weaving 'com.yourcompany.zoo.animal.Animal'    

3) [AppClassLoader@203ba002] weaveinfo Join point 'method-execution(java.lang.String com.yourcompany.zoo.animal.Animal.getName())' in Type 'com.yourcompany.zoo.animal.Animal' (Animal.java:16) advised by around advice from 'com.yourcompany.zoo.PerfSpyDemoAsepct' (AbstractPerfSpyAspect.java) [with runtime test]                                                          

4) [AppClassLoader@203ba002] weaveinfo Join point 'method-execution(com.yourcompany.zoo.people.Trainer com.yourcompany.zoo.animal.Animal.getTrainer())' in Type 'com.yourcompany.zoo.animal.Animal' (Animal.java:20) advised by around advice from 'com.yourcompany.zoo.PerfSpyDemoAsepct' (AbstractPerfSpyAspect.java) [with runtime test]

5) [AppClassLoader@203ba002] debug generating class 'com.yourcompany.zoo.animal.Animal$AjcClosure1'

6) [AppClassLoader@203ba002] debug generating class 'com.yourcompany.zoo.animal.Animal$AjcClosure3'

1)2):'com.yourcompany.zoo.Show' is not woven while 'com.yourcompany.zoo.animal.Animal' is, because that is how it is defined in aop.xml:

      <include within="com.yourcompany.zoo.animal..*"/>

                <include within="com.yourcompany.zoo.people..*"/>        

3)4):all Animal methods are woven, obeying this PointCut:

      @Pointcut("execution(* com.yourcompany.zoo..*.*(..) )")

        public void withinCflowOps()

Notice, the constructor method of Animal is not woven, because constructor PointCut has to be defined using another syntax.

5)6):The product of the weaving process. AspectJ agent creates these binary parts which replace the original Animal class. You can view these generated classes by adding this into aop.xml weave option:

       <dump beforeandafter="true" within="com.yourcompany.zoo.animal..*"/>

<dump beforeandafter="true" within="com.yourcompany.zoo.people..*"/> 

PerfSpy 4 -- PerfSpyAspectDemo

This Aspect would like to see how an Animal does its tricks. This Aspect has to be versatile: it can spy on a Dolphin, and if configured, spy on a Panda or other animals.

It extends from AbstractPerfSpyAspect and implements the two abstract PointCut:

@Aspect

public class PerfSpyDemoAsepct extends AbstractPerfSpyAspect {

       

        @Pointcut("execution(* com.yourcompany.zoo..*.*(..) )")

        public void withinCflowOps() {

        }

        @Pointcut("cflow(execution(*  com.yourcompany.zoo.animal.Animal.playTricks(..)  ) )")

        public void cflowOps() {

        }

}

cflowOps(): @Pointcut("cflow(execution(*  com.yourcompany.zoo.animal.Animal.playTricks(..)  ) )")

Capture what happens inside the execution of Animal.playTricks. Notice, here the superclass Animal is being spied on.

withinCflowOps():@Pointcut("execution(* com.yourcompany.zoo..*.*(..) )")

Capture all method invocations from classes inside com.yourcompany.zoo packages.

PerfSpy 3 -- PerfSpyDemo

I like dolphin! It is such an intelligent, playful and social animal. It can learn so many tricks, tail-walking, dancing, jumping, you name it. It can even innovate – creating new tricks on their own! Of course, if you have the world’s cutest bottom as a panda does, you do not have to learn tricks to please the crowd – hey, life is not fair and beauty is not just skip-deep.

I am going to use dolphin and panda in my demo, if you think it is silly, bear with me.

In this demo:

Animal is an abstract class with an abstract method playTricks(),Panda and Dolphin extends from it. Show invokes Animal.playTricks() to startAShow(). Animals have a Trainer. Notice how they are inside different packages, it is going to play a role in your Aspect.

public abstract class Animal {

        private String name;

        private Trainer trainer;

        public Animal(String name, Trainer trainer) {

                super();

                this.name = name;

                this.trainer = trainer;

        }

        public String getName() {

                return name;

        }

        public Trainer getTrainer() {

                return trainer;

        }

        public abstract void playTricks() throws Exception;

}

Dolphin does a lot of things in a show:

public class Dolphin extends Animal {

        private List friends = new ArrayList();

        public Dolphin(String name, Trainer trainer) {

                super(name, trainer);

                friends.add(trainer);

                //a bit narcissistic, friends with himself 100 times

                for (int i = 0; i < 100; i++) {

                        friends.add(this);

                }

        }

        @Override

        public void playTricks() throws Exception {

                shakeHands(this.getTrainer());

                tailWalk(10);

                for (int i = 0; i < 5; i++) {

                        backflip(i);

                }

        }

        private void addFriend(Object friend) {

                this.friends.add(friend);

        }

        private void tailWalk(int length) {

                System.out.println(this.getName() + " is tail walking " + length + " meters ...");

        }

        private void backflip(int index) throws Exception {

                System.out.println(this.getName() + " is backflipping " + index + " time ...");

//mimic slow methods

                Thread.sleep(1 * 1000);

        }

        private void shakeHands(Trainer trainer) {

                System.out.println(this.getName() + " is shaking hands with " + trainer.getName() + " ...");

                trainer.award(this);

        }

}

On the other hand, Panda simply needs to be a Panda:

public class Panda extends Animal{

        public Panda(String name, Trainer trainer) {

                super(name, trainer);          

        }

        @Override

        public void playTricks() {     

                beingCute();

        }

       

        private String beingCute(){

                return "being cute...";

        }

       

}

Here is a Show:

public class Show {

        public void startAShow(String type) throws Exception {

                Trainer trainer;

                Animal animal;

                if (type.equals("dolphin")) {

                        trainer = new Trainer("Lucy");

                        animal = new Dolphin("Noodle", trainer);

                } else {

                        trainer = new Trainer("xiaowang");

                        animal = new Panda("lingling", trainer);

                }

                animal.playTricks();

        }

        public static void main(String[] args) throws Exception {

                new Show().startAShow(args[0]);

        }

}