Blog ITPlace

VisualVM is tool for profiling Java applications made by Sun. Today I would like to write about my experience with it.

Some time ago I was experimenting with game programming in Java. I wrote clone of famous Boulder Dash game. When playing the game on different machines I found out that it eats terrible amount of CPU time. What? The original was running nicely on 8bits ZX Spectrum ;). I started looking into the code and optimize it. Some hours later the performance got better but still not good enough. I came to the point where I could
not proceed any further. All my algorithms looked nice and clean. I delayed the solution and left it as it was.

Recently I have heard about VisualVM and I decided to give it a try.

Making it run

Installation was smooth. I just downloaded the zip archive from https://visualvm.dev.java.net/, extracted it and run. The first run of VisualVM resulted into warning message: Local Applications Cannot Be Detected. But the issue is nicely documented directly on VisualVM site and the solution took me only few seconds (see https://visualvm.dev.java.net/…hooting.html#… for details).

Finding a big spender

After I started-up the game i was able to see it as local java application in VisualVM applications panel to the left:

As you can see it is using up to 80% of my 2.4GHz Sempron which is quite a lot. I was going to find out what is eating so much performance so i clicked on Profiler tab and opened the settings by checking the checkbox to the right:

At first I left all settings as set by default except Start profiling from classes, where I put com.spekacek.boulder.**. Then I started up CPU profiling. Then I was playing the game for few moments – profiling slows everything down so it was not a big fun. Then I hit Snapshot button and I got following report:

In CPU snapshot view you can see how much time did it take to process each method. In the case of my game the obvious winner is GamePanel.paintLevelData() method. It was called 3858 times and sum of the times spent calling it is 38865 miliseconds which is 70.2% of time in AWT-EventQueue-1 thread. Look at Self time item right beneath GamePanel.paintLevelData(). This is time spend calling not instrumented methods – methods which don't match with the settings we did before starting the profiling.

To be able to look more deeply into what is going on in GamePanel.paintLevelData() I started-up new profiling session. this time I set Start profiling from classes to com.spekacek.boulder.view.GamePanel and cleared everything in Do not profile classes setting – I want to profile everything starting from com.spekacek.boulder.view.GamePanel and I don't want any exclusions. Then I started-up the CPU profiling again and after a while of playing the game I made another snapshot. This is what I got:

Now you can see that inside GamePanel.paintLevelData() method the biggest spender is SunGraphics2D.drawImage() method. It was called 313218 times and sum of the times spent calling it is 21622 miliseconds.

So now I know where the problem lies and I can focus myself on fixing it. I know that I have to paint game levels faster. I can try either to reduce number of SunGraphics2D.drawImage() calls or find a faster alternative. But this is not the topic of this article.

Conclusion

I like this tool. It is very simple an intuitive – not very different from highly advanced JProfiler. It can do much more than I described in this humble article including memory profiling, heap viewer, etc. In short it can help you to find weak spots in your application for free. Good job guys! :)

Some links

• https://visualvm.dev.java.net/ – VisualVM Homepage
• http://en.wikipedia.org/…Boulder_Dash – some information about Boulder Dash, the best game ever.
• http://boulder.spekacek.com/ – Java Dash homepage, including still not fully optimized Boulder Dash clone ;)

Jan Šmuk Performance