Qants – Tips in the field of Java Performance & Software Testing

Last week i was running some performance tests, using an increasing number of users, without restarting my Glassfish Application Server. It occured to me at some point in time, that although my scripts were not running (taking a pause), the Glassfish Application Server was returning some interesting warnings, that immediately got my attention.

The first thing to see, was the warnings referred to the passivation of an Entity Bean. More specifically, this was the error returned:

passivateEJB(), Exception caught -> java.io.IOException: java.io.IOException

at com.sun.ejb.base.io.IOUtils.serializeObject(IOUtils.java:105)
at com.sun.ejb.containers.util.cache.LruSessionCache.saveStateToStore(LruSessionCache.java:508)
at com.sun.ejb.containers.util.cache.LruSessionCache.passivateEJB(LruSessionCache.java:433)
at com.sun.ejb.containers.StatefulSessionContainer.passivateEJB(StatefulSessionContainer.java:1784)

Caused by: java.io.IOException

Caused by: java.io.NotSerializableException: java.util.logging.Logger

Now, after carefully reading once more the lifecycle of an Entity Bean, i realised that in order for something like this to happen, the Bean must have reached it’s cache idle timeout before being moved to the pool (passivation) (default in Glassfish is set to 600 seconds = 10 minutes) . That meant  first of all, that the application using the bean, was not calling the remove method, which would have caused the EJB container to call the ejbRemove method.

I was therefore more than interested to see some statistics on the bean. So i turned to my Glassfish Administrator, hoping that i will find the option of down-drilling the Entity Beans, and checking on their status.I wasn’t very surprised to see that although the Glassfish Monitoring allows setting different levels on monitoring the EJB’s, it doesn’t really provide any “friendly” interface for “reading” the information.

So i had to go the hard way…digging in command line.

Now, it may seem difficult in the beginning, but once you know how to filter all the information (and i am also still struggling on that), it can get easier. Here is what you have to do:

1. Run “asadmin” in your console
2. type the following to list the  monitorable components for instance server:
   list –user admin –monitor server*
3. extract the name of the bean you want to collect statistics for. Let’s call it MyBean
4. type the following to collect the statistics on the bean:
   get -m –user admin *.MyBean.*

This will return a lot of statistics on the bean. I was interested in the number of created beans, running with 50 virtual users, and i wasn’t surprised at all to see this:

MyBean.createcount-count = 50

MyBean.removecount-count = 0

So i made one thing sure. A bean was instantiated for every virtual user of mine, but the remove method was never called. Point taken!

Now, i still had one question…why wasn’t the Bean able to be passivated.

Well, the secret here is that the ejb passivation fails because ejb has a Logger object and it cannot be serialized, hence the two log entries above:

at com.sun.ejb.base.io.IOUtils.serializeObject(IOUtils.java:105)

Caused by: java.io.NotSerializableException: java.util.logging.Logger

The solution here as i know, would be to make the logger transient. That way it won’t be serialized no more, and you have a “clean” passivation. But that is not the subject of the post, so if i am wrong on the last point here, please do correct me.

Cheers, and have a good night. I am still a little waisted after watching the U2 concert live on YouTube , so i’m heading home now.

Alex