 |
Using Mustang's jmap/jhat to profile GlassFish
Posted by jfarcand on February 15, 2006 at 02:34 PM | Comments (6)
Recently I was working on a bug where Grizzly was leaking memory. From the code, I was convinced the leak wasn't in Grizzly (of course :-))! The problem was occurring when GlassFish was stressed during three days. After approximatively 16 hours, some components in GlassFish weren't able to get a file descriptor, so I've suspected a memory leak somewhere in other's code ;-). The test was using JDK 1.5ur7, and it was very hard to find what caused the problem:
ERROR /export1/as90pe/domains/domain1/imq/instances/imqbroker/etc/accesscontrol.properties (Too many open files)
euh....OK I admit I wasn't able to debug this using strace, pfiles etc. and was ready to blame the IMQ team :-). Then I've decided to switch to Mustang to see if I can get a better error message. Thanks to Mustang, I've got:
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
I decided to ping Alan to make sure he wasn't aware of any socket leak, and he recommended I try the improved jhat. I was a little scared of using this tool, and I wasn't sure if I should use strace/truss instead.....I was very very surprised by the new Mustang's jhat. Since then, I can't live without it :-). What I did is:
% jmap -dump:file=heap.bin
And then
% jhat -J-mx512m heap.bin
This started a web server, so I did:
http://localhost:7000
Wow! From that page, I was able to browse the heap and find which object has been created by whom. The histo is a very good starting point:
http://localhost:7000/histo/
because it tells you the number of allocated objects at the time the jmap was executed. From there, you can click and see which object is having reference to what. The instance count is also helpful
http://localhost:7000/showInstanceCounts/includePlatform/
because it tells you the candidate for the memory leak. Finally the SQL query page is amazing:
http://localhost:7000/oql/
I was looking at all the current active HTTP requests, so I did:
select s from com.sun.enterprise.web.connector.grizzly.ReadTask s where s.byteBuffer.position > 0
and got them!!! I don't think you can do this with any available profilers right now.
For Grizzly, the number of java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask was extremely high, because Future aren't gc() unless you explicitely purge() them, which is something I didn't expect (and I'm not the only one I'm sure). Thus I've decided to not use any java.util.concurrent.ScheduledThreadPoolExecutor and instead implement a better strategy for keep-aliving connections...and now the leak disappeared (not to say performance is much better!)
Of course profilers like NetBeans Profiler can always be used....but I've find jmap/jhat so fast and simple to use, not to say I really liked the Object Query Language (OQL) query page where I can get the exact instance I'm looking at....good work J2SE team!!
technorati: grizzly jmap
Bookmark blog post:  del.icio.us  Digg  DZone  Furl  Reddit
Comments
Comments are listed in date ascending order (oldest first) | Post Comment
-
are you sure about the 'Future not being gced unless purged' statement. Your blog gave me the heebie jeebies enough that I did some profiling of some work Ive been doing with a SingleThreadedScheduledExecutor and I was seeing my WeakReferences getting put on the queue. Im going to do some more work investigating the issue, but my initial results indicate that the statement is incorrect. leouser
Posted by: leouser on February 15, 2006 at 08:44 PM
-
hi there jean,
good post.
i will add you to my google feedreader.
BR,
~A
Posted by: anjanb2 on February 15, 2006 at 10:17 PM
-
Yes, I'm sure :-) Grizzly was using Future for tracking idle connection (times out idle connection, like socket.setSoTimeout()). A lot of Future where created and cancelled before their execution. If you take a look at the Javadoc, you will see java.util.Timer suffer the same problem. If you don't call Timer.purge() every X minutes (in my case), you end up with tons of Timer related Task....
Posted by: jfarcand on February 16, 2006 at 06:17 AM
-
Well my test here says differently:
import java.util.concurrent.*;
import java.lang.ref.*;
import java.util.*;
import static java.lang.System.out;
public class TestSE implements Runnable{
static List refs = new ArrayList();
static List sfs = new ArrayList();
static List xes = new ArrayList();
static ScheduledExecutorService ses = Executors.newSingleThreadScheduledExecutor();
//static ScheduledExecutorService ses = new ScheduledThreadPoolExecutor(1);
static ReferenceQueue rq = new ReferenceQueue();
static ReferenceQueue rqx = new ReferenceQueue();
public void testSE(){
out.println("ScheduledExecutorService is an instance of " + ses.getClass());
for(int i = 0; i wr = new WeakReference(sf, rq);
WeakReference wr2 = new WeakReference(x, rqx);
refs.add(wr);
xes.add(wr2);
sfs.add(sf);
}
new Thread(this).start();
}
public void run(){
boolean first = true;
while(true){
try{
if(first){
Thread.sleep(5000);
for(ScheduledFuture sf: sfs){
sf.cancel(true);
}
sfs.clear();
first = false;
}
Thread.sleep(2000);
System.gc();
out.println("SFuture Queue: " + rq.poll());
out.println("X Queue: " + rqx.poll());
}
catch(Exception x){}
}
}
public static class X implements Runnable{
public void run(){
out.println("Running.... " + hashCode() );
}
public void finalize() throws Throwable{
super.finalize();
out.println("An x is being finalized...");
}
}
public static void main(String ... args){
new TestSE().testSE();
}
}
I keep seeing the WeakReferences showing up in the queue and the X class being finalized. Ill have to try the cancel before execution test.
leouser
Posted by: leouser on February 16, 2006 at 09:01 AM
-
Wow! It does appear that if you cancel a SchedueldFuture before its run it doesn't get gced unless purged. My modified test example takes the cancel before run into account:
import java.util.concurrent.*;
import java.lang.ref.*;
import java.util.*;
import static java.lang.System.out;
public class TestSE implements Runnable{
static List refs = new ArrayList();
static List sfs = new ArrayList();
static List xes = new ArrayList();
static List ttasks = new ArrayList();
//static ScheduledExecutorService ses = Executors.newSingleThreadScheduledExecutor();
static ScheduledThreadPoolExecutor ses = new ScheduledThreadPoolExecutor(1);
static ReferenceQueue rq = new ReferenceQueue();
static ReferenceQueue rqx = new ReferenceQueue();
static ReferenceQueue rqx2 = new ReferenceQueue();
static Timer timer = new Timer();
public void testSE(){
out.println("ScheduledExecutorService is an instance of " + ses.getClass());
X xtest = new X3();
ScheduledFuture norunsf = ses.scheduleAtFixedRate(xtest, 100000, 100000, TimeUnit.MILLISECONDS);
WeakReference norunwr = new WeakReference(norunsf, rq);
refs.add(norunwr);
sfs.add(norunsf);
for(int i = 0; i wr = new WeakReference(sf, rq);
WeakReference wr2 = new WeakReference(x, rqx);
refs.add(wr);
xes.add(wr2);
sfs.add(sf);
X2 x2 = new X2();
WeakReference x2r = new WeakReference(x2, rqx2);
xes.add(x2r);
ttasks.add(x2);
timer.schedule(x2, 1000, 1000);
}
new Thread(this).start();
}
public void run(){
boolean first = true;
while(true){
try{
if(first){
Thread.sleep(5000);
out.println(sfs.size());
for(ScheduledFuture sf: sfs){
sf.cancel(true);
}
//ses.purge();
for(TimerTask tt: ttasks)
tt.cancel();
sfs.clear();
ttasks.clear();
first = false;
}
Thread.sleep(2000);
System.gc();
out.println("SFuture Queue: " + rq.poll());
out.println("X Queue: " + rqx.poll());
out.println("TTask Queue: " + rqx2.poll());
}
catch(Exception x){}
}
}
public static class X2 extends TimerTask{
public void run(){
out.println("X2 Running... " + hashCode());
}
}
public static class X implements Runnable{
public void run(){
out.println("Running.... " + hashCode() );
}
public void finalize() throws Throwable{
super.finalize();
out.println("An x is being finalized...");
}
}
public static class X3 extends X implements Runnable{
public void run(){
out.println("Running X3.... " + hashCode() );
}
public void finalize() throws Throwable{
super.finalize();
out.println("An x3 is being finalized...");
}
}
public static void main(String ... args){
new TestSE().testSE();
}
}
Ive only seen the X3 instance get put in the ReferenceQueue when Ive done a purge on the scheduled executor service. All the others can get gced after they have been run. This is truly odd. If you are using an interface from the Executors then you may have yourself an unattackable problem....
leouser
Posted by: leouser on February 16, 2006 at 09:29 AM
-
hmmm... it appears that the canceled before run do get gced. Ive modified the test so that the X3 test waits 10000 ms before executing, it gets canceled before that. From the looks of it, it may have to wait until that time to become eligable for gc.
import java.util.concurrent.*;
import java.lang.ref.*;
import java.util.*;
import java.awt.Toolkit;
import static java.lang.System.out;
public class TestSE implements Runnable{
static List refs = new ArrayList();
static List sfs = new ArrayList();
static List xes = new ArrayList();
static List ttasks = new ArrayList();
static ScheduledExecutorService ses = Executors.newSingleThreadScheduledExecutor();
//static ScheduledThreadPoolExecutor ses = new ScheduledThreadPoolExecutor(1);
static ReferenceQueue rq = new ReferenceQueue();
static ReferenceQueue rqx = new ReferenceQueue();
static ReferenceQueue rqx2 = new ReferenceQueue();
static Timer timer = new Timer();
public void testSE(){
out.println("ScheduledExecutorService is an instance of " + ses.getClass());
X xtest = new X3();
ScheduledFuture norunsf = ses.scheduleAtFixedRate(xtest, 10000, 10000, TimeUnit.MILLISECONDS);
WeakReference norunwr = new WeakReference(norunsf, rq);
refs.add(norunwr);
sfs.add(norunsf);
for(int i = 0; i wr = new WeakReference(sf, rq);
WeakReference wr2 = new WeakReference(x, rqx);
refs.add(wr);
xes.add(wr2);
sfs.add(sf);
X2 x2 = new X2();
WeakReference x2r = new WeakReference(x2, rqx2);
xes.add(x2r);
ttasks.add(x2);
timer.schedule(x2, 1000, 1000);
}
new Thread(this).start();
}
public void run(){
boolean first = true;
while(true){
try{
if(first){
Thread.sleep(5000);
out.println("There are " + sfs.size() + " ScheduledFuture instances...");
for(ScheduledFuture sf: sfs){
sf.cancel(true);
}
//ses.purge();
for(TimerTask tt: ttasks)
tt.cancel();
sfs.clear();
ttasks.clear();
first = false;
}
Thread.sleep(2000);
System.gc();
out.println("SFuture Queue: " + rq.poll());
out.println("X Queue: " + rqx.poll());
out.println("TTask Queue: " + rqx2.poll());
}
catch(Exception x){}
}
}
public static class X2 extends TimerTask{
public void run(){
out.println("X2 Running... " + hashCode());
}
}
public static class X implements Runnable{
public void run(){
out.println("Running.... " + hashCode() );
}
public void finalize() throws Throwable{
super.finalize();
out.println("An x is being finalized...");
}
}
public static class X3 extends X implements Runnable{
public void run(){
Toolkit.getDefaultToolkit().beep();
out.println("Running X3.... " + hashCode() );
}
public void finalize() throws Throwable{
super.finalize();
out.println("An x3 is being finalized...");
}
}
public static void main(String ... args){
new TestSE().testSE();
}
}
This is good to know, but I don't think it will be a killer of my ScheduledFuture work Im doing...
leouser
Posted by: leouser on February 16, 2006 at 09:49 AM
|
java.net RSS Feeds
