Business Flow
The flow of teh business logic is as follows. It loops around 500 time, and it each loop it does some reads, and finally an update.


Method call (No of Calls) {Resulting calls to .equals calls}
-----------------------------------------------------------------
SaveChargeDetails (1)
> UpdateOrSAveInvoiceChargeDetails (1)
> > SaveInvoiceBillingDeviceChargeDetails (500)
> > > GetInvoiceBatch (500) {0.36 M}
> > > > HibernateTemplate.Find (500)
> > > SaveInvoiceBillingDeviceChargeDetails (500)
> > > > HibernateTemplate.load (500)
> > > > HibernateTemplate.get (1500)
> > > > HibernateTemplate.find (1500) {1.12 M}
> > > > GetInvoicePayment (1500)
> > > > > HibernateTeamplate.find (1500) {1.12 M}

> > > > UpdateOrSAveInvoicePaymentChargeTo (1500)
> > > > > .find (3000) {2.25 M}
SaveOrUpdate (1500)

Note: This font color indicates db access, using springs HibernateTemplate.

Problem
Sample Jprobe profiler snapshot indicates the following problem
· Too many calls to InvoiceChargePK.equals(), some 4.88 million calls. The break up of the calls in indicated within brackets in the table above.
· Too many short-lived objects created hence garbage collection is taking too much time

We have put some debug logging at .equals method, basically we printed the attributes of object being compared, and the object with which it is being compared. The attributes displayed are billing device id, and charge type.

The calls to hibernatetemplate.find(), and resulting .equals() calls are as follows (Note that we have 1500 billing device, and charge type – 68305 – 1, 68305 – 6, 68305 – 8, 68306 – 1, 68307 – 6, ……..68805 – 8

Loop 1 - Find (68305 – 1)
1 call to .equals (Comparing 68305 – 1 with 68305 – 1)

Loop 2 - Find (68305 – 6)
2 calls to .equals (Comparing 68305 – 1 with 68305 – 1)
(Comparing 68305 – 6 with 68305 – 6)

Loop 3 – Find (68305 – 8)
3 calls to .equals (Comparing 68305 – 1 with 68305 – 1)
(Comparing 68305 – 6 with 68305 – 6)
(Comparing 68305 – 8 with 68305 – 8)

Loop 4 – Find (68306 – 1)
4 calls to .equals (Comparing 68305 – 1 with 68305 – 1)
(Comparing 68305 – 6 with 68305 – 6)
(Comparing 68305 – 8 with 68305 – 8)
(Comparing 68306 – 1 with 68305 – 1)



and so on.

Now just for the sake of testing. I modified the find in the getInvoicePayment() method. I included an hard coded call to another billing device, and charge type (89305 – 1) for the first loop, and then terminated the transaction.

The equals method was called once, (Comparing 68305 – 1 with 68305 – 1)

It seems that objects are getting added to cache (as expected when we doing a find, get, save etc) and when we do a find, it first tries to retrieve from internal cache. I wonder why both the LHS and RHS change with every .equals calls. Once should remain fixed.

We have profiled the entire application, including hibernate calls using Jprobe. The details are as follows

What we noticed is that hibernate if doing some checks
org.hibernate.impl.SessionImpl.autoFlushRequired(Set)

This in turn calls
org.hibernate.event.AutoFlushEventListener.onAutoFlush(AutoFlushEvent)

Which in turn ( a few levels deeper) calls
Org.hibernate.event.def.DefaultFlushEventListener.dirtyCheck and
Org.hibernate.event.def.DefaultFlushEventListener.CheckId

The above two methods combined, take a majority of the time (80%).

From this is looks like there is some auto flushing happening that is causing so many calls to .equals() (Called from CheckId).

Was wondering whether session.setFlushMode(…) would help. But then this would impact the entire session. Also had a look at session.clear() in the getInvoicePayment method. It helped there, as there were no cache calls now. But it failed somewhere else, I think the clear also cleared objects part of the session, that had to be saved later (Each of our loop has a read, and then save)