Swiss Java Knife - A useful tool to add to your diagnostic tool-kit?

OK, so now we've got the process ID of our server we can start to look at what is going on. First of all, lets check garbage collection.

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
[000001] user= 0.00% sys= 0.00% alloc=     0b/s - main
[000002] user= 0.00% sys= 0.00% alloc=     0b/s - Reference Handler
[000003] user= 0.00% sys= 0.00% alloc=     0b/s - Finalizer
[000004] user= 0.00% sys= 0.00% alloc=     0b/s - Signal Dispatcher
[000010] user= 0.00% sys= 0.00% alloc=     0b/s - Timer-0
[000011] user= 0.00% sys= 0.01% alloc=    96b/s - Timer-1
[000012] user= 0.00% sys= 0.01% alloc=    20b/s - [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'
[000013] user= 0.00% sys= 0.00% alloc=     0b/s - weblogic.time.TimeEventGenerator
[000014] user= 0.00% sys= 0.04% alloc=   245b/s - weblogic.timers.TimerThread
[000017] 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
[000040] user=83.95% sys= 2.82% alloc=     0b/s - [ACTIVE] ExecuteThread: '5' for queue: 'weblogic.kernel.Default (self-tuning)'
[000038] user=93.71% sys=-0.44% alloc=     0b/s - [ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'
[000044] user= 3.90% sys= 4.91% alloc= 4855kb/s - RMI TCP Connection(5)-127.0.0.1
[000001] user= 0.00% sys= 0.00% alloc=     0b/s - main
[000002] user= 0.00% sys= 0.00% alloc=     0b/s - Reference Handler
[000003] user= 0.00% sys= 0.00% alloc=     0b/s - Finalizer
[000004] user= 0.00% sys= 0.00% alloc=     0b/s - Signal Dispatcher
[000010] user= 0.00% sys= 0.00% alloc=     0b/s - Timer-0
[000011] user= 0.00% sys= 0.04% alloc=  1124b/s - Timer-1
[000012] 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 5427

    1:         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.

Conclusion

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.