Useful tool

From time to time, I need to get a clue about what some code is doing. Of course, I can - and do - read the code. But when it's highly concurrent, and the stack is deep, I would like to get an immediate vision of the stack trace for a complete execution.

I'm using a small tool called JIP : Java Interactive Profiler. I'm not sure why they added interactive in the name, because there is nothing interactive once you have launch your program, but anyway...

So how does it work ? Simple : you add some instruction in your command line, run your program, and get back some trace. Let's see with an exemple. Yesterday evening, I did some debugging session with MINA and I wanted the trace generated for the server initialization, and a simple client call. I added this argument in the server command line :

-javaagent:/Users/elecharny/jip-1.1.1/profile/profile.jar -Dprofile.properties=/Users/elecharny/jip-1.1.1/profile/profile.properties

and run my server. The profile.properties has just been modified slightly to fit my need :

profiler=on

remote=off

port=15599

ClassLoaderFilter.1=com.mentorgen.tools.profile.instrument.clfilter.StandardClassLoaderFilter

thread-depth=-1

thread.compact.threshold.ms=1

max-method-count=cw-1compact

method.compact.threshold.ms=1

file=/Users/elecharny/jip-1.1.1/profile.txt

exclude=org.eclipse,org.junit,org.slf4j,org.apache.log4j,org.apache.commons

track.object.alloc=on

output=text

output-method-signatures=yes

clock-resolution=ms

Basically, I just set a file name to store the trace, filter some classes, extended the thread depth to infinite. The property file itself is quite well documented, and it should not be a problem to run the tool with a very minimum RTFming.

Here is a sample of the trace I got :

+------------------------------
| Thread: 1
+------------------------------
           Time            Percent
    ----------------- ---------------
Count    Total      Net   Total     Net  Location
=====    =====      ===   =====     ===  =========
  1    422.1     96.1   100.0    22.8  +--Server:main        (mina.test2)
  1    106.8     23.9    25.3     5.7  | +--NioSocketAcceptor: (org.apache.mina.transport.socket.nio)
  1     82.7     16.1    19.6     3.8  | | +--AbstractPollingIoAcceptor:       (org.apache.mina.core.polling)
  1     24.4      0.0     5.8          | | | +--SimpleIoProcessorPool: (org.apache.mina.core.service)
  1     24.4     11.1     5.8     2.6  | | | | +--SimpleIoProcessorPool:       (org.apache.mina.core.service)
  1     13.1      6.4     3.1     1.5  | | | | | +--NioProcessor:      (org.apache.mina.transport.socket.nio)
  1      6.7      6.5     1.6     1.5  | | | | | | +--AbstractPollingIoProcessor:      (org.apache.mina.core.polling)
  1     30.9      0.8     7.3     0.2  | | | +--AbstractPollingIoAcceptor:     (org.apache.mina.core.polling)
  1     30.0      0.1     7.1          | | | | +--AbstractIoAcceptor:  (org.apache.mina.core.service)
  1     29.9     11.9     7.1     2.8  | | | | | +--AbstractIoService: (org.apache.mina.core.service)
  2     15.7     13.8     3.7     3.3  | | | | | | +--NioSocketAcceptor:getTransportMetadata (org.apache.mina.transport.socket.nio)
  1      1.8      1.7     0.4     0.4  | | | | | | | +--DefaultTransportMetadata:      (org.apache.mina.core.service)
  1     16.1      0.1     3.8          | +--IoBuffer:wrap    (org.apache.mina.core.buffer)
  1     16.1      0.0     3.8          | | +--IoBuffer:wrap  (org.apache.mina.core.buffer)
  1     16.0     15.9     3.8     3.8  | | | +--SimpleBufferAllocator:wrap   (org.apache.mina.core.buffer)
  1      8.3      8.1     2.0     1.9  | +--BufferCodec:       (mina.test2)
  1      1.3      1.1     0.3     0.3  | +--DefaultIoFilterChainBuilder:addLast      (org.apache.mina.core.filterchain)
  1     17.3      0.0     4.1          | +--AbstractIoAcceptor:bind  (org.apache.mina.core.service)
  1     17.3      0.1     4.1          | | +--AbstractIoAcceptor:bind        (org.apache.mina.core.service)
  1     16.9      1.0     4.0     0.2  | | | +--AbstractPollingIoAcceptor:bindInternal       (org.apache.mina.core.polling)
  1      4.2      1.5     1.0     0.4  | | | | +--AbstractPollingIoAcceptor:startupAcceptor  (org.apache.mina.core.polling)
  1      2.6      0.1     0.6          | | | | | +--AbstractIoService:executeWorker  (org.apache.mina.core.service)
  1      2.6      2.3     0.6     0.5  | | | | | | +--AbstractIoService:executeWorker        (org.apache.mina.core.service)
  1     11.1     11.1     2.6     2.6  | | | | +--NioSocketAcceptor:wakeup   (org.apache.mina.transport.socket.nio)
+------------------------------
| Thread: 11
+------------------------------

This first stack trace is the server bind() method execution.

Here is the stack trace for a message being processed :

+------------------------------
| Thread: 14
+------------------------------
              Time            Percent   
       ----------------- ---------------
 Count    Total      Net   Total     Net  Location
 =====    =====      ===   =====     ===  =========
     1   1115.2      0.1   100.0          +--NamePreservingRunnable:run (org.apache.mina.util)
     1   1115.1      0.6   100.0          | +--AbstractPollingIoProcessor$Processor:run (org.apache.mina.core.polling)
     6   1048.9   1048.9    94.1    94.1  | | +--NioProcessor:select    (org.apache.mina.transport.socket.nio)
     6      2.1      0.1     0.2          | | +--AbstractPollingIoProcessor:access$6    (org.apache.mina.core.polling)
     6      2.0      0.0     0.2          | | | +--AbstractPollingIoProcessor:handleNewSessions (org.apache.mina.core.polling)
     1      2.0      0.1     0.2          | | | | +--AbstractPollingIoProcessor:addNow  (org.apache.mina.core.polling)
     1      1.2      0.6     0.1          | | | | | +--IoServiceListenerSupport:fireSessionCreated      (org.apache.mina.core.service)
     6     24.2      0.1     2.2          | | +--AbstractPollingIoProcessor:access$9    (org.apache.mina.core.polling)
     6     24.2      0.1     2.2          | | | +--AbstractPollingIoProcessor:flush     (org.apache.mina.core.polling)
     3     20.8      0.0     1.9          | | | | +--NioProcessor:getState      (org.apache.mina.transport.socket.nio)
     3     20.8     20.7     1.9     1.9  | | | | | +--NioProcessor:getState    (org.apache.mina.transport.socket.nio)
     3      3.2      0.2     0.3          | | | | +--AbstractPollingIoProcessor:flushNow        (org.apache.mina.core.polling)
     2      2.3      0.1     0.2          | | | | | +--AbstractPollingIoProcessor:writeBuffer   (org.apache.mina.core.polling)
     6      2.5      0.1     0.2          | | +--AbstractPollingIoProcessor:access$10   (org.apache.mina.core.polling)
     6      2.4      0.0     0.2          | | | +--AbstractPollingIoProcessor:removeSessions    (org.apache.mina.core.polling)
     1      2.3      0.0     0.2          | | | | +--AbstractPollingIoProcessor:removeNow       (org.apache.mina.core.polling)
     1      1.6      0.1     0.1          | | | | | +--IoServiceListenerSupport:fireSessionDestroyed    (org.apache.mina.core.service)
     1      1.5      0.0     0.1          | | | | | | +--DefaultIoFilterChain:fireSessionClosed (org.apache.mina.core.filterchain)
     1      1.2      0.0     0.1          | | | | | | | +--DefaultIoFilterChain:callNextSessionClosed   (org.apache.mina.core.filterchain)
     1      1.1      0.0     0.1          | | | | | | | | +--IoFilterAdapter:sessionClosed      (org.apache.mina.core.filterchain)
     1      1.1      0.0     0.1          | | | | | | | | | +--DefaultIoFilterChain$EntryImpl$1:sessionClosed   (org.apache.mina.core.filterchain)
     1      1.1      0.0     0.1          | | | | | | | | | | +--DefaultIoFilterChain:access$2  (org.apache.mina.core.filterchain)
     1      1.1      0.0     0.1          | | | | | | | | | | | +--DefaultIoFilterChain:callNextSessionClosed   (org.apache.mina.core.filterchain)
     1      1.0      0.0     0.1          | | | | | | | | | | | | +--ProtocolCodecFilter:sessionClosed  (org.apache.mina.filter.codec)
     4     36.0      0.1     3.2          | | +--AbstractPollingIoProcessor:access$8    (org.apache.mina.core.polling)
     4     35.9      0.2     3.2          | | | +--AbstractPollingIoProcessor:process   (org.apache.mina.core.polling)
     4     34.7      0.1     3.1          | | | | +--AbstractPollingIoProcessor:process (org.apache.mina.core.polling)
     2     34.3      0.2     3.1          | | | | | +--AbstractPollingIoProcessor:read  (org.apache.mina.core.polling)
     3      2.3      0.0     0.2          | | | | | | +--NioProcessor:read      (org.apache.mina.transport.socket.nio)
     3      2.2      2.2     0.2     0.2  | | | | | | | +--NioProcessor:read    (org.apache.mina.transport.socket.nio)
     1     31.2      0.0     2.8          | | | | | | +--DefaultIoFilterChain:fireMessageReceived       (org.apache.mina.core.filterchain)
     1     31.0      0.0     2.8          | | | | | | | +--DefaultIoFilterChain:callNextMessageReceived (org.apache.mina.core.filterchain)
     1     30.9      0.0     2.8          | | | | | | | | +--IoFilterAdapter:messageReceived    (org.apache.mina.core.filterchain)
     1     30.9      0.0     2.8          | | | | | | | | | +--DefaultIoFilterChain$EntryImpl$1:messageReceived (org.apache.mina.core.filterchain)
     1     30.9      0.0     2.8          | | | | | | | | | | +--DefaultIoFilterChain:access$5  (org.apache.mina.core.filterchain)
     1     30.9      0.0     2.8          | | | | | | | | | | | +--DefaultIoFilterChain:callNextMessageReceived (org.apache.mina.core.filterchain)
     1     30.8      0.1     2.8          | | | | | | | | | | | | +--ProtocolCodecFilter:messageReceived        (org.apache.mina.filter.codec)
     1      1.3      1.2     0.1     0.1  | | | | | | | | | | | | | +--ProtocolCodecFilter:getDecoderOut        (org.apache.mina.filter.codec)
     1     28.6      0.0     2.6          | | | | | | | | | | | | | +--ProtocolCodecFilter$ProtocolDecoderOutputImpl:flush      (org.apache.mina.filter.codec)
     1     28.6      0.0     2.6          | | | | | | | | | | | | | | +--DefaultIoFilterChain$EntryImpl$1:messageReceived       (org.apache.mina.core.filterchain)
     1     28.5      0.0     2.6          | | | | | | | | | | | | | | | +--DefaultIoFilterChain:access$5        (org.apache.mina.core.filterchain)     1     28.5      0.0     2.6          | | | | | | | | | | | | | | | | +--DefaultIoFilterChain:callNextMessageReceived       (org.apache.mina.core.filterchain)
     1     28.5      0.0     2.6          | | | | | | | | | | | | | | | | | +--DefaultIoFilterChain$TailFilter:messageReceived  (org.apache.mina.core.filterchain)
     1     28.3      0.3     2.5          | | | | | | | | | | | | | | | | | | +--Server$MyIOHandler:messageReceived     (mina.test2)
     1     27.9      0.0     2.5          | | | | | | | | | | | | | | | | | | | +--AbstractIoSession:write      (org.apache.mina.core.session)
     1     27.9      1.4     2.5     0.1  | | | | | | | | | | | | | | | | | | | | +--AbstractIoSession:write    (org.apache.mina.core.session)
     1     26.1      0.0     2.3          | | | | | | | | | | | | | | | | | | | | | +--DefaultIoFilterChain:fireFilterWrite     (org.apache.mina.core.filterchain)
     1     26.1      0.0     2.3          | | | | | | | | | | | | | | | | | | | | | | +--DefaultIoFilterChain:callPreviousFilterWrite   (org.apache.mina.core.filterchain)
     1     26.0      0.0     2.3          | | | | | | | | | | | | | | | | | | | | | | | +--DefaultIoFilterChain$TailFilter:filterWrite  (org.apache.mina.core.filterchain)
     1     26.0      0.0     2.3          | | | | | | | | | | | | | | | | | | | | | | | | +--DefaultIoFilterChain$EntryImpl$1:filterWrite       (org.apache.mina.core.filterchain)
     1     26.0      0.0     2.3          | | | | | | | | | | | | | | | | | | | | | | | | | +--DefaultIoFilterChain:access$7    (org.apache.mina.core.filterchain)
     1     25.9      0.0     2.3          | | | | | | | | | | | | | | | | | | | | | | | | | | +--DefaultIoFilterChain:callPreviousFilterWrite   (org.apache.mina.core.filterchain)
     1     25.9     21.3     2.3     1.9  | | | | | | | | | | | | | | | | | | | | | | | | | | | +--ProtocolCodecFilter:filterWrite      (org.apache.mina.filter.codec)
     1      2.3      2.2     0.2     0.2  | | | | | | | | | | | | | | | | | | | | | | | | | | | | +--ProtocolCodecFilter:getEncoderOut  (org.apache.mina.filter.codec)
     1      1.2      0.5     0.1          | | | | | | | | | | | | | | | | | | | | | | | | | | | | +--ProtocolCodecFilter$ProtocolEncoderOutputImpl:flushWithoutFuture   (org.apache.mina.filter.codec)