AnsweredAssumed Answered

Strange behavior with multithreading

Question asked by marcinj on Apr 13, 2011
Latest reply on Apr 19, 2011 by tombaeyens
Hi,

I am observing an undesired behavior with multithreaded use of Activiti.

My program starts a number of threads, each of them starts a new business process. My business process is comprised of 4 Java Services, each of them just printing a message and sleeping for some time. (Service1, Service2a and Service2b in parallel, Service3)

The problem is: in some cases the program does not finish, just hangs.

I have analyzed the thread dump. Basically, I see a number of threads just waiting to get a db connection, like this:

"Thread-16" prio=6 tid=0x000000000725c000 nid=0xec0 in Object.wait() [0x0000000008f9e000]
   java.lang.Thread.State: WAITING (on object monitor)
   at java.lang.Object.wait(Native Method)
   - waiting on <0x00000000f015dfa0> (a org.apache.commons.pool.impl.GenericObjectPool$Latch)
   at java.lang.Object.wait(Object.java:485)
   at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1115)


My logs suggest that database connections are only closed after the business process finishes, and there are cases when the JDBC connection is requested more than once during thread lifetime. In the effect, a deadlock takes place.
For example, Thread-13 calls getConnection twice, and does not close the first one.
(there's a little hack to monitor opening and closing db connections - HackedDataSource)


process deployed OK!
ok, got runtimeService
  –getConnection called for thread Thread-1
  –getConnection called for thread Thread-2
  –getConnection called for thread Thread-11
  –getConnection called for thread Thread-6
  –getConnection called for thread Thread-8
   –getConnection finishes for thread Thread-2
  –getConnection called for thread Thread-3
  –getConnection called for thread Thread-10
  –getConnection called for thread Thread-15
  –getConnection called for thread Thread-12
  –getConnection called for thread Thread-4
  –getConnection called for thread Thread-14
   –getConnection finishes for thread Thread-1
  –getConnection called for thread Thread-7
   –getConnection finishes for thread Thread-11
Service 1 called in thread Thread-2
Service 1 called in thread Thread-1
  –getConnection called for thread Thread-5
  –getConnection called for thread Thread-9
  –getConnection called for thread Thread-13
Service 1 called in thread Thread-11
Service 1 finishes in thread Thread-1
Service 2a called in thread Thread-1
Service 1 finishes in thread Thread-2
Service 2a called in thread Thread-2
Service 1 finishes in thread Thread-11
Service 2a called in thread Thread-11
Service 2a finishes in thread Thread-1
Service 2b called in thread Thread-1
Service 2a finishes in thread Thread-11
Service 2b called in thread Thread-11
Service 2a finishes in thread Thread-2
Service 2b called in thread Thread-2
Service 2b called in thread Thread-11
Service 2b called in thread Thread-1
Service 3 called in thread Thread-11
Service 3 called in thread Thread-1
Service 2b called in thread Thread-2
Service 3 called in thread Thread-2
Service 3 finishes in thread Thread-11
  –Connection.close called for thread Thread-11
  –Connection.close finishes for thread Thread-11
   –getConnection finishes for thread Thread-6
Service 1 called in thread Thread-6
Service 3 finishes in thread Thread-1
  –Connection.close called for thread Thread-1
  –Connection.close finishes for thread Thread-1
   –getConnection finishes for thread Thread-8
Service 1 called in thread Thread-8
Service 3 finishes in thread Thread-2
  –Connection.close called for thread Thread-2
  –Connection.close finishes for thread Thread-2
   –getConnection finishes for thread Thread-3
Service 1 called in thread Thread-3
Service 1 finishes in thread Thread-6
Service 2a called in thread Thread-6
Service 2a finishes in thread Thread-6
Service 2b called in thread Thread-6
Service 1 finishes in thread Thread-8
Service 2a called in thread Thread-8
Service 1 finishes in thread Thread-3
Service 2a called in thread Thread-3
Service 2a finishes in thread Thread-8
Service 2b called in thread Thread-8
Service 2b called in thread Thread-6
Service 3 called in thread Thread-6
Service 2a finishes in thread Thread-3
Service 2b called in thread Thread-3
Service 3 finishes in thread Thread-6
  –Connection.close called for thread Thread-6
  –Connection.close finishes for thread Thread-6
   –getConnection finishes for thread Thread-10
Service 1 called in thread Thread-10
Service 2b called in thread Thread-8
Service 3 called in thread Thread-8
Service 1 finishes in thread Thread-10
Service 2a called in thread Thread-10
Service 2b called in thread Thread-3
Service 3 called in thread Thread-3
Service 3 finishes in thread Thread-8
  –Connection.close called for thread Thread-8
  –Connection.close finishes for thread Thread-8
   –getConnection finishes for thread Thread-15
Service 1 called in thread Thread-15
Service 2a finishes in thread Thread-10
Service 2b called in thread Thread-10
Service 3 finishes in thread Thread-3
  –Connection.close called for thread Thread-3
  –Connection.close finishes for thread Thread-3
   –getConnection finishes for thread Thread-12
Service 1 called in thread Thread-12
Service 1 finishes in thread Thread-15
Service 2a called in thread Thread-15
Service 1 finishes in thread Thread-12
Service 2a called in thread Thread-12
Service 2b called in thread Thread-10
Service 3 called in thread Thread-10
Service 2a finishes in thread Thread-15
Service 2b called in thread Thread-15
Service 2a finishes in thread Thread-12
Service 2b called in thread Thread-12
Service 3 finishes in thread Thread-10
  –Connection.close called for thread Thread-10
  –Connection.close finishes for thread Thread-10
   –getConnection finishes for thread Thread-4
Service 1 called in thread Thread-4
Service 2b called in thread Thread-15
Service 3 called in thread Thread-15
Service 2b called in thread Thread-12
Service 3 called in thread Thread-12
Service 3 finishes in thread Thread-15
  –Connection.close called for thread Thread-15
  –Connection.close finishes for thread Thread-15
   –getConnection finishes for thread Thread-14
Service 1 called in thread Thread-14
Service 1 finishes in thread Thread-4
Service 2a called in thread Thread-4
Service 3 finishes in thread Thread-12
  –Connection.close called for thread Thread-12
  –Connection.close finishes for thread Thread-12
   –getConnection finishes for thread Thread-7
Service 1 called in thread Thread-7
Service 1 finishes in thread Thread-7
Service 2a called in thread Thread-7
Service 2a finishes in thread Thread-4
Service 2b called in thread Thread-4
Service 1 finishes in thread Thread-14
Service 2a called in thread Thread-14
Service 2b called in thread Thread-4
Service 2a finishes in thread Thread-14
Service 2b called in thread Thread-14
Service 3 called in thread Thread-4
Service 2a finishes in thread Thread-7
Service 2b called in thread Thread-7
Service 3 finishes in thread Thread-4
Service 2b called in thread Thread-7
Service 3 called in thread Thread-7
  –Connection.close called for thread Thread-4
  –Connection.close finishes for thread Thread-4
   –getConnection finishes for thread Thread-5
Service 1 called in thread Thread-5
Service 2b called in thread Thread-14
Service 3 called in thread Thread-14
Service 3 finishes in thread Thread-7
  –Connection.close called for thread Thread-7
  –Connection.close finishes for thread Thread-7
   –getConnection finishes for thread Thread-9
Service 1 called in thread Thread-9
Service 1 finishes in thread Thread-5
Service 2a called in thread Thread-5
Service 3 finishes in thread Thread-14
Service 1 finishes in thread Thread-9
Service 2a called in thread Thread-9
  –Connection.close called for thread Thread-14
  –Connection.close finishes for thread Thread-14
   –getConnection finishes for thread Thread-13
Service 1 called in thread Thread-13
Service 2a finishes in thread Thread-5
Service 2b called in thread Thread-5
Service 1 finishes in thread Thread-13
  –getConnection called for thread Thread-13
Service 2a finishes in thread Thread-9
Service 2b called in thread Thread-5
(we're stuck here)

Of course the problem is not 100% repeatable, it takes a bad luck with the threads interleave.

The main program looks as follows:


package pac1;

import java.util.ArrayList;
import java.util.List;

import javax.sql.DataSource;

import org.activiti.engine.ProcessEngine;
import org.activiti.engine.ProcessEngineConfiguration;
import org.activiti.engine.RepositoryService;
import org.activiti.engine.RuntimeService;
import org.activiti.engine.repository.Deployment;
import org.apache.commons.dbcp.BasicDataSource;

public class Prog3 {
   public static void main(String[] args) throws Exception {
      ProcessEngine processEngine = null;
      BasicDataSource myDataSource = null;
      try {
         System.out.println("starting!");
         int threadNumber = 15;
         int maxConnectionNumber = 3;

         myDataSource = new org.apache.commons.dbcp.BasicDataSource();
         myDataSource.setDriverClassName("org.postgresql.Driver");
         myDataSource.setUrl("jdbc:postgresql://127.0.0.1:54322/activiti");
         myDataSource.setUsername("activiti");
         myDataSource.setPassword("activiti");
         myDataSource.setMaxActive(maxConnectionNumber);
         myDataSource.setMinIdle(0);
         System.out.println("max Active: " + myDataSource.getMaxActive());

         DataSource ds = new HackedDataSource(myDataSource);
         ProcessEngineConfiguration processEngineConfiguration = ProcessEngineConfiguration
               .createStandaloneProcessEngineConfiguration()
               .setDataSource(ds);

         processEngine = processEngineConfiguration.buildProcessEngine();
         System.out.println("processEngine created OK!");

         // Deploy the test process
         RepositoryService repositoryService = processEngine
               .getRepositoryService();
         Deployment deployment = repositoryService.createDeployment()
               .addClasspathResource("tescior3.bpmn20.xml").deploy();
         System.out.println("process deployed OK!");

         final RuntimeService runtimeService = processEngine
               .getRuntimeService();
         System.out.println("ok, got runtimeService");

         // Start a number of process instances
         List<Thread> myThreads = new ArrayList<Thread>();
         for (int i = 0; i < threadNumber; i++) {
            Thread thr = new Thread(new Runnable() {
               @Override
               public void run() {
                  runtimeService.startProcessInstanceByKey("test3");
               }
            });
            thr.start();
            myThreads.add(thr);
         }

         for (Thread t : myThreads) {
            t.join();
         }

         System.out.println("ok, all threads joined");
      } finally {

         if (processEngine != null)
            try {
               System.out.println("about to close process engine…");
               processEngine.close();
               System.out.println("process engine closed");
            } catch (Exception e) {
               e.printStackTrace();
            }

         if (myDataSource != null)
            try {
               System.out.println("about to close data source…");
               myDataSource.close();
               System.out.println("data source closed");
            } catch (Exception e) {
               e.printStackTrace();
            }
      }
   }
}

I am using Activiti 5.4, connected to Postgres, with external DataSource configuration.

BTW, if the max connection number is set to 1, I cannot deploy the process :-(

Thanks,
Marcin Jaskolski

Outcomes