Java Scenegraph Profiler : Morten Nobel

« Using Eclipse compil... | Main | Profiling JavaFX... »

27 jul · sø 2008

Java Scenegraph Profiler

Using Java Scenegraph it is easy to build very interactive applications with lots of animations and effects. Even though Java Scenegraph (and the Java2D) does a great job, a too complex scene will hurt the performance. Java Scenegraph only paint the dirty objects on, but when more objects needs to be repainted simultaneously, its a bit hard to figure out what part(s) of the Scenegraph that needs to be improved.

A solution for this problem is a Java Scenegraph profiler, which profiles the rendering of each repaint on node level.

Scenegraph rendering

The Scenegraph rendering mechanism renders a node if it is dirty. The rendering takes place in the render(Graphics2D g, Rectangle dirtyRegion) method, defined as an abstract method in the class SGNode. This class only has two direct subclasses:

SGParent - Base class for nodes that contain one or more children.
SGLeaf - Base class for nodes that can paint [...].

The SGLeaf defines the method render and uses it to to call a paint(Graphics2D g) method (an abstract method defined in the SGLeaf). In other words, in a scenegraph, every node that inherits from SGLeaf has a paint method to do the actual work, and all other nodes (instances of SGParent) uses the render method to reach to the leaves.

However the SGParent objects may also do some work such as applying effects to an offscreen image, so both kinds of objects need to be profiled.

Profiling the rendering

The profiler needs to measure the time every render operation takes. To do this, any subclass of SGNode are added a ProfileEntry object, that will measure the time of each render operation. Before the any scenegraph render method is invoked, the profileEntry.startRendering() is invoked, and after the rendering is finished, the profileEntry.stopRendering() is invoked.

The main purpose of the two methods is to track time on each render operation. The time measuring both handles render time for node inclusive child nodes and node exclusive child nodes (referred to as self time) and keeps track of minimum and maximum of the two types as well.

To identify SGNodes from each other, we also store the class of the SGNode and the ID (a String attribute on SGNode).

The following code shows the ProfileEntry class:

import java.util.LinkedList;

public class ProfileEntry {
    private int numberOfRepaints;
    private long minimumRenderTime = Long.MAX_VALUE;
    private long maximumRenderTime = Long.MIN_VALUE;
    private long minimumSelfRenderTime = Long.MAX_VALUE;
    private long maximumSelfRenderTime = Long.MIN_VALUE;
    private long totalRenderTime = 0;
    private long totalSelfRenderTime = 0;

    private String id;
    private Class profileClass=null;
    
    private long time;
    private long selfRenderTime;

    private ProfileEntry parent;

    private static LinkedList<ProfileEntry> renderStack = new LinkedList<ProfileEntry>();

    public ProfileEntry(Class profileClass) {
        this.profileClass = profileClass;
        ProfilerModel.getProfilerModel().addProfileEntry(this);
    }

    public void startRendering(){
        // set parent reference
        if (!renderStack.isEmpty()){
            parent = renderStack.peek();
        }
        else{
            parent = null;
        }

        renderStack.addFirst(this);
        selfRenderTime = time = System.nanoTime();
    }

    public void stopRendering(String id){
        this.id = id;
        numberOfRepaints++;
        long now = System.nanoTime();
        long timeNanos = now-this.time;
        long time = (timeNanos)/1000000L;
        long selfRenderTime = (now-this.selfRenderTime)/1000000L;
        minimumRenderTime = Math.min(time, minimumRenderTime);
        maximumRenderTime = Math.max(time, maximumRenderTime);
        minimumSelfRenderTime = Math.min(selfRenderTime, minimumSelfRenderTime);
        maximumSelfRenderTime = Math.max(selfRenderTime, maximumSelfRenderTime);

        totalRenderTime += time;
        totalSelfRenderTime += selfRenderTime;
        if (parent!=null){
            parent.selfRenderTime += timeNanos;
        }
        renderStack.removeFirst();
    }

    public int getNumberOfRepaints() {
        return numberOfRepaints;
    }

    public long getMinimumRenderTime() {
        return minimumRenderTime;
    }

    public long getMaximumRenderTime() {
        return maximumRenderTime;
    }

    public long getTotalRenderTime() {
        return totalRenderTime;
    }

    public long getMaximumSelfRenderTime() {
        return maximumSelfRenderTime;
    }

    public long getMinimumSelfRenderTime() {
        return minimumSelfRenderTime;
    }

    public long getAvgRepaintTime(){
        if (numberOfRepaints==0){
            return -1;
        }
        return totalRenderTime /numberOfRepaints;
    }

    public long getSelfAvgRepaintTime(){
        if (numberOfRepaints==0){
            return -1;
        }
        return totalSelfRenderTime/numberOfRepaints;
    }

    public Class getProfileClass() {
        return profileClass;
    }

    public String getId() {
        if (id==null){
            return " - ";
        }
        return id;
    }

    public ProfileEntry getParent() {
        return parent;
    }
}

Note that every instance of ProfileEntry is added to a singleton object ProfilerModel. The purpose of the ProfilerModel is to keep track of all profiled instances and print the profiling data out when the program terminates (using a Runtime.getRuntime().addShutdownHook(Thread)).

The following code shows the ProfilerModel class:

import javax.swing.tree.DefaultMutableTreeNode;
import java.util.*;

public class ProfilerModel {
    private static final int CLASS_NAME_SIZE = 70;
    private Set<ProfileEntry> entries = new HashSet<ProfileEntry>();
    // Singleton
    private static final ProfilerModel profilerModel = new ProfilerModel();

    private ProfilerModel(){
        Runtime.getRuntime().addShutdownHook(new Thread() {
            public void run() {
                printStatHierarchy();
            }
        });
    }

    private void printStatHierarchy() {
        // convert list of ProfileEntries to a Tree
        Map<ProfileEntry, DefaultMutableTreeNode> treeLookup = new HashMap<ProfileEntry, DefaultMutableTreeNode>();
        DefaultMutableTreeNode root = new DefaultMutableTreeNode();
        // Assume one root
        for (ProfileEntry entry:entries){
            if (entry.getNumberOfRepaints()>0){
                addNode(entry, treeLookup, root);
            }
        }

        System.out.println("Profiler model stats");
        final int SPACES = 3;
        final int FIRST_FIELD_WIDTH = CLASS_NAME_SIZE+SPACES*root.getDepth();
        System.out.printf("%-"+FIRST_FIELD_WIDTH+"s %-15s %15s %15s %15s %15s %15s %15s %15s\n", "Class name", "Id", "Avg self time","Self time min","Self time max", "Avg time ms", "Min min ms", "Max time ms", "Frequency");
        System.out.println(spacer(FIRST_FIELD_WIDTH+8*16, '-'));

        List<ProfileEntry> entries = new ArrayList<ProfileEntry>(this.entries);
        Collections.sort(entries, ProfileEntryComparator);
        Enumeration depthFirstEnum = root.preorderEnumeration();

        while (depthFirstEnum.hasMoreElements()){
            DefaultMutableTreeNode node = (DefaultMutableTreeNode) depthFirstEnum.nextElement();
            ProfileEntry entry = (ProfileEntry) node.getUserObject();
            if (entry.getAvgRepaintTime()==-1){
                continue; // never called
            }
            String className = entry.getProfileClass().getName();
            if (className.length()>CLASS_NAME_SIZE){
                className = "..."+className.substring(className.length()-CLASS_NAME_SIZE-3);
            }
            className = spacer(SPACES+node.getLevel(),' ')+className;

            System.out.printf("%-"+FIRST_FIELD_WIDTH+"s %-15s %15d %15d %15d %15d %15d %15d %15d\n", className, entry.getId(),entry.getSelfAvgRepaintTime(),entry.getMinimumSelfRenderTime(),entry.getMaximumSelfRenderTime(),entry.getAvgRepaintTime(), entry.getMinimumRenderTime(), entry.getMaximumRenderTime(), entry.getNumberOfRepaints());
        }
    }

    /**
     * Helper method for converting list of ProfileEntries to a Tree
     */
    private void addNode(ProfileEntry entry, Map<ProfileEntry, DefaultMutableTreeNode> treeLookup, DefaultMutableTreeNode root) {
        if (entry.getParent()==null){
            root.setUserObject(entry);
            treeLookup.put(entry,root);
        }
        else if (treeLookup.get(entry)==null){
            // add parent first
            addNode(entry.getParent(),treeLookup, root);

            DefaultMutableTreeNode parentNode = treeLookup.get(entry.getParent());
            assert parentNode!=null;
            DefaultMutableTreeNode child = new DefaultMutableTreeNode(entry);
            parentNode.add(child);
            treeLookup.put(entry,child);
        }
    }

    private String spacer(int size, char ch){
        char[] c = new char[size];
        Arrays.fill(c, ch);
        return new String(c);
    }

    private Comparator<ProfileEntry> ProfileEntryComparator = new Comparator<ProfileEntry>() {
        public int compare(ProfileEntry o1, ProfileEntry o2) {
            return (int)(o1.getAvgRepaintTime()-o2.getAvgRepaintTime());
        }
    };

    public static ProfilerModel getProfilerModel(){
        return profilerModel;
    }


    public void addProfileEntry(ProfileEntry profileEntry) {
        entries.add(profileEntry);
    }
}

Adding profiler code

I have now created a simple model for profiling scenegraph application. The only thing missing is how this profiler model invoked. One simple solution is to modify every scenegraph node class' render method and call the profiler in the beginning and in the end of each method. However using scenegraph, you could easily have created your own subclasses of one of the scenegraph nodes, and may have overwritten the render method as well. This approach isn't very generic and not flexible in any way (since you would have to remove the profiler code when you are done profiling).

Wouldn't it be cool if we could add the profiler code on the fly, just when we need to run the profiler? I found the solution reading Thorbjørn Ravn Andersen's blog Add Logging at Class Load Time with Java Instrumentation, that mentions "Java 5 added the Java Instrumentation mechanism, which allows you to provide "Java agents" that can inspect and modify the byte code of the classes as they are loaded.".

So the solution is to create a agent that 'enhance' the render methods with a call to the profiling model.

Agent implementation

Like Thorbjørn, I use JBoss "Javassist" library, to modify the byte code. I'm no expert in bytecode, but Javassist let you compile Java code snippets and insert into the byte code class.

The first thing I needed after creating a ClassFileTransformer, was to modify only classes that inherited from SGNode. For each of there classes, I added a private ProfileEntry field named _profileEntry. For every render method, I add a call to the profile entry before and after the render method.

private byte[] doClass(String name, byte[] b) {
        ClassPool pool = ClassPool.getDefault();
        CtClass cl = null;
        try {
            cl = pool.makeClass(new java.io.ByteArrayInputStream(b));
            if (!cl.isInterface() && (
                    JavassistHelper.inheritsFromClass(cl, "com.sun.scenario.scenegraph.SGLeaf") ||
                            JavassistHelper.inheritsFromClass(cl, "com.sun.scenario.scenegraph.SGNode"))){
                // add extra fields to object
                CtField field = CtField.make("private com.mortennobel.scenegraphprofiler.model.ProfileEntry _profileEntry;", cl);
                String init = "new com.mortennobel.scenegraphprofiler.model.ProfileEntry(getClass());";
                cl.addField(field, init);
               
                // add profiling code to methods
                CtBehavior[] methods = cl.getDeclaredBehaviors();
                for (CtBehavior method : methods) {
                    if (!method.isEmpty()) {
                        try{
                            if (isRenderMethod(method)){
                                method.insertBefore("_profileEntry.startRendering();");
                                method.insertAfter("_profileEntry.stopRendering(getID());");
                            }
                        }
                        catch (Exception e){
                            e.printStackTrace();
                        }
                    }
                }

                b = cl.toBytecode();
            }
        } catch (Exception e) {
            System.err.println("Could not instrument  " + name
                    + ",  exception : " + e.getMessage());
        } finally {
            if (cl != null) {
                cl.detach();
            }
        }
        return b;
    }

The full source code of the agent:

import java.lang.instrument.*;

import javassist.*;

public class ProfilerAgent implements ClassFileTransformer {

    private static final String[] ignore = new String[] { "java/", "javax/" };

    public static void premain(String agentArgument,
                               Instrumentation instrumentation) {
        instrumentation.addTransformer(new ProfilerAgent());
    }

    public byte[] transform(ClassLoader loader, String className,
                            Class clazz, java.security.ProtectionDomain domain,
                            byte[] bytes) {

        for (String anIgnore : ignore) {
            if (className.startsWith(anIgnore)) {
                return bytes;
            }
        }
        return doClass(className, bytes);
    }

    private byte[] doClass(String name, byte[] b) {
        ClassPool pool = ClassPool.getDefault();
        CtClass cl = null;
        try {
            cl = pool.makeClass(new java.io.ByteArrayInputStream(b));
            if (!cl.isInterface() && (
                    JavassistHelper.inheritsFromClass(cl, "com.sun.scenario.scenegraph.SGLeaf") ||
                            JavassistHelper.inheritsFromClass(cl, "com.sun.scenario.scenegraph.SGNode"))){
                // add extra fields to object
                CtField field = CtField.make("private com.mortennobel.scenegraphprofiler.model.ProfileEntry _profileEntry;", cl);
                String init = "new com.mortennobel.scenegraphprofiler.model.ProfileEntry(getClass());";
                cl.addField(field, init);
               
                // add profiling code to methods
                CtBehavior[] methods = cl.getDeclaredBehaviors();
                for (CtBehavior method : methods) {
                    if (!method.isEmpty()) {
                        try{
                            if (isRenderMethod(method)){
                                method.insertBefore("_profileEntry.startRendering();");
                                method.insertAfter("_profileEntry.stopRendering(getID());");
                            }
                        }
                        catch (Exception e){
                            e.printStackTrace();
                        }
                    }
                }

                b = cl.toBytecode();
            }
        } catch (Exception e) {
            System.err.println("Could not instrument  " + name
                    + ",  exception : " + e.getMessage());
        } finally {
            if (cl != null) {
                cl.detach();
            }
        }
        return b;
    }

    private boolean isRenderMethod(CtBehavior behavior) throws NotFoundException {
        return "render".equals(behavior.getName()) && behavior.getParameterTypes() != null && behavior.getParameterTypes().length == 2 && behavior.getParameterTypes()[0].getName().equals("java.awt.Graphics2D") && behavior.getParameterTypes()[1].getName().equals("java.awt.Rectangle");
    }
}

Using the agent

The agent and the model are compiled into two separate jars. The agent jar links to both the model jar and the Javassist jar in the manifest. These three jar files must be located in the same directory.

When you want to profiling any Java Scenegraph application, just add the following parameter:

java -javaagent:C:\javaprojects\scenegraphprofiler\dist\profileragent.jar com.mortennobel.scenegraphprofiler.test.SimpleScenegraphDemo

When the application terminates, the profiling data is printed out.

Example profiling

As a simple example of the usage of this profiling model, I have created a simple Java Scenegraph example with two text nodes with edges constantly changing between wide and narrow. On the second text-node, I have added a red shadow effect.

Besides I have named the nodes (using the ID) as follows:

SGGroup: Scene 0

SGTransform.Translate: translate_1

SGText: text_1

SGEffect: effect_2

SGTransform.Translate: translate_2

SGText: text_2

Source code for example code:

import com.sun.scenario.scenegraph.*;
import com.sun.scenario.animation.*;
import com.sun.scenario.effect.Shadow;

import javax.swing.*;
import java.awt.*;
import java.awt.geom.*;

public class SimpleScenegraphDemo extends JFrame {
     
    public SimpleScenegraphDemo() {
        super("Simple Scenegraph Demo");
        JSGPanel panel = new JSGPanel();
        SGNode scene = createScene();
        panel.setScene(scene);
        getContentPane().setLayout(new BorderLayout());
        getContentPane().add(panel, BorderLayout.CENTER);
        setSize(500,500);
        setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
        setVisible(true);
    }

    private SGNode createScene() {
        SGGroup scene = new SGGroup();
        scene.setID("Scene 0");
        SGNode text1 = createText("Hallo world (text1)",50,50, 1);
        scene.add(text1);
        SGNode text2 = createText("Another hallo (text2)",50,250, 2);
        SGEffect effect = new SGEffect();
        effect.setEffect(new Shadow(10, Color.red));
        effect.setChild(text2);
        effect.setID("effect_2");
        scene.add(effect);
        return scene;
    }

    private SGNode createText(String text, int x, int y, int id){
        final SGText txtShape = new SGText();
        txtShape.setMode(SGAbstractShape.Mode.STROKE_FILL);
        txtShape.setFont(new Font("SANS_SERIF",Font.BOLD,80));
        txtShape.setAntialiasingHint(RenderingHints.VALUE_TEXT_ANTIALIAS_ON);
        txtShape.setDrawPaint(Color.gray);
        txtShape.setText(text);
        txtShape.setID("text_"+id);
        Rectangle2D rect2d = txtShape.getBounds();
        Point2D src = new Point.Float(0,(float)rect2d.getY());
        Point2D dest = new Point.Float(0,(float)(rect2d.getY()+rect2d.getHeight()));
        GradientPaint gradientPaint = new GradientPaint(src,Color.decode("#8d8a85"),dest,Color.black);
        txtShape.setFillPaint(gradientPaint);
        SGTransform.Translate translate = SGTransform.createTranslation(x,y,txtShape);
        translate.setID("translate_"+id);
        Clip clip = Clip.create(1000,new TimingTargetAdapter() {
            public void timingEvent(float fraction, long totalElapsed) {
                txtShape.setDrawPaint(new Color(1-fraction,1-fraction,1-fraction));
                txtShape.setDrawStroke(new BasicStroke(fraction*2));
            }
        });
        clip.setRepeatCount(Clip.INDEFINITE);
        clip.start();
        return translate;
    }

    public static void main(String[] args){
        new SimpleScenegraphDemo();
    }
}

The profiling result is:

Profiler model stats
Class name                                                                            Id                Avg self time   Self time min   Self time max     Avg time ms      Min min ms     Max time ms       Frequency
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   com.sun.scenario.scenegraph.SGGroup                                                 -                            0               0               0             160             149             200              12
    com.sun.scenario.scenegraph.SGGroup                                                -                            0               0               0             160             149             200              12
     com.sun.scenario.scenegraph.SGGroup                                              Scene 0                       0               0               0             160             149             200              12
      com.sun.scenario.scenegraph.SGEffect                                            effect_2                    145             137             175             153             145             186              12
       com.sun.scenario.scenegraph.DesktopSGTransformFactory$Translate                translate_2                   0               0               0               7               6              11              12
        com.sun.scenario.scenegraph.SGText                                            text_2                        7               6              11               7               6              11              12
      com.sun.scenario.scenegraph.DesktopSGTransformFactory$Translate                 translate_1                   0               0               0               6               3              14              12
       com.sun.scenario.scenegraph.SGText                                             text_1                        6               3              14               6               3              14              12

From this you can see that the SGEffect is clearly the most expensive render operation.

Downloading the profiler

Binaries: Scenegraphprofiler_0.1_bin.zip

Source: Scenegraphprofiler_0.1_src.zip

Update 0.2 (03-aug-08)

Changes: