-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 7 posts ] 
Author Message
 Post subject: hibernate is updating rows unexpectedly (causing deadlocks)
PostPosted: Wed May 04, 2005 7:14 pm 
Beginner
Beginner

Joined: Fri Dec 17, 2004 8:30 pm
Posts: 20
I've posted several questions about this on experts exchange, but so far have not gotten any answers. For a full history of my questions, see:
- Most recent: http://experts-exchange.com/Programming/Programming_Languages/Java/Q_21410535.html
- http://www.experts-exchange.com/Databases/PostgreSQL/Q_21409106.html
- http://www.experts-exchange.com/Programming/Programming_Languages/Java/Q_21410209.html

The problem boils down to this:
1. I was getting apparent deadlocks to the DB.
2. I determined that the deadlocks were all due to updates being attempted to one particular table.
3. I easily replicated this behavior by forcing a refresh of a particular page a bunch of times in a row until a deadlock occurred and no future page requests finished.
4. The code to display that page is not supposed to be doing any updates at all.
5. As an experiment, I changed the cache type to read-only for the offending object type and as a result I get an error every time I display the page.
6. I traced through the code and was able to pull out the code to make a short example that always causes this problem.

Here is the simplest example I could come up with:

Code:
Session s = CustomObjFieldMetaDAO.getInstance().getSession();
Query query = s.getNamedQuery("com.knowlist.list.hh.CustomObjFieldMeta.findByObjTypeAndFieldType");
query.setInteger("objType",100);
query.setInteger("fieldType",10);
query.uniqueResult();
// No exeception has been thrown yet. But, when query.uniqueResult() is called a second time here, it will throw the "Can't write to a readonly object" which is obviously because I made the cache read only.
query.uniqueResult();


This happens every single time. It's not just after server restart. For some reason, every single time I hit this page, it runs the query once without problems but then for some reason attempts to execute an update when the same query is run a second time.

Note that I have lots of hibernate objects and this is the only one that was causing deadlocks. I haven't tried changing other cache types to read only to see if everything is updating for every query.

So, there are two mysteries here.
1. why are these updates occurring on the second query?
2. why are these updates causing deadlocks? They aren't part of a transaction (unless hibernate is creating one), so there's no reason they should deadlock.


Hibernate version:
3.0.2

Mapping documents:
Code:
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
     "-//Hibernate/Hibernate Mapping DTD//EN"
     "http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd" >

<hibernate-mapping schema="know" package="com.knowlist.list.hh">
     <class name="CustomObjFieldMeta" table="customobjfieldmeta">
          <!-- OPTIONS: read-write, nonstrict-read-write, read-only -->
            <cache usage="read-only"/>
         
          <id
               column="id"
               name="id"
               type="integer"
          >
               <generator class="sequence"><param name="sequence">CustomObjFieldMeta_id_seq</param></generator>
          </id>

          <property
               column="visibility"
               length="11"
               name="visibility"
               not-null="true"
               type="integer"
           />
          <property
               column="versionId"
               length="11"
               name="versionId"
               not-null="false"
               type="integer"
           />
          <property
               column="objType"
               length="11"
               name="objType"
               not-null="true"
               type="integer"
           />
          <property
               column="versionOf"
               length="11"
               name="versionOf"
               not-null="false"
               type="integer"
           />
          <property
               column="shortDesc"
               name="shortDesc"
               not-null="false"
               type="string"
           />
          <property
               column="longDesc"
               name="longDesc"
               not-null="false"
               type="string"
           />

          <many-to-one name="fieldType" class="com.knowlist.list.hh.CustomObjFieldType" column="fieldType" not-null="true"/>

     </class>
     
     
     <query name="com.knowlist.list.hh.CustomObjFieldMeta.findByObjType">
          <![CDATA[
               select cofm
               from
                    com.knowlist.list.hh.CustomObjFieldMeta as cofm,
                    com.knowlist.list.hh.CustomObjFieldType as coft
               where
                    cofm.objType=:objType
                    and cofm.fieldType=coft
               order by
                    cofm.fieldType
          ]]>
     </query>
     
     <query name="com.knowlist.list.hh.CustomObjFieldMeta.findByObjTypeAndFieldType">
          <![CDATA[
               from com.knowlist.list.hh.CustomObjFieldMeta as cofm
               where
                    cofm.objType=:objType
                    and cofm.fieldType=:fieldType
          ]]>
     </query>
     
</hibernate-mapping>


Code between sessionFactory.openSession() and session.close():

Full stack trace of any exception that occurs:
(This only occurs when I make the cache read-only. When the cache is read-write it works fine until it deadlocks. After that it just never finishes. No exceptions are ever thrown in that case.)

Code:
01:04:55.796 WARN!! [P1-0] org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:590) >11> /know/:
java.lang.UnsupportedOperationException: Can't write to a readonly object
     at org.hibernate.cache.ReadOnlyCache.lock(ReadOnlyCache.java:43)
     at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:69)
     at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:239)
     at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:223)
     at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:137)
     at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:274)
     at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:48)
     at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:659)
     at org.hibernate.impl.SessionImpl.prepareQueries(SessionImpl.java:833)
     at org.hibernate.impl.SessionImpl.getQueries(SessionImpl.java:823)
     at org.hibernate.impl.SessionImpl.list(SessionImpl.java:782)
     at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
     at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:603)
     at com.knowlist.list.hh.dao.CustomObjFieldMetaDAO.findByFieldType(CustomObjFieldMetaDAO.java:51)
     at com.knowlist.list.hh.CustomObj.getField(CustomObj.java:141)
     at com.knowlist.list.main.MainPage.service(MainPage.java:45)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:688)
     at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:427)
     at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:496)
     at org.mortbay.jetty.servlet.Dispatcher.dispatch(Dispatcher.java:263)
     at org.mortbay.jetty.servlet.Dispatcher.forward(Dispatcher.java:157)
     at org.apache.jasper.runtime.PageContextImpl.doForward(PageContextImpl.java:670)
     at org.apache.jasper.runtime.PageContextImpl.forward(PageContextImpl.java:637)
     at org.apache.jsp.index_jsp._jspService(index_jsp.java:45)
     at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:94)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:688)
     at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:324)
     at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:292)
     at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:236)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:688)
     at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:427)
     at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:496)
     at org.mortbay.jetty.servlet.Dispatcher.dispatch(Dispatcher.java:263)
     at org.mortbay.jetty.servlet.Dispatcher.forward(Dispatcher.java:157)
     at org.mortbay.jetty.servlet.Default.handleGet(Default.java:312)
     at org.mortbay.jetty.servlet.Default.service(Default.java:232)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:688)
     at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:427)
     at org.mortbay.jetty.servlet.WebApplicationHandler$CachedChain.doFilter(WebApplicationHandler.java:822)
     at com.knowlist.hibernate.HibernateSessionFilter.doFilter(HibernateSessionFilter.java:54)
     at org.mortbay.jetty.servlet.WebApplicationHandler$CachedChain.doFilter(WebApplicationHandler.java:813)
     at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:298)
     at org.mortbay.jetty.servlet.WebApplicationHandler$CachedChain.doFilter(WebApplicationHandler.java:813)
     at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:494)
     at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:569)
     at org.mortbay.http.HttpContext.handle(HttpContext.java:1482)
     at org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationContext.java:624)
     at org.mortbay.http.HttpContext.handle(HttpContext.java:1434)
     at org.mortbay.http.HttpServer.service(HttpServer.java:896)
     at org.mortbay.http.HttpConnection.service(HttpConnection.java:814)
     at org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:981)
     at org.mortbay.http.HttpConnection.handle(HttpConnection.java:831)
     at org.mortbay.http.SocketListener.handleConnection(SocketListener.java:244)
     at org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:366)
     at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:534)


Name and version of the database you are using:
PostgresSQL 8


The generated SQL (show_sql=true):
Strangely, this only shows select statements. I don't see any update statements when I turn show_sql=true. But, they clearly are being executed due to the reasons I stated above.

See http://www.experts-exchange.com/Databases/PostgreSQL/Q_21409106.html for the full postgresql data about the deadlocks.

Debug level Hibernate log excerpt:


Top
 Profile  
 
 Post subject: actually, there is an update in the logging
PostPosted: Wed May 04, 2005 10:53 pm 
Beginner
Beginner

Joined: Fri Dec 17, 2004 8:30 pm
Posts: 20
I removed all servlet filters and moved the code into a separate servlet. It still does the update. To elminate the exception I made the cache read-write again. But, notice that in the log where it does an update.

Here's the test servlet:

Code:
package com.knowlist.list.main;

import java.io.IOException;

import javax.servlet.ServletException;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.apache.log4j.Logger;
import org.hibernate.Query;
import org.hibernate.Session;

import com.knowlist.list.hh.HibernateInit;
import com.knowlist.list.hh.dao.CustomObjFieldMetaDAO;
import com.knowlist.list.hh.dao._RootDAO;


public class MainPageTest extends HttpServlet {

    static {
        HibernateInit.doInit();
    }
   
   protected void service(HttpServletRequest req, HttpServletResponse res)
         throws ServletException, IOException
   {
        try {
            Logger.getLogger(getClass()).debug("1");
            Session s = CustomObjFieldMetaDAO.getInstance().getSession();
            Query query = s.getNamedQuery("com.knowlist.list.hh.CustomObjFieldMeta.findByObjTypeAndFieldType");
            query.setInteger("objType",100);
            query.setInteger("fieldType",10);
            Logger.getLogger(getClass()).debug("2");
            query.uniqueResult();
            Logger.getLogger(getClass()).debug("3");
            query.uniqueResult();
            Logger.getLogger(getClass()).debug("4");
        } catch(Exception e) {
            throw new ServletException(e);
        } finally {
            _RootDAO.closeCurrentThreadSessions();
        }
   }
}




After my app server starts up, here is what is output after I hit this servlet 3 times in a row. Notice that it does the exact same thing each time.
Code:
DEBUG[2005-05-04 19:50:53,453] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:29)(MainPageTest.java29): 1
DEBUG[2005-05-04 19:50:53,625] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:34)(MainPageTest.java34): 2
Hibernate: select customobjf0_.id as id, customobjf0_.visibility as visibility7_, customobjf0_.versionId as versionId7_, customobjf0_.objType as objType7_, customobjf0_.versionOf as versionOf7_, customobjf0_.shortDesc as shortDesc7_, customobjf0_.longDesc as longDesc7_, customobjf0_.fieldType as fieldType7_ from know.customobjfieldmeta customobjf0_ where customobjf0_.objType=? and customobjf0_.fieldType=?
DEBUG[2005-05-04 19:50:53,703] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:36)(MainPageTest.java36): 3
Hibernate: select customobjf0_.id as id0_, customobjf0_.keyName as keyName13_0_, customobjf0_.shortDesc as shortDesc13_0_, customobjf0_.longDesc as longDesc13_0_, customobjf0_.storageParam1 as storageP5_13_0_, customobjf0_.storageParam2 as storageP6_13_0_, customobjf0_.storageParam3 as storageP7_13_0_, customobjf0_.storageParam4 as storageP8_13_0_, customobjf0_.storageType as storageT9_13_0_ from know.customobjfieldtype customobjf0_ where customobjf0_.id=?
Hibernate: update know.customobjfieldmeta set visibility=?, versionId=?, objType=?, versionOf=?, shortDesc=?, longDesc=?, fieldType=? where id=?
Hibernate: select customobjf0_.id as id, customobjf0_.visibility as visibility7_, customobjf0_.versionId as versionId7_, customobjf0_.objType as objType7_, customobjf0_.versionOf as versionOf7_, customobjf0_.shortDesc as shortDesc7_, customobjf0_.longDesc as longDesc7_, customobjf0_.fieldType as fieldType7_ from know.customobjfieldmeta customobjf0_ where customobjf0_.objType=? and customobjf0_.fieldType=?
DEBUG[2005-05-04 19:50:53,750] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:38)(MainPageTest.java38): 4
DEBUG[2005-05-04 19:51:03,046] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:29)(MainPageTest.java29): 1
DEBUG[2005-05-04 19:51:03,046] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:34)(MainPageTest.java34): 2
Hibernate: select customobjf0_.id as id, customobjf0_.visibility as visibility7_, customobjf0_.versionId as versionId7_, customobjf0_.objType as objType7_, customobjf0_.versionOf as versionOf7_, customobjf0_.shortDesc as shortDesc7_, customobjf0_.longDesc as longDesc7_, customobjf0_.fieldType as fieldType7_ from know.customobjfieldmeta customobjf0_ where customobjf0_.objType=? and customobjf0_.fieldType=?
DEBUG[2005-05-04 19:51:03,046] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:36)(MainPageTest.java36): 3
Hibernate: update know.customobjfieldmeta set visibility=?, versionId=?, objType=?, versionOf=?, shortDesc=?, longDesc=?, fieldType=? where id=?
Hibernate: select customobjf0_.id as id, customobjf0_.visibility as visibility7_, customobjf0_.versionId as versionId7_, customobjf0_.objType as objType7_, customobjf0_.versionOf as versionOf7_, customobjf0_.shortDesc as shortDesc7_, customobjf0_.longDesc as longDesc7_, customobjf0_.fieldType as fieldType7_ from know.customobjfieldmeta customobjf0_ where customobjf0_.objType=? and customobjf0_.fieldType=?
DEBUG[2005-05-04 19:51:03,062] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:38)(MainPageTest.java38): 4
DEBUG[2005-05-04 19:51:04,203] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:29)(MainPageTest.java29): 1
DEBUG[2005-05-04 19:51:04,203] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:34)(MainPageTest.java34): 2
Hibernate: select customobjf0_.id as id, customobjf0_.visibility as visibility7_, customobjf0_.versionId as versionId7_, customobjf0_.objType as objType7_, customobjf0_.versionOf as versionOf7_, customobjf0_.shortDesc as shortDesc7_, customobjf0_.longDesc as longDesc7_, customobjf0_.fieldType as fieldType7_ from know.customobjfieldmeta customobjf0_ where customobjf0_.objType=? and customobjf0_.fieldType=?
DEBUG[2005-05-04 19:51:04,218] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:36)(MainPageTest.java36): 3
Hibernate: update know.customobjfieldmeta set visibility=?, versionId=?, objType=?, versionOf=?, shortDesc=?, longDesc=?, fieldType=? where id=?
Hibernate: select customobjf0_.id as id, customobjf0_.visibility as visibility7_, customobjf0_.versionId as versionId7_, customobjf0_.objType as objType7_, customobjf0_.versionOf as versionOf7_, customobjf0_.shortDesc as shortDesc7_, customobjf0_.longDesc as longDesc7_, customobjf0_.fieldType as fieldType7_ from know.customobjfieldmeta customobjf0_ where customobjf0_.objType=? and customobjf0_.fieldType=?
DEBUG[2005-05-04 19:51:04,234] com.knowlist.list.main.MainPageTest.service(MainPageTest.java:38)(MainPageTest.java38): 4


Top
 Profile  
 
 Post subject: more info
PostPosted: Thu May 05, 2005 4:06 am 
Beginner
Beginner

Joined: Fri Dec 17, 2004 8:30 pm
Posts: 20
Ok, I've got some interesting new info. After a lot of experimentation, I've discovered the following:

The following does NOT cause updates:
protected void service(HttpServletRequest req, HttpServletResponse res)
throws ServletException, IOException
{
try {
Session s = CustomObjFieldMetaDAO.getInstance().getSession();
Query query = s.createQuery("from com.knowlist.list.hh.CustomObjFieldMeta as cofm");
query.list();
} catch(Exception e) {
throw new ServletException(e);
} finally {
_RootDAO.closeCurrentThreadSessions();
}

try {
Session s = CustomObjFieldMetaDAO.getInstance().getSession();
Query query = s.createQuery("from com.knowlist.list.hh.CustomObjFieldMeta as cofm");
query.list();
} catch(Exception e) {
throw new ServletException(e);
} finally {
_RootDAO.closeCurrentThreadSessions();
}
}

The following DOES cause updates:
protected void service(HttpServletRequest req, HttpServletResponse res)
throws ServletException, IOException
{
try {
Session s = CustomObjFieldMetaDAO.getInstance().getSession();
Query query = s.createQuery("from com.knowlist.list.hh.CustomObjFieldMeta as cofm");
query.list();
query.list();
} catch(Exception e) {
throw new ServletException(e);
} finally {
_RootDAO.closeCurrentThreadSessions();
}
}


In the first case I run the query.list() in separate sessions. In the latter I run them in the same session.

Furthermore, if I execute query.list() more than two times in a row, it only causes ONE update. That one update occurs when the second call to query.list() is made.

Another interesting bit is that, you may notice I'm doing list() instead of uniqueResult() now. I found that by changing the query to increase the number of results, it will actually update all results returned. So, if query.list() returns 50 results then I actually see 50 update statements run.

Lastly, the CustomObjFieldMeta object have a variety of attributes. One of them is called shortDesc. I override that method as such:
public CustomObjFieldType getFieldType() {
return CustomObjFieldTypeDAO.getInstance().load(getFieldTypeId());
}
public java.lang.String getShortDesc() {
String shortDesc = super.getShortDesc();
if(shortDesc==null || "".equals(shortDesc))
return getFieldType().getShortDesc();
return shortDesc;
}

I found that if I comment out the section of getShortDesc() which calls getFieldType() then no updates occur. So, somehow loading the corresponding CustomObjFieldType causes the CustomObjFieldMeta to become "dirty" somehow. But, the key here is that getShortDesc() is NOT called except before the second execution of the query. Why that should be the case is totally inexplicable to me.

As it turns out, turning off ehcache does not appear to have an effect on this. It's hard to tell because I haven't removing the cache enabling lines in all the other hbm files.


Top
 Profile  
 
 Post subject: Thank you!
PostPosted: Thu May 05, 2005 7:02 am 
Newbie

Joined: Thu Apr 21, 2005 12:20 pm
Posts: 4
Hi

Your explanation solved my problem. I have a read-write-cache, so naturally when I changed my get-method (which maybe is a no-no?) in a object supposed to be in synch with the database, I got a problem. I watched Hibernate doing hundreds of updates and I didn't have a clue why.. When doing the list() for the second time I got (sometimes) and exception: Unexpected row count...bla bla. I must say it was somewhat difficult to grasp the REAL reason.

I must say this forum works exceptionally well:-) My problem arises at 11 o'clock. I check the forum at 12 o'clock, problem solved thirty minutes later. If all software problems could be solved that quick, where would we be?:)

Morten Simonsen


Top
 Profile  
 
 Post subject:
PostPosted: Thu May 05, 2005 10:42 am 
Newbie

Joined: Thu Sep 11, 2003 11:49 am
Posts: 8
Location: Albuquerque NM
hey mxnmatch, if you are only trying to read from the cache, I was wondering if you could set FlushMode to NEVER before you get a unique result. This may stop the updates from happening (and answer a question for me.)
TIA
Dan


Top
 Profile  
 
 Post subject: no dirty bit? that's crazy! Deadlocks inherent in updates?
PostPosted: Thu May 05, 2005 4:53 pm 
Beginner
Beginner

Joined: Fri Dec 17, 2004 8:30 pm
Posts: 20
What?! Are you telling me that it does a comparison of every single field of an object when it is pulled from the cache? Why in the world would it do that? Why wouldn't it just set a dirty bit when any of the set methods are called?

This would mean that I have to modify all places where I override methods from the generated base class! I would need to change the name of the base class methods and make them private somehow (assuming that is even allowed).

Is there any way I can tell hibernate to use a dirty bit instead of having it do a total comparison?

Actually, now that I think of it, I don't know why it matters in this case. I never call save or saveOrUpdate or update, so why the heck does it attempt to check the object's dirtiness?

It now makes sense to me what is happening (though not actually why it's doing it that way), but it doesn't explain the deadlocks that resulted. I guess I'll need to load test a part of my code that does explicit updates within actual transactions to see if hibernate updates are inherently unsafe.


Top
 Profile  
 
 Post subject: session.setFlushMode(FlushMode.NEVER);
PostPosted: Thu May 05, 2005 5:12 pm 
Beginner
Beginner

Joined: Fri Dec 17, 2004 8:30 pm
Posts: 20
Yep, calling:
session.setFlushMode(FlushMode.NEVER);
does prevent the update from occurring.

Of course, that still means that deadlocks caused by those updates could still happen on any page that edits things.


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 7 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.