Toplink/java persistency mystery time sink

Question

I have a servlet calling a session bean via a local interface. There is a 3 second pause between the last statement of the session method and the statement following that method call in the servlet.

I have identified what statement in the session bean causes the extra delay upon method return, but I just have no idea why there is such a pause and what is happening:

The session bean method:

public void getXMLByDatesPlCtry(PrintWriter out, Date dateStart, Date dateEnd, int plId, String ctry) throws ParserConfigurationException {

  Query findCtry = em.createNamedQuery("Ctry.findByCtry");
    findCtry.setParameter("ctry", ctry);
    Ctry country = (Ctry) findCtry.getSingleResult();

    findByDatesPlFcIds = em.createNamedQuery("SortTypeInv.findByDatesPlCtry");
    findByDatesPlFcIds.setParameter("dateStart", dateStart);
    findByDatesPlFcIds.setParameter("dateEnd", dateEnd);
    findByDatesPlFcIds.setParameter("plId", plId);
    findByDatesPlFcIds.setParameter("ctry", country);

    inventoryList = findByDatesPlFcIds.getResultList(); // statement causing pain
    logger.warning("about to return");
}

The servlet calling the session bean:

protected void processRequest(HttpServletRequest request, HttpServletResponse response)
throws ServletException, IOException {

[...]

 sortTypeInvFacade.getXMLByDatesPlCtry(out, lastSunday.getTime(), yesterday.getTime(), pl_id, request.getParameter("ctry"));
        Logger.getLogger(InventoryServlet.class.getName()).warning("just received");
    } catch (ParserConfigurationException ex) {
        Logger.getLogger(InventoryServlet.class.getName()).log(Level.SEVERE, null, ex);
    } finally {
        out.close();
    }
}

So the 3 seconds pause happens between the "about to return" log message in the session bean and the "just received" log message in the servlet. It only does that long pause if at some stage the incriminating statement (gathering data into a collection) is called. What's really surprising is that the wasted time is not spent building the collection, but rather upon method return. And in this instance nothing is returned by the method.

Whether the collection is a private variable of the session class or a local variable doesn't change anything. Same goes with making the session bean stateful or stateless.

What is happening? How can that long pause be avoided?

Answer 1

It's hard to answer without knowing your full code.

I would guess it is either related to transaction being committed upon exiting from session bean, or maybe some interceptors that are executing after the exit from session bean.

Also I would try to comment out the .getResultSet() call to see if it has any effect.

Answer 2

My guess is that you have a huge garbage collection triggered. Try enabling the flag that allows you to follow garbage collections.

For the Sun JVM this appears to be -verbose:gc