jdbc - HikariCP: Seeing low insert thoughput while DB/App cpu % is still low

Question

I've set up doobie + hikaricp with settings similar to the default. With debug logging I can see how many connections are active / idle and this also reflects what pg_stat_activity returns with this query

SELECT
  pid,
  query,
  query_start,
  state
FROM pg_stat_activity;

HikariPool-1 - Pool stats (total=10, active=4, idle=6, waiting=0)

My app mainly processes messages from a stream by storing them in the db with through a transaction that consists of 3 inserts and 2 selects before committing.

Below is how the transactor is created with hikariCP:

val hikariConfig = new HikariConfig()
hikariConfig.setJdbcUrl(dbUrl)
hikariConfig.setDriverClassName("org.postgresql.Driver")
hikariConfig.setUsername(dbUser)
hikariConfig.setPassword(dbPassword)
hikariConfig.setMaximumPoolSize(10)
hikariConfig.setAutoCommit(false)
hikariConfig.addDataSourceProperty("socketTimeout", "30")

val dataSource: HikariDataSource     = new HikariDataSource(hikariConfig)
val transactor: HikariTransactor[IO] = HikariTransactor[IO](dataSource)

this transactor is then passed everywhere to handle database transactions:

import doobie._
import doobie.implicits._
import doobie.postgres.implicits._

val query = for {
  _ <- sql"insert into foo (id, value) values (fooId, 'b')".update.run
  _ <- sql"insert into bar (id, value) values (barId, 'b')".update.run
  _ <- sql"select * from bar where id = $barId".query[Bar].unique
  _ <- sql"insert into bazz (id, value1, value2) values (bazzId, fooId, barId)".update.run
  _ <- sql"select * from bazz where id = $barId".query[Bazz].unique
} yield ()

query.transact(transactor).unsafeToFuture()

The issue I'm seeing is that the queries seem fast but insert throughput is slow.

Some points I noticed:

1. Checking pg_stat_activity, I see many COMMIT queries (more than the inserts) where each take between ~90ms - 200ms.

   SELECT pid, now() - pg_stat_activity.query_start AS duration, query, query_start, state FROM pg_stat_activity where state <> 'idle' order by duration desc;

2. The above pg_stat_activity query only returns 4-8 rows at a time, majority of the results are query = 'COMMIT'.

3. Starting from an empty stream, the throughput can go as high as 30k messages a minute. After 15-20 minutes though, the throughput drops to 3k messages a minute and does not reset recover until the stream is empty for many hours where restarting the app or scaling more instances of the app does not improve throughput.

Both the database's and app's CPU (10%) / Mem usage (16%) is low so theoretically the throughput should be able to go much higher, what would be some areas worth investigating?

currently using doobie 0.5.4, hikariCP 0.5.4

UPDATE: Raised commit_delay and commit_siblings settings on the rds database from Laurenz's suggestion which prolonged the period of high throughput from 30 minutes -> 60 minutes before the prolonged decrease in throughput as previous. I started testing raising max_wal_size but this seems to cause spikier throughput (at times very low) not close to the original startup rate.

Answer 1

If COMMIT takes long, that's a clear indication that your I/O system is overloaded.

If it is not the I/O volume that is the problem, it is probably the many WAL sync requests from the many transactions.

Some options:

• Perform the work with fewer, bigger transactions.

• If you can afford to lose half a second of committed transactions in the event of a crash, set synchronous_commit to off.

• If losing committed transactions is not an option, tune commit_delay and commit_siblings. That will make transactions take slightly longer, but it can reduce the I/O load.