cancel
Showing results for 
Search instead for 
Did you mean: 

Strange behavior with multithreading

marcinj
Champ in-the-making
Champ in-the-making
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
16 REPLIES 16

ronald_van_kuij
Champ on-the-rise
Champ on-the-rise
If  there are no "waitstates" in the process, the connection is indeed only returned after the process finished, so if the number of connections is limited, the behaviour you see is to be expected.

marcinj
Champ in-the-making
Champ in-the-making
Hi,

maybe my previous post was not clear. This is not about the number of connections in the pool. Activiti (or Ibatis ?) seem to request the resources (db connections) in the following fashion:

(let's say there are 2 connections available)

Thread A                                       Thread B
getConnection -> OK!
                                                getConnection -> OK!
getConnection -> wait…
                                                getConnection -> wait…
…now both threads are just stuck forever…
And that's a classic deadlock example.

In my case, it is unclear for me what is the point of the second request ? Avoiding it would prevent the deadlock.

Thanks,
Marcin Jaskolski

ronald_van_kuij
Champ on-the-rise
Champ on-the-rise
your original post was indeed not clear (enough) and your second post  makes it a little more clear. 🙂

Are you sure it is activiti requesting the second connection? In you log I do not see a second connection being retrieved before one s closed in the same thread.

Still then, the pool size has to be tuned for what fuynctionality wise is needed, even if activiti requests a second connection in a thread.

jbarrez
Star Contributor
Star Contributor
What if you change your pool with a datasource pooling solutiuon such as DBCP? The iBatis default connection pool is fairly simple implemented, last time I went through the code.

frederikherema1
Star Contributor
Star Contributor
The getConnection() on mybatis datasource always returns the same connection when transaction is active. The same goos for out spring-implementation (which used TransactionAwareDataSourceProxy), as long as spring-transaction is active  the getConnection() returns the same.

What datasource is your hackedDatasource actually extending?

marcinj
Champ in-the-making
Champ in-the-making
Hi Ronald,

thanks for your reply 🙂

Please have a closer look at Thread-13. It asks for the second connection.

It is perfectly agreeable that performance-wise the pool size has to be tuned. But still, if the program blocks, it is a highly problematic situation.
(As a rule of thumb, process should not ask for an additional resource if it's already holding a resource of the same type.  :geek: )

I have run a few more tests and I have a more detailed information now.

One of my threads enters the synchronized method: org.activiti.engine.impl.db.DbIdGenerator.getNextId(DbIdGenerator.java:34), and the call proceeds to the point where it asks for additional connection:

"Thread-38" prio=6 tid=0x0000000006f14800 nid=0x10fc in Object.wait() [0x000000000a24c000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000ee416210> (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)
- locked <0x00000000ee416210> (a org.apache.commons.pool.impl.GenericObjectPool$Latch)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
…..
at org.activiti.engine.impl.db.DbIdGenerator.getNewBlock(DbIdGenerator.java:41)
- locked <0x00000000ee4112b0> (a org.activiti.engine.impl.db.DbIdGenerator)
at org.activiti.engine.impl.db.DbIdGenerator.getNextId(DbIdGenerator.java:34)
- locked <0x00000000ee4112b0> (a org.activiti.engine.impl.db.DbIdGenerator)
at org.activiti.engine.impl.history.handler.ActivityInstanceStartHandler.notify(ActivityInstanceStartHandler.java:39)
…..

and waits for free resource (sorry, no free resources now, you have to wait)

In the meantime, other threads try to enter the getNextId method (but sorry, it's taken by the previous thread).

I believe this is a real problem. I cannot assume that my database pool is unlimited.  :lol:

If it's of any use, I am more than willing to provide source code, thread dumps, etc (too long to post).

Thanks,
Marcin Jaskolski

frederikherema1
Star Contributor
Star Contributor
Now I see… The nextId block stuff indeed gets a new connection (to have seperate transaction, to be sure id's aren't taken by others). So basically the current thread can't reuse the same connection for this (so it's actually holding a resource of another type).

This is indeed an issue that was overlooked.

marcinj
Champ in-the-making
Champ in-the-making
What if you change your pool with a datasource pooling solutiuon such as DBCP? The iBatis default connection pool is fairly simple implemented, last time I went through the code.
Hi jbarrez,

thanks for your reply.
I am using the Apache Commons DBCP, mainly to monitor who's asking for connections, closing them, etc. It's configured this way:


   myDataSource = new org.apache.commons.dbcp.BasicDataSource();
   myDataSource.setDriverClassName("org.postgresql.Driver");
   myDataSource.setUrl("jdbcSmiley Tongueostgresql://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!");

The classes HackedConnection and HackedDataSource implement java.sql.Connection and javax.sql.DataSource respectively. :


public class HackedConnection implements Connection {

private Connection conn;

public HackedConnection(Connection conn) {
  this.conn = conn;
}

public void close() throws SQLException {
  String name = Thread.currentThread().getName();
  System.out.println("  –Connection.close called for thread " + name
    + ".");
  HackerDatabase.customerLeaves(name);
  conn.close();
  System.out.println("  –Connection.close finishes for thread " + name
    + ".");
}
..delegate methods…


public class HackedDataSource implements DataSource {

private DataSource dataSource;
private TreeSet<String> customers;

public HackedDataSource(DataSource dataSource) {
  this.dataSource = dataSource;
  this.customers = new TreeSet<String>();
}

public Connection getConnection() throws SQLException {
  String name = Thread.currentThread().getName();
  System.out.println("  –getConnection called for thread " + name + ".");
  synchronized (customers) {
   if (!"main".equals(name)) {
    if (customers.contains(name))
     System.out.println("  —-hey!");
    customers.add(name);
   }
  }

  HackerDatabase.customerAsking(name);
  Connection conn = dataSource.getConnection();
  HackerDatabase.customerServed(name);

  System.out.println("   –getConnection finishes for thread " + name
    + ".");
  return new HackedConnection(conn);
}
…delegate methods…

HackerDatabase maintains sets of threads waiting for the connection and those holding a connection.

Thanks,
Marcin Jaskolski

frederikherema1
Star Contributor
Star Contributor
To summarize:
If no free connections in connection-pool are available, and a new block of ID's is requested, an SQL-connection is requested -> thread has to wait for available SQLConnections. Since this fetching is done in a syncronized block, all other theads that use the ID-generator are blocked. Since they are blocked, they can't return the SQL-connection they use to the pool -> locked untill the pools maxWaitTime expires and the waiting thread gets an exception on the getConnection().