DTrace @ JavaOne

Well, I can truly say that I had a great time at this years JavaOne. There were several highlights for me but all of them weren't technical (Smashmouth were absolutely excellent on Thursday night). I guess what I enjoyed the most was seeing what's going off in technology areas that are so different to the one that I do for my day to day activities and I picked up some ideas for pet projects that may (or may not) see the light of day this year...

Down to DTrace and Java - it was exciting to see how much interest there is in the marriage of these two technologies. The demo booths in the pavilion seemed to be permanently rammed with people wanting to see what's going off in this area and the hands on labs were very well attended (hats off to Angelo et. al). Simon Ritter and I got the chance to take up the baton from Adam and Jarod this year to present two sessions on DTrace and Java (well, we did the same session twice anyway!). We had a fantastic time doing this and may thanks to everyone who came to see the show and also to those that asked so many interesting and well thought out questions afterwards.

DTrace tends top be a hands-on technology and demo's and talks are best when code is cranked live so that is what we (mostly) did. One of the issues though when demo'ing DTrace is having a workload to observe that isn't too contrived and simplistic but one that also isn't overly complicated. For our JavaOne talk I wanted some Java code that everyone could feel at home with and, standing on the shoulders of giants , I opted for a game from my youth, Space Invaders. I used Kevin Glass's excellent Space Invader game as it was designed as a tutorial and is therefore simple and perfect for a demo like this. As a bunch of people asked for the scripts for this session I thought I'd put down here what I did. What follows are three examples of what we showed on the day in our session. Apologies if what I write is over prescriptive at times for the DTrace long timers but hopefully a bit of detail may help any newcomers to DTrace.

The main aim of this session was to show how you can use the dvm and hotspot providers to obtain new views on your Java code. I then wanted to show how the great work that is being done by Keith McGuigan and team on Java Statically Defined Tracing can be used to enhance that view. All the Java focussed demo's of the session (there were some plain old DTrace ones as well) were done using the hotspot provider which comes with Java SE6 and the SE7 JVM for the JSDT demo's. I wanted to show the approach that I'd taken when first analysing the behaviour of this game so that the attendees could get a view of the kind of approaches you can take when looking at such an application (which may not be the most optimal way BTW!). Anyway, onto the code and analysis.

Example 1 - Looking at the methods

I had the code in one workspace in a netbeans project so that I could easily modify it with and rebuild it quickly. First off I just wanted to look at the methods that were being called to see if anything of interested turned up:

$ cat meth.d
#!/usr/sbin/dtrace -s

hotspot$target:::method-entry
{
	this->str = strjoin(".", copyinstr(arg3, arg4));
	@[strjoin(copyinstr(arg1, arg2), this->str)] = count();
}

Note that the strjoin()'s that I use are just there to make the output pretty. We grab the pid of the relevant jvm:

$ jps
806 Main
813 Game
814 Jps

...run the script and play the game for a few seconds:

$ dtrace -q -s ./meth.d -p 813
\^C
<chop>
  java/util/concurrent/locks/AbstractQueuedSynchronizer.release             5153
  java/util/concurrent/locks/ReentrantLock$NonfairSync.lock             5153
  java/util/concurrent/locks/ReentrantLock$Sync.tryRelease             5153
  sun/java2d/SunGraphics2D.drawImage                             7466
  sun/java2d/pipe/DrawImage.copyImage                            7466
  java/awt/Rectangle.intersects                                108993
  org/newdawn/spaceinvaders/Entity.collidesWith                108994
  java/awt/image/BufferedImage.getHeight                       221725
  java/awt/image/BufferedImage.getWidth                        221725
  java/util/ArrayList.RangeCheck                               227932

So, from the look of the method names this is collision detection code which may or may not be interesting. Let's just take a look at where these methods are being executed by getting stack traces of the RangeCheck method:

$ cat range.d
#!/usr/sbin/dtrace -s

hotspot$target:::method-entry
/copyinstr(arg3, arg4) == "RangeCheck"/
{
	@[jstack(30, 16384)] = count();
}
$ dtrace -q -s ./range.d -p 813
\^C
<chop>
              libjvm.so`__1cNSharedRuntimeTdtrace_method_entry6FpnKJavaThread_pnNmethodOopDesc__i_+0x7b
              java/util/ArrayList.RangeCheck(I)V\*
              org/newdawn/spaceinvaders/Game.gameLoop()V\*
              org/newdawn/spaceinvaders/Game.main([Ljava/lang/String;)V
              StubRoutines (1)
              libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1a3
              libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x27
              libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2f
              libjvm.so`__1cRjni_invoke_static6FpnHJNIEnv__pnJJavaValue_pnI_jobject_nLJNICallType_pnK_jmethodID_pnSJNI_ArgumentPusher_pnGThread__v_+0x1df
              libjvm.so`jni_CallStaticVoidMethod+0x154
              java`JavaMain+0xd30
              libc.so.1`_thr_setup+0x52
              libc.so.1`_lwp_start
             5153

We see that most of them are coming out of the Game.gameLoop() method which probably makes sense if it's collision detection. Looking at the code for this we see:

        for (int p=0;p<entities.size();p++) {
                for (int s=p+1;s<entities.size();s++) {
			Entity me = (Entity) entities.get(p);
			Entity him = (Entity) entities.get(s);
					
			if (me.collidesWith(him)) {
					me.collidedWith(him);
					him.collidedWith(me);
			}
		}
        }

The entities object is an ArrayList so the RangeCheck calls are coming from there (looks like the get() is being optimised out of the stacktrace). Now that we have the area of code in view we can easily see that there is an inefficiency here. This loop goes along the list of entities (aliens, missiles) and sees if the current entity (me) intersects with any other entities. However, note that the current entity, me, is being retreived on every iteration of the inner loop when it only needs to be fetched on the outer loop. We can hoist that out as shown below, rebuild and see what the effect is:

        for (int p=0;p<entities.size();p++) {
		Entity me = (Entity) entities.get(p);
                for (int s=p+1;s<entities.size();s++) {
			Entity him = (Entity) entities.get(s);
					
			if (me.collidesWith(him)) {
					me.collidedWith(him);
					him.collidedWith(me);
			}
		}
        }

$ dtrace -q -s ./meth.d -p 833
<chop>
  java/util/concurrent/locks/AbstractQueuedSynchronizer.release             4747
  java/util/concurrent/locks/ReentrantLock$NonfairSync.lock             4747
  java/util/concurrent/locks/ReentrantLock$Sync.tryRelease             4747
  sun/java2d/SunGraphics2D.drawImage                             7144
  sun/java2d/pipe/DrawImage.copyImage                            7144
  java/awt/Rectangle.intersects                                104874
  org/newdawn/spaceinvaders/Entity.collidesWith                104874
  java/util/ArrayList.RangeCheck                               117608
  java/awt/image/BufferedImage.getHeight                       213326
  java/awt/image/BufferedImage.getWidth                        213326

And we see that the RangeCheck method has dropped down the list accordingly.

Example 2 - Shots gone Wild!

I wanted to provide an example where we could write some simple D to drill down on a particular aspects of the games behaviour that may be of interest. In a game like this there are really only a few things that are of great interest and any interaction a user has is one of these areas. The example I took next was to look at detecting when a missile has gone off the screen (as opposed to hitting an alien) to demonstrate the kind of things we do to differentiate events in D scripts. The code for moving a missile is the ShotEntity.move method:

	public void move(long delta) {
		// proceed with normal move
		super.move(delta);
		
		// if we shot off the screen, remove ourselfs
                
		if (y < -100) {
			game.removeEntity(this);
		}
	}

So, we just need to look for the case where we calling game.removeEntity when we are in the ShotEntity.move method. The script that I created to show this is:

$ cat shotmiss.d
#!/usr/sbin/dtrace -s

hotspot$target:::method-entry
/basename(copyinstr(arg1,arg2)) == "ShotEntity" &&
	copyinstr(arg3, arg4) == "move"/
{
	self->in = 1;
}

hotspot$target:::method-entry
/self->in && copyinstr(arg3, arg4) == "removeEntity"/
{
	printf("Missile Missed!\\n");
}

hotspot$target:::method-return
/basename(copyinstr(arg1,arg2)) == "ShotEntity" &&
	copyinstr(arg3, arg4) == "move" && self->in/
{
	self->in = 0;
}

So, we probe method-entry and build up the predicate to show our interest in ShotEntity.move. Note that I use the D basename() subroutine to pull the class name out of the fully qualified package name. By setting the thread local variable, in, when we enter the move method we can then predicate upon that in the following clause to ensure that we only show interest in removeEntity calls that originate from ShotEntity.move. The third clause makes sure that we unset the in thread local variable when we return from the ShotEntity.move method as we're done.

Java Statically Defined Tracing

Java Statically Defined Tracing is the Java equivalent of USDT and should be arriving in Java SE7. Augmenting the SpaceInvader game to use JSDT was simple. I first defined my provider by extending the Provider interface:

@ProviderName("Invader")
interface MyProvider extends Provider {
    @ProbeName("boom") void death(String type);
    void miss(int nothing);
}

Note that although I have named the provider, MyProvider, I have used an annotation to override this name so that it will appear as Invader. You'll see I also did the same with the probe named death. This is for no other reason than to demonstrate the annotations. As you see above, the provider has two probes defined, death which takes a String as its argument and, miss which takes an integer as its argument.

In the Game class's constructor I created the instance of the ProviderFactory from which I then create my provider (read Keith's blog referenced above for why it's done this way):

        provider = ProviderFactory.getDefaultFactory().createProvider(MyProvider.class);

Note that provider is defined as public MyProvider provider in the Game classes public data. Adding probes is then trivial as we just insert calls in our code where suitable. I had two probe placements, one which is taken from the last hotspot example, to show missiles going off screen. The ShotEntity.move code now becomes:

 public void move(long delta) {
    // proceed with normal move
    super.move(delta);
    
    // if we shot off the screen, remove ourselfs
    if (y < -100) {
      game.provider.miss(1);
      game.removeEntity(this);
    }
  }

I also added the death probe into where Entities (aliens and missiles) are destroyed in Game.removeEntity. I also added in here some code to demonstrate the JSDT mechanism for checking whether a probe is enabled or not. We can use this technique of the code taken to construct probe arguments is costly and therefore we only want to do it when a probe is enabled. The code for this looks like:

	public void removeEntity(Entity entity) {
                Method m = null;
                String ent = null;
                
                try {
                        m = MyProvider.class.getMethod("death", String.class);
                }
                catch (NoSuchMethodException e) {
                        System.out.println("Can't find probe");
                }
                Probe p = provider.getProbe(m);
                
                if (p.isEnabled() ) {
                    // Do argument prep in here
                    if (entity instanceof AlienEntity)
                        ent = "Alien";
                    else if (entity instanceof ShotEntity)
                        ent = "Missile";
                    else
                        ent = "Unknown Object";
                }
 
                provider.death(ent);
		removeList.add(entity);
	}

We obtain a reference to the provider from which we can then verify whether or not a probe is currently enabled. Smart! If it is I then check what type of object is being removed and prepare a suitable string to pass as an argument to the death probe. Building the code and running it we then see the following probes available:

$ dtrace -l -P Invader\*
   ID   PROVIDER            MODULE                          FUNCTION NAME
70483 Invader899      java_tracing                       unspecified miss
70484 Invader899      java_tracing                       unspecified boom

I then cranked the following script which shows us how many aliens were destroyed, how many missiles were fired and how many of those went off the screen (i.e. missed their targets)

$ cat alien.d
#!/usr/sbin/dtrace -s

Invader\*:::miss
{
	@[probename] = count();
}

Invader\*:::boom
{
	@[copyinstr(arg0)] = count();
}

Running this against the game and playing a level we saw:

$ dtrace -q -s ./alien.d    
\^C

  miss                                                             18
  Alien                                                            60
  Missile                                                          78
$ 

18 misses out of 78 shots! Poor indeed! One thing that was immediately obvious to those watching this was the much, much reduced probe effect of the JSDT version. With the hotspot techniques we have visible probe effect owing to the mechanisms being used by that provider but the JSDT version is slick and fast.

The last thing I demo'd for fun was the integration of these newly created JSDT based probes with a visualisation technique. I took the Chime Visualisation tool and created a display so we could graph the killing in real time! I did cheat and create the display before the session but it only took a few minutes to do. Here's a screenshot of some realtime destruction:

As you can see from the screenshot, I was a real killing machine until near the end (missile fired in blue , aliens killed in green) when I couldn't hit anything at all for and my miss count (in red) rises rapidly! The point of this demo was not to prove my lack or prowess at SpaceInvaders but rather to show that we have a set of Java API's that you can hook into easily so it's not much effort to plug DTrace into a Java management framework or visualisation tools (just as two examples).

Anyway, that's about it for now. I did do some more hotspot demo's which were interesting but they'll have to save for another time. If you came along to our sessions at JavaOne then I hope you enjoyed it as much as we did.

Comments:

Post a Comment:
Comments are closed for this entry.
About

jonh

Search

Categories
Archives
« April 2014
MonTueWedThuFriSatSun
 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
    
       
Today