Tuesday Dec 04, 2007

toString covers up nullpointer

While the project I'm working on is ready for production, I've gotten a few bug reports from the end users. One of them comes from a print page of an event schedule.

Here's the data model

Event has many Timeslots which has many Appointments, Timeslots & Appointments then become the schedule of an event.

Therefore to print the schedule of an event, I created a JSF page that prints it out via two dataLists.

<t:dataList value="#{eventAction.currentEntity.timeslots}" var="timeslot">
<t:dataList value="#{timeslot.appointments}" var="appointment">
...
</t:dataList>
</t:dataList>

The initial error the print page gives is outOfMemory exception (running out of Java heap space). I then tracked the error down to this particular line in the JSF:
<s:currencydisplaynolabel currency="#{appointment.screeningsTotal}" />
So I looked into the getScreeningsTotal method on my Appointment object. While debugging thru line by line, I noticed that when my cursor lands on this line, and opens up event (appointment's grandparent) in the variable screen, it causes countless queries to be run.
this.getParentEntity().getParentEntity().getQuantityDiscounts()

To debug, I added the line
Timeslot t = this.getParentEntity();
Event e = t.getParentEntity();
System.out.println(e);

Every time I hit the line System.out.println(e); so many queries are run and eventually the application runs out of memory.

I was convinced that something weird was going on with hibernate. It seems as if hibernate no longer does any lazy loading. It tries to pull all the child, grandchild etc objects under Event out while loading it. This should not have happened. All collections on the event should be lazily fetched.

After trying many different ways to solve the issue to no avail, I talked to Travis and he hinted that the toString method on event is probably doing something weird. System.out.println(e); after all calls the toString method. Then I looked into it...

Everything in the application extends baseEntity in the app. Thus the hierarchy is
BaseEntity -> Account -> Event -> Timeslot -> Appointment
and the BaseEntity toString() method contains:

return ToStringBuilder.reflectionToString(this, ToStringStyle.MULTI_LINE_STYLE);

So when it's printing the event obj, it loads all of its child collections which then load all their child collections so on and so forth.

After I put a break point in the toString method in the BaseEntity, I noticed that before the millions of queries were run, there was actually a nullpointer exception thrown. Since the eclipse console was too busy printing all hibernate queries, the original nullpointer exception was completely covered up. Tomcat log also only shows the outOfMemory error.

I still do not know what exactly is calling the toString method since it's called AFTER the nullpointer exception is thrown. It could be called by facelets when it is trying to print the stack trace on the screen.

Ultimately the lesson learned is that:

return ToStringBuilder.reflectionToString(this, ToStringStyle.MULTI_LINE_STYLE);

Although the line above looks very cool to stick in a toString method, DON'T DO IT in the base object when all your domain models extend that object.

Comments:

I actually ran into exactly the same problem on my project. I wasn't using toString in the application anywhere but I defined it in a base bean superclass of all my domain objects to print out all the properties of the current object and their values (for debugging).

I was getting a weird out of heap space on a couple random objects when I tried to view them in the application. I believe the cause is that either spring or hibernate are calling toString as part of their logging. (I suspect that hibernate is DEBUG level logging the objects it creates a lazy load proxy for)

Posted by Paul on December 04, 2007 at 08:06 PM CST #

Post a Comment:
  • HTML Syntax: NOT allowed