PostgreSQL Slow, Deadlock Issues, Hibernate Related?

sentiental · **Posted:** Sun Aug 05, 2007 10:18 pm

Hi, this is my first post to the forum. I've been good about not posting superfluous things, but I've run into a problem that I can't resolve.

I've been developing a web app with Spring/Hibernate/Tomcat5.5 in the Eclipse IDE. Our firm's production server, which is currently running PostgreSQL 7.4.16, seems to be having a tremendously hard time performing relatively simple queries (max 3 joins) on a small db (in that case, a join table between 300 x 22 tuples). When more than one user tries to get to this page, the database almost immediately hits deadlock.

Developing locally, I've been using HSQLDB as a lightweight development database, and run times on the same queries are much smaller (loading one of the heavier pages, with plenty of collections of objects and several substantial queries takes ~1.5 seconds, PostgreSQL verges on 10-15). I've pumped a lot of sample data into the HSQLDB instance and not seen anywhere near the time taken by PostgreSQL.

While I'm mostly concerned that it's a PostgreSQL configuration issue, I can't be certain that Hibernate is not playing a role. I searched for known issues between PostgreSQL and Hibernate in performing queries and found this discussion, referencing an older but similar problem:

http://archives.postgresql.org/pgsql-bugs/2005-01/msg00218.php

If anybody could shed some light on the situation, I would really appreciate it. Thanks!

Here's some detailed information:

Hibernate version:3.2.4.sp1

PostgreSQL 7.4.16, Java 1.5 on Debian Linux, Tomcat 5.5.23, Spring 2.0

Celeron 2GHz, 2 gigs RAM

Full stack trace of any exception that occurs:

Code:

2007-08-05 20:01:47,568 WARN [org.hibernate.util.JDBCExceptionReporter] - SQL Error: 0, SQLState: null
2007-08-05 20:01:47,568 ERROR [org.hibernate.util.JDBCExceptionReporter] - Batch entry 2 delete from UserWalkthroughs where SID= was aborted. Call getNextException() to see the cause.
2007-08-05 20:01:47,568 WARN [org.hibernate.util.JDBCExceptionReporter] - SQL Error: 0, SQLState: 40P01
2007-08-05 20:01:47,568 ERROR [org.hibernate.util.JDBCExceptionReporter] - ERROR: deadlock detected

2007-08-05 20:01:47,568 ERROR [org.hibernate.event.def.AbstractFlushingEventListener] - Could not synchronize database state with session
org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
        at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:253)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:237)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:143)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
        at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
        at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
        at com.firm.sbx.model.sbxdb.insertion.HibernateObjectWriter.attachObjects(HibernateObjectWriter.java:41)
        at com.firm.sbx.model.sbxdb.insertion.HibernateObjectWriter.attachObjects(HibernateObjectWriter.java:54)
        at com.firm.sbx.model.sbxdb.insertion.MultiObjectInsertion.run(MultiObjectInsertion.java:41)
        at com.firm.sbx.model.sbxdb.insertion.BlockSellerInsertion.run(BlockSellerInsertion.java:88)
        at com.firm.sbx.model.sbxdb.insertion.BlockSellerInsertion.block(BlockSellerInsertion.java:63)
        at com.firm.sbx.controller.UnsubscribeController.tryBlock(UnsubscribeController.java:138)
        at com.firm.sbx.controller.UnsubscribeController.handleRequest(UnsubscribeController.java:89)
        at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:857)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:792)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:461)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:416)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:870)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)

Also resulting from these operations that can't be completed are these constraint violations that only manifest themselves right before the deadlock occurs. We've worked really hard to fix any session management issues, and in HSQL this constraint violation is never thrown.

Code:

org.hibernate.exception.ConstraintViolationException: could not insert collection: [com.firm.sbx.model.sbxdb.hibernate.Seller.walkedUsers#1207]        
   at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:71)        
   at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)        
   at org.hibernate.persister.collection.AbstractCollectionPersister.recreate(AbstractCollectionPersister.java:1183)        
   at org.hibernate.action.CollectionRecreateAction.execute(CollectionRecreateAction.java:26)        
   at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)        
   at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)        
   at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:145)        
   at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)        
   at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:41)        
   at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:969)        
   at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1114)        
   at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)        
   at com.firm.sbx.model.sbxdb.active.ReceiptsAndEmailsOperation.operate(ReceiptsAndEmailsOperation.java:81)        
   at com.firm.sbx.model.sbxdb.active.ActiveSessionHandler.perform(ActiveSessionHandler.java:26)        
   at com.firm.sbx.model.command.HomeDAO.populate(HomeDAO.java:69)        
   at com.firm.sbx.model.StandardContentWithUserLogin.populateAll(StandardContentWithUserLogin.java:124)        
   at com.firm.sbx.controller.CompoundController.formBackingObject(CompoundController.java:110)        
   at org.springframework.web.servlet.mvc.AbstractFormController.getErrorsForNewForm(AbstractFormController.java:343)        
   at org.springframework.web.servlet.mvc.AbstractFormController.showNewForm(AbstractFormController.java:323)        
   at org.springframework.web.servlet.mvc.AbstractFormController.handleRequestInternal(AbstractFormController.java:263)        
   at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:153)        
   at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)        
   at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:857)        
   at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:792)        
   at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:461)        
   at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:416)        
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)        
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)        
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)        
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)        
   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)        
   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)        
   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)        
   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)        
   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)        
   at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)        
   at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:870)        
   at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)        
   at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)        
   at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)        
   at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)        
   at java.lang.Thread.run(Thread.java:595)

The SHOW ALL from PostgreSQL

Code:

              name              |             setting              
--------------------------------+----------------------------------
 add_missing_from               | on
 australian_timezones           | off
 authentication_timeout         | 60
 backslash_quote                | safe_encoding
 check_function_bodies          | on
 checkpoint_segments            | 3
 checkpoint_timeout             | 300
 checkpoint_warning             | 30
 client_encoding                | UNICODE
 client_min_messages            | notice
 commit_delay                   | 0
 commit_siblings                | 5
 cpu_index_tuple_cost           | 0.001
 cpu_operator_cost              | 0.0025
 cpu_tuple_cost                 | 0.01
 DateStyle                      | ISO, MDY
 db_user_namespace              | off
 deadlock_timeout               | 1000
 debug_pretty_print             | off
 debug_print_parse              | off
 debug_print_plan               | off
 debug_print_rewritten          | off
 default_statistics_target      | 10
 default_transaction_isolation  | read committed
 default_transaction_read_only  | off
 dynamic_library_path           | $libdir
 effective_cache_size           | 1000
 enable_hashagg                 | on
 enable_hashjoin                | on
 enable_indexscan               | on
 enable_mergejoin               | on
 enable_nestloop                | on
 enable_seqscan                 | on
 enable_sort                    | on
 enable_tidscan                 | on
 explain_pretty_print           | on
 extra_float_digits             | 0
 from_collapse_limit            | 8
 fsync                          | on
 geqo                           | on
 geqo_effort                    | 1
 geqo_generations               | 0
 geqo_pool_size                 | 0
 geqo_selection_bias            | 2
 geqo_threshold                 | 11
 join_collapse_limit            | 8
 krb_server_keyfile             | FILE:/etc/postgresql/krb5.keytab
 lc_collate                     | en_US.UTF-8
 lc_ctype                       | en_US.UTF-8
 lc_messages                    | en_US.UTF-8
 lc_monetary                    | en_US.UTF-8
 lc_numeric                     | en_US.UTF-8
 lc_time                        | en_US.UTF-8
 log_connections                | off
 log_duration                   | off
 log_error_verbosity            | default
 log_executor_stats             | off
 log_hostname                   | off
 log_min_duration_statement     | -1
 log_min_error_statement        | panic
 log_min_messages               | notice
 log_parser_stats               | off
 log_pid                        | off
 log_planner_stats              | off
 log_source_port                | off
 log_statement                  | off
 log_statement_stats            | off
 log_timestamp                  | on
 max_connections                | 100
 max_expr_depth                 | 10000
 max_files_per_process          | 1000
 max_fsm_pages                  | 20000
 max_fsm_relations              | 1000
 max_locks_per_transaction      | 64
 password_encryption            | on
 port                           | 5432
 pre_auth_delay                 | 0
 preload_libraries              | unset
 random_page_cost               | 4
 regex_flavor                   | advanced
 rendezvous_name                | unset
 search_path                    | $user,public
 server_encoding                | UNICODE
 server_version                 | 7.4.16
 shared_buffers                 | 2000
 silent_mode                    | off
 sort_mem                       | 1024
 sql_inheritance                | on
 ssl                            | off
 statement_timeout              | 0
 stats_block_level              | off
 stats_command_string           | off
 stats_reset_on_server_start    | on
 stats_row_level                | on
 stats_start_collector          | on
 superuser_reserved_connections | 2
 syslog                         | 0
 syslog_facility                | LOCAL0
 syslog_ident                   | postgres
 tcpip_socket                   | on
 TimeZone                       | unknown
 trace_notify                   | off
 transaction_isolation          | read committed
 transaction_read_only          | off
 transform_null_equals          | off
 unix_socket_directory          | /var/run/postgresql
 unix_socket_group              | unset
 unix_socket_permissions        | 511
 vacuum_mem                     | 8192
 virtual_host                   | unset
 wal_buffers                    | 8
 wal_debug                      | 0
 wal_sync_method                | fdatasync
 zero_damaged_pages             | off
(114 rows)

sentiental · **Posted:** Mon Aug 06, 2007 9:43 am

On a suggestion, I set show_sql to true in the Hibernate configuration and got this stream of queries. I think it's pretty revelatory:

Code:

Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: delete from UserWalkthroughs where SID=?
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)
Hibernate: insert into UserWalkthroughs (SID, UID) values (?, ?)

When I first saw this I thought it might be related to the user being directly available to the jsp as a form backing object, but the inserts still appear after I try evicting it from the session and merging it back in on form submission.

Here's the HQL query for the Sellers with walkthroughs:

Code:

from Seller s where s.hasWalkthrough='true'

And here's the code used within the session:

Code:

      userWithSellers = (User) session.load(User.class, id);
      userWithSellers.getWalkedSellers().size();
      
      SbxQueries q = SbxQueries.SELLERS_WITH_WALKTHROUGHS;
      
      
      Query qr = session.createQuery(q.queryAsString());
      
      List l = qr.list();
      storeList = new ArrayList<Seller>(l);
      Seller.sortByCategory(storeList);
      Iterator<Seller> i = storeList.iterator();
      TreeSet<Seller> set = new TreeSet<Seller>();
      String cat = "-1";
      while(i.hasNext()){
         Seller k = i.next();
         if(!k.getCategory().equals(cat)){
            set = new TreeSet<Seller>();
            categorizedSellers.put(k.getCategory(), set);
            cat = k.getCategory();
         }
         set.add(k);
         sellerMap.put(k.getName(), k);
      }
      session.evict(userWithSellers);

thatmikewilliams · **Posted:** Mon Aug 06, 2007 2:27 pm

The problem here was collection handling inside an entity. When hibernate set a collection property, a new collection was being created and the elements added to it.

Code:

public void setUsers(Set users) {
  this.users = new HashSet();
  this.users.addAll(users);
}

When hibernate read the collection back at the end of the transaction it concluded that all the elements of the original collection had been removed and a new set of elements inserted. Hence the multiple delete and insert operations on the join table.