8

Waiting for the server to restart when working with Play cost us a lot of time. One thing I see in the log is that shutting down and starting the HikaryPool takes a lot of time (> 40 seconds).

Here is the log:

2019-10-31 09:11:47,327 [info] application - Shutting down connection pool.
2019-10-31 09:11:47,328 [info] c.z.h.HikariDataSource - HikariPool-58 - Shutdown initiated...
2019-10-31 09:11:53,629 [info] c.z.h.HikariDataSource - HikariPool-58 - Shutdown completed.
2019-10-31 09:11:53,629 [info] application - Shutting down connection pool.
2019-10-31 09:11:53,629 [info] c.z.h.HikariDataSource - HikariPool-59 - Shutdown initiated...
2019-10-31 09:11:53,636 [info] c.z.h.HikariDataSource - HikariPool-59 - Shutdown completed.
2019-10-31 09:11:53,636 [info] application - Shutting down connection pool.
2019-10-31 09:11:53,636 [info] c.z.h.HikariDataSource - HikariPool-60 - Shutdown initiated...
2019-10-31 09:11:53,640 [info] c.z.h.HikariDataSource - HikariPool-60 - Shutdown completed.
....
2019-10-31 09:12:26,454 [info] p.a.d.DefaultDBApi - Database [amseewen] initialized at jdbc:postgresql://localhost:5432/bpf?currentSchema=amseewen
2019-10-31 09:12:26,454 [info] application - Creating Pool for datasource 'amseewen'
2019-10-31 09:12:26,454 [info] c.z.h.HikariDataSource - HikariPool-68 - Starting...
2019-10-31 09:12:26,455 [info] c.z.h.HikariDataSource - HikariPool-68 - Start completed.
2019-10-31 09:12:26,455 [info] p.a.d.DefaultDBApi - Database [companyOds] initialized at jdbc:sqlserver://localhost:1433;databaseName=companyOds
2019-10-31 09:12:26,455 [info] application - Creating Pool for datasource 'companyOds'
2019-10-31 09:12:26,455 [info] c.z.h.HikariDataSource - HikariPool-69 - Starting...
2019-10-31 09:12:26,456 [info] c.z.h.HikariDataSource - HikariPool-69 - Start completed.
2019-10-31 09:12:26,457 [info] p.a.d.DefaultDBApi - Database [company] initialized at jdbc:oracle:thin:@castor.olymp:1521:citrin
2019-10-31 09:12:26,457 [info] application - Creating Pool for datasource 'company'
2019-10-31 09:12:26,457 [info] c.z.h.HikariDataSource - HikariPool-70 - Starting...
2019-10-31 09:12:26,458 [info] c.z.h.HikariDataSource - HikariPool-70 - Start completed.
2019-10-31 09:12:26,458 [info] p.a.d.DefaultDBApi - Database [amseewen] initialized at jdbc:postgresql://localhost:5432/bpf?currentSchema=amseewen
2019-10-31 09:12:26,458 [info] application - Creating Pool for datasource 'amseewen'
2019-10-31 09:12:26,458 [info] c.z.h.HikariDataSource - HikariPool-71 - Starting...
2019-10-31 09:12:26,459 [info] c.z.h.HikariDataSource - HikariPool-71 - Start completed.
2019-10-31 09:12:26,459 [info] p.a.d.DefaultDBApi - Database [companyOds] initialized at jdbc:sqlserver://localhost:1433;databaseName=companyOds
2019-10-31 09:12:26,459 [info] application - Creating Pool for datasource 'companyOds'
2019-10-31 09:12:26,459 [info] c.z.h.HikariDataSource - HikariPool-72 - Starting...
2019-10-31 09:12:26,459 [info] c.z.h.HikariDataSource - HikariPool-72 - Start completed.

Is there a way to shorten this time?

Updates

I use The Play integration of Intellij. The build-tool is sbt.

Here is the configuration:

Build Config

sbt 1.2.8

Thread Pools

We use the default thread pool for the application. For the Database access we use:

database.dispatcher {
  executor = "thread-pool-executor"
  throughput = 1
  thread-pool-executor {
    fixed-pool-size = 55 # db conn pool (50) + number of cores (4) + housekeeping (1)
  }
}
pme
  • 14,156
  • 3
  • 52
  • 95
  • @user7294900 the `......` is all hikari. The main reason is that we have about 5 databases, for each of them hikari creates a pool. – pme Nov 06 '19 at 16:16
  • You haven't provided the most important informations such as build tool, how is your project setup into module, IDE, configurations. –  Nov 08 '19 at 15:25
  • @Issilva I adjusted my question - let me know if still is something missing. – pme Nov 08 '19 at 15:35
  • What SBT version do you have? if you change the pool size does it speed things up? why so low on jvm memory? how long does a clean SBT compile takes? what are the SBT options you are using? During development do you really need a connection pool? –  Nov 08 '19 at 15:48
  • @Issilva sbt 1.2.8. Increasing Memory did not help. clean 5s, compile 64s, We develop with a real database. I think the main problem is that the Pools are stopped sequentially and not in parallel, resp. I don't found how to share the pools between the datasources. – pme Nov 10 '19 at 16:40
  • Yes that is why I asked about the module structure because if you have a persistence layer module and the actual part of code you are changing has nothing to do with the persistence then it doesn't need to restart at all –  Nov 11 '19 at 10:47
  • @Issilva so it would help to move the persistence stuff from the play server module to its own module? – pme Nov 11 '19 at 17:57
  • Probably not, this issue seems to be easier to solve with configuration. Just hard without the whole project overview. How is your play thread pool configured? https://www.playframework.com/documentation/2.7.x/ThreadPools –  Nov 12 '19 at 08:12
  • @Issilva I added the configuration to the question – pme Nov 12 '19 at 08:46

1 Answers1

1

Ok with the help of billoneil on the Hikari Github Page and suggestions of @Issilva, I could figure out the problem:

The problem are now datasources where the database is not reachable (during development). So we configured it, that the application also starts when the database is not reachable (initializationFailTimeout = -1).

So there are 2 problems when shutting down:

  • The pools are shutdown sequentially.
  • A pool that has no connection takes 10 seconds to shutdown.

The suggested solution is not to initialise the datasources that can not be reached. Except a strange exception the shutdown time problem is solved (down to milliseconds).

pme
  • 14,156
  • 3
  • 52
  • 95