As a support consultant at C2B2 I am always looking for handy tools that may be
able to help me or my team in diagnosing our customers middleware
issues. So, when I came across a project called Swiss Java Knife
promising tools for 'JVM monitoring, profiling and tuning' I figured I
should take a look. It's basically a single jar file that allows you to
run a number of tools most of which are similar to the ones that come
bundled with the JDK.
If you're interested in those tools my colleague Matt Brasier did a good introductory webinar which is available here:
Firstly I downloaded the latest jar file from github:
The source code is also available but for the purposes of this look into what it can offer the jar will suffice.
What does it offer?
Swiss Java Knife offers a number of commands:
jps - Similar to the jps tool that comes with the JDK.
ttop - Similar to the linux top command.
hh - Similar to running the jmap tool that comes with the JDK with the -histo option.
gc - Reports information about GC in real time.
mx - Allows you to do basic operations with MBeans from the command line.
mxdump - Dumps all MBeans of the target java process to JSON.
In order to test out the commands that are available I set up a Weblogic server and deployed an app containing a number of servlets that have known issues. These are then called via JMeter to show certain server behaviour:
- excessive Garbage Collection
- high CPU usage
- a memory leak
Finding the process ID
Normally to find the process ID I'd use the jps command that comes with the JDK.
Swiss Java Knife has it's own version of the jps command so I tried that instead.
Running the command:
java -jar sjk-plus-0.1-2013-09-06.jar jps
gives the following output:
5402org.apache.derby.drda.NetworkServerControl start 3250weblogic.Server 4032./ApacheJMeter.jar 3172weblogic.NodeManager -v 5427weblogic.Server 6523sjk-plus-0.1-2013-09-06.jar jps
jps -lv will generally give you everything you need.
OK. Now this one looks more promising. Swiss Java Knife has a command for collecting real time GC statistics. Let's give it a go.
So, running the following command without my dodgy servlet running should give us a 'standard' reading:
java -jar sjk-plus-0.1-2013-09-06.jar gc -p 3016 [GC: PS Scavenge#10471 time: 6ms interval: 113738ms mem: PS Survivor Space: 0k+96k->96k[max:128k,rate:0.84kb/s] PS Old Gen: 78099k+0k->78099k[max:349568k,rate:0.00kb/s] PS Eden Space: 1676k-1676k->0k[max:174464k,rate:-14.74kb/s]] [GC: PS MarkSweep#10436 time: 192ms interval: 40070ms mem: PS Survivor Space: 96k-96k->0k[max:128k,rate:-2.40kb/s] PS Old Gen: 78099k+7k->78106k[max:349568k,rate:0.19kb/s] PS Eden Space: 0k+0k->0k[max:174400k,rate:0.00kb/s]] PS Scavenge[ collections: 31 | avg: 0.0057 secs | total: 0.2 secs ] PS MarkSweep[ collections: 9 | avg: 0.1980 secs | total: 1.8 secs ]
OK. Looks good. Useful to be able to get runtime GC info without having to rely on GC logs which are often not available.
After running my dodgy servlet (containing a number System.gc() calls) we see the following:
[GC: PS Scavenge#9787 time: 5ms interval: 38819ms mem: PS Survivor Space: 0k+64k->64k[max:192k,rate:1.65kb/s] PS Old Gen: 78062k+0k->78062k[max:349568k,rate:0.00kb/s] PS Eden Space: 204k-204k->0k[max:174336k,rate:-5.28kb/s]] [GC: PS MarkSweep#10200 time: 155ms interval: 112488ms mem: PS Survivor Space: 64k-64k->0k[max:192k,rate:-0.57kb/s] PS Old Gen: 78071k+0k->78071k[max:349568k,rate:0.00kb/s] PS Eden Space: 0k+0k->0k[max:174336k,rate:0.00kb/s]] PS Scavenge[ collections: 666 | avg: 0.0046 secs | total: 3.1 secs ] PS MarkSweep[ collections: 689 | avg: 0.1588 secs | total: 109.4 secs ]
A big difference and although not a particularly realistic scenario it's certainly a useful tool for being able to quickly view runtime GC info.
Next up we'll take a look at CPU usage.
Checking CPU usage
Swiss Java Knife has a command that works in a similar way to the linux top command which displays the top CPU processes.
Running the following command should give us the top 10 CPU processes when running normally:
java -jar sjk-plus-0.1-2013-09-06.jar ttop -n 10 -p 5427 -o CPU
2014-03-11T08:56:33.120-0700 Process summary process cpu=2.21% application cpu=0.67% (user=0.30% sys=0.37%) other: cpu=1.54% heap allocation rate 245kb/s  user= 0.00% sys= 0.00% alloc= 0b/s - main  user= 0.00% sys= 0.00% alloc= 0b/s - Reference Handler  user= 0.00% sys= 0.00% alloc= 0b/s - Finalizer  user= 0.00% sys= 0.00% alloc= 0b/s - Signal Dispatcher  user= 0.00% sys= 0.00% alloc= 0b/s - Timer-0  user= 0.00% sys= 0.01% alloc= 96b/s - Timer-1  user= 0.00% sys= 0.01% alloc= 20b/s - [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'  user= 0.00% sys= 0.00% alloc= 0b/s - weblogic.time.TimeEventGenerator  user= 0.00% sys= 0.04% alloc= 245b/s - weblogic.timers.TimerThread  user= 0.00% sys= 0.00% alloc= 0b/s - Thread-7
So far so good, minimal CPU usage. Now I'll run my dodgy servlet and run it again:
Hmmm, not so good:
Unexpected error: java.lang.IllegalArgumentException: Comparison method violates its general contract!
Try once again and we get the following:
2014-03-11T09:00:10.625-0700 Process summary process cpu=199.14% application cpu=189.87% (user=181.57% sys=8.30%) other: cpu=9.27% heap allocation rate 4945kb/s  user=83.95% sys= 2.82% alloc= 0b/s - [ACTIVE] ExecuteThread: '5' for queue: 'weblogic.kernel.Default (self-tuning)'  user=93.71% sys=-0.44% alloc= 0b/s - [ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'  user= 3.90% sys= 4.91% alloc= 4855kb/s - RMI TCP Connection(5)-127.0.0.1  user= 0.00% sys= 0.00% alloc= 0b/s - main  user= 0.00% sys= 0.00% alloc= 0b/s - Reference Handler  user= 0.00% sys= 0.00% alloc= 0b/s - Finalizer  user= 0.00% sys= 0.00% alloc= 0b/s - Signal Dispatcher  user= 0.00% sys= 0.00% alloc= 0b/s - Timer-0  user= 0.00% sys= 0.04% alloc= 1124b/s - Timer-1  user= 0.00% sys= 0.00% alloc= 0b/s - [STANDBY] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'
So, the CPU usage is now through the roof (as expected).
The main issue with this is that similar to the jps command it doesn't really offer much more than the top command. It also threw the exception above many times when trying to run commands ordered by CPU.
Overall, it doesn't really add much to the command already available and unexpected errors are never good.
Finally, we'll take a look at memory usage.
Checking memory usage
For checking memory usage Swiss Java Knife has a tool called hh which it claims is an extended version of jmap -histo. For those not familiar with jmap, it's another of the tools that comes with the JDK which prints shared object memory maps or heap memory details for a process.
So, first of all I run my JMeter test that repeatedly calls my dodgy servlet. This time one that allocates multiple byte arrays each time it's called to simulate a memory leak.
Although it claims to be an extended version of jmap -histo the only real addition is the ability to state how many buckets to view but this can be easily achieved by piping the output of jmap -histo through head. Aside from that the output is virtually identical.
Output from jmap:
num #instances #bytes class name
1: 42124 234260776 [B
2: 161472 24074512 <constMethodKlass>
3: 161472 21970928 <methodKlass>
4: 12853 15416848 <constantPoolKlass>
5: 12853 10250656 <instanceKlassKlass>
6: 84735 9020400 [C
7: 10896 8943104 <constantPoolCacheKlass>
8: 91873 2939936 java.lang.String
9: 14021 1675576 java.lang.Class
10: 10311 1563520 [Ljava.lang.Object;
Output from sjk:
java -jar sjk-plus-0.1-2013-09-06.jar hh -n 10 -p 54271: 56626 386286072 [B
2: 161493 24076192 <constMethodKlass>
3: 161493 21973784 <methodKlass>
4: 12850 15409912 <constantPoolKlass>
5: 12850 10249384 <instanceKlassKlass>
6: 10891 8936672 <constantPoolCacheKlass>
7: 83336 8577720 [C
8: 90525 2896800 java.lang.String
9: 14018 1675264 java.lang.Class
10: 9819 1579400 [Ljava.lang.Object;
Total 996089 500086120
The only other tools available are the commands mxdump and mx which allow access to MBean attributes and operations.
However, trying to run either of these resulted in a Null pointer exception.
At this point I would generally download the code and start to poke about but by now I'd seen enough.
Although a nice idea it's very limited in what it offers. Under the covers it uses the Attach API so requires the JDK and not just the JRE in order to run so the majority of tools available are already provided with the standard JDK. There are a few additions to those tools but nothing that really makes it worthwhile using this instead.
The only tool I could see myself using would be the real-time GC data gathering tool but this would only be of use where GC logs were unavailable and no other monitoring tools were available.
The number of errors seen when running basic commands was also a concern, although this is just a project on github not a commercial offering and doesn't appear to be a particularly active project.
So, a useful tool to add to your diagnostic tool-kit? Not in my opinion. It's certainly an interesting idea and with further work could be useful but for now I'd stick with the tools that are already available.