2021 01 27 conectionpool (#2578)

* Give connection pool example config

* Get hikari logging working on postgres

* fix 2.12.x

* Bump metrics core to a supported version

* Add hikari-logging and hikari-logging-interval configuration options to turn off/on hikari and schedule how often logs appear

* Turn off hikari logging in the db-commons/reference.conf and add it to appserver/reference.conf

* default the logging to off in scala code

* Make sure connection pool is enabled in db-commons, add default database configuration to website

* Address code review, fix things that didn't need to be changed

app/oracle-server/src/main/resources/reference.conf

@@ -1,8 +1,15 @@
+bitcoin-s {
+    oracle {
+        hikari-logging = true
+        hikari-logging-interval = 1 minute
+    }
+}
+
 akka {
 
   # Set these to the defaults instead of the
   # appServer's modified ones
   http.server.request-timeout = 10s
   http.server.parsing.max-content-length = 8m
   http.client.parsing.max-content-length = 8m
-}
+}

app/server/src/main/resources/logback.xml

@@ -93,7 +93,7 @@
 
     <!-- Disable slick logging in server -->
     <logger name="slick" level="OFF"/>
-    <logger name="com.zaxxer" level="OFF"/>
+    <logger name="com.zaxxer" level="INFO"/>
 
     <!-- Get rid of messages like this:
     Connection attempt failed. Backing off new connection

app/server/src/main/resources/reference.conf

@@ -1,8 +1,21 @@
 bitcoin-s {
     network = mainnet
 
+    chain {
+        hikari-logging = true
+        hikari-logging-interval = 1 minute
+    }
+
+    wallet {
+        hikari-logging = true
+        hikari-logging-interval = 1 minute
+    }
+
     node {
         mode = neutrino # neutrino, spv, bitcoind
         peers = ["neutrino.suredbits.com:8333"]
+
+        hikari-logging = true
+        hikari-logging-interval = 1 minute
     }
 }

chain/src/main/scala/org/bitcoins/chain/config/ChainAppConfig.scala

@@ -92,11 +92,23 @@ case class ChainAppConfig(
         }
       }
     } yield {
+      if (isHikariLoggingEnabled) {
+        //.get is safe because hikari logging is enabled
+        startHikariLogger(hikariLoggingInterval.get)
+        ()
+      }
+
       logger.info(s"Applied ${numMigrations} to chain project")
+      ()
     }
 
   }
 
+  override def stop(): Future[Unit] = {
+    val _ = stopHikariLogger()
+    FutureUtil.unit
+  }
+
   lazy val filterHeaderBatchSize: Int = {
     // try by network, if that fails, try general
     try {

db-commons-test/src/test/scala/org/bitcoins/db/AppConfigTest.scala

@@ -97,7 +97,8 @@ class AppConfigTest extends BitcoinSAsyncTest {
     //to freshly load all system properties
     ConfigFactory.invalidateCaches()
 
-    val walletAppConfig = WalletAppConfig(datadir)
+    val walletAppConfig =
+      WalletAppConfig(datadir)
     val assertF = for {
       _ <- walletAppConfig.start()
     } yield {

db-commons/src/main/resources/reference.conf

@@ -20,8 +20,11 @@ bitcoin-s {
       # see: https://github.com/bitcoin-s/bitcoin-s/pull/1840
       numThreads = 1
       queueSize=5000
-      connectionPool = disabled
+      connectionPool = "HikariCP"
+      registerMbeans = true
     }
+    hikari-logging = false
+    hikari-logging-interval = 1 minute
   }
 
   node = ${bitcoin-s.dbDefault}

db-commons/src/main/scala/org/bitcoins/db/AppConfig.scala

@@ -107,7 +107,7 @@ abstract class AppConfig extends StartStopAsync[Unit] with BitcoinSLogger {
   /**
     * Name of the module. `chain`, `wallet`, `node` etc.
     */
-  protected[bitcoins] def moduleName: String
+  private[bitcoins] def moduleName: String
 
   /** Chain parameters for the blockchain we're on */
   lazy val chain: BitcoinChainParams = {

db-commons/src/main/scala/org/bitcoins/db/DbAppConfig.scala

@@ -7,7 +7,9 @@ import slick.basic.DatabaseConfig
 import slick.jdbc.JdbcProfile
 
 import java.nio.file.{Path, Paths}
+import java.util.concurrent.TimeUnit
 import scala.concurrent.Future
+import scala.concurrent.duration.{Duration, FiniteDuration}
 import scala.util.{Failure, Success, Try}
 
 abstract class DbAppConfig extends AppConfig {
@@ -120,4 +122,35 @@ abstract class DbAppConfig extends AppConfig {
         throw exception
     }
   }
+
+  lazy val isHikariLoggingEnabled: Boolean = {
+    val hikariLoggingOpt =
+      config.getBooleanOpt(s"bitcoin-s.$moduleName.hikari-logging")
+    hikariLoggingOpt match {
+      case Some(bool) => bool
+      case None       =>
+        //default hikari logging off
+        false
+    }
+  }
+
+  /** Gets how often we should log hikari connection pool stats
+    * if None, this means [[isHikariLoggingEnabled]] is not enabled
+    */
+  lazy val hikariLoggingInterval: Option[Duration] = {
+    if (isHikariLoggingEnabled) {
+      val intervalOpt =
+        config.getDurationOpt(s"bitcoin-s.$moduleName.hikari-logging-interval")
+      val interval = intervalOpt match {
+        case Some(interval) => interval
+        case None           =>
+          //default to 1 minute if nothing is set
+          new FiniteDuration(1, TimeUnit.MINUTES)
+      }
+      Some(interval)
+    } else {
+      None
+    }
+
+  }
 }

db-commons/src/main/scala/org/bitcoins/db/HikariLogging.scala

@@ -0,0 +1,239 @@
+package org.bitcoins.db
+
+import com.codahale.metrics.{Histogram, MetricRegistry}
+import com.zaxxer.hikari.{HikariDataSource, HikariPoolMXBean}
+import org.bitcoins.core.util.{BitcoinSLogger, StartStop}
+import slick.jdbc.JdbcDataSource
+import slick.jdbc.hikaricp.HikariCPJdbcDataSource
+import slick.util.AsyncExecutorMXBean
+
+import java.lang.management.ManagementFactory
+import java.util.concurrent.{Executors, ScheduledFuture, TimeUnit}
+import javax.management.{JMX, ObjectName}
+import scala.concurrent.duration._
+
+case class HikariLogging(
+    hikariDataSource: HikariDataSource,
+    moduleName: String,
+    interval: Duration
+) extends BitcoinSLogger
+    with StartStop[HikariLogging] {
+
+  /** Logs thread activity */
+  private case class HikariActivityUpdate(
+      active: Int,
+      idle: Int,
+      waiting: Int,
+      total: Int,
+      maxThreads: Int,
+      activeThreads: Int,
+      maxQueueSize: Int,
+      queueSize: Int
+  ) {
+
+    override def toString: String = {
+      s"""
+         | "${moduleName}-activity-update" : { 
+         |  "active" : ${active},
+         |  "idle" : ${idle},
+         |  "waiting" : ${waiting},
+         |  "total" : ${total},
+         |  "maxThreads" : ${maxThreads},
+         |  "activeThreads" : ${activeThreads},
+         |  "maxQueueSize" : ${maxQueueSize},
+         |  "queueSize" : ${queueSize}
+         |}
+         |""".stripMargin.replaceAll("\\s", "")
+    }
+  }
+
+  /**
+    * From the docs:
+    * How long each connection is used before being returned to the pool. This is the "out of pool" or "in-use" time.
+    * @see https://github.com/brettwooldridge/HikariCP/wiki/Dropwizard-Metrics
+    */
+  private case class HikariPoolUsageUpdate(
+      `75thPercentile`: Double,
+      `95thPercentile`: Double,
+      `98thPercentile`: Double,
+      `99thPercentile`: Double,
+      `999thPercentile`: Double,
+      max: Double,
+      min: Double,
+      median: Double,
+      mean: Double
+  ) {
+
+    override def toString: String = {
+      s"""
+         |"${moduleName}-pool-usage" : { 
+         |  "max" : ${max},
+         |  "min" : ${min},
+         |  "median" : ${median},
+         |  "mean" : ${mean},
+         |  "75thPercentile" : ${`75thPercentile`},
+         |  "95thPercentile" : ${`95thPercentile`},
+         |  "98thPercentile" : ${`98thPercentile`},
+         |  "99thPercentile" : ${`99thPercentile`},
+         |  "999thPercentile" : ${`999thPercentile`}
+         |}
+         |""".stripMargin.replaceAll("\\s", "")
+    }
+  }
+
+  //this is needed to get the 'AsyncExecutor' bean below to register properly
+  //dbConfig.database.ioExecutionContext
+
+  private lazy val poolName = hikariDataSource.getPoolName
+  private lazy val mBeanServer = ManagementFactory.getPlatformMBeanServer
+
+  lazy val aeBeanName = new ObjectName(
+    s"slick:type=AsyncExecutor,name=$poolName")
+
+  lazy val poolBeanName = new ObjectName(
+    s"com.zaxxer.hikari:type=Pool ($poolName)")
+
+  lazy val poolConfigBeanName = new ObjectName(
+    s"com.zaxxer.hikari:type=PoolConfig ($poolName)"
+  )
+
+  /**
+    * MBean uses random string incantations for
+    * accessing attributes :-(
+    *
+    * @see [[https://github.com/brettwooldridge/HikariCP/wiki/MBean-(JMX)-Monitoring-and-Management#programmatic-access HikariCP docs]]
+    */
+  private lazy val objectName = new ObjectName(
+    s"com.zaxxer.hikari:type=Pool ($poolName)"
+  )
+
+  /**
+    * @see https://github.com/brettwooldridge/HikariCP/wiki/MBean-(JMX)-Monitoring-and-Management
+    */
+  private lazy val hikariMxBean =
+    JMX.newMXBeanProxy(mBeanServer, objectName, classOf[HikariPoolMXBean])
+
+  /**
+    * @see http://slick.lightbend.com/doc/3.3.0/config.html#monitoring
+    */
+  private lazy val slickMxBean =
+    JMX.newMXBeanProxy(mBeanServer, aeBeanName, classOf[AsyncExecutorMXBean])
+
+  // https://github.com/brettwooldridge/HikariCP/wiki/Dropwizard-Metrics#pool-namepoolusage
+  private lazy val poolUsageMetricName = s"$poolName.pool.Usage"
+
+  private lazy val metricRegistry: MetricRegistry = Option(
+    hikariDataSource.getMetricRegistry
+  ) match {
+    case Some(registry: MetricRegistry) =>
+      registry
+    case Some(other: AnyRef) =>
+      val msg = s"Could not load metric registry, got $other"
+      logger.error(msg)
+      throw new RuntimeException(msg)
+    case None =>
+      val msg = "Could not load metric registry, got null!"
+      logger.error(msg)
+      throw new RuntimeException(msg)
+  }
+
+  private val logHikariStats: Runnable = () => {
+
+    val usageHistogram: Histogram =
+      metricRegistry.getHistograms().get(poolUsageMetricName)
+    val usageSnapshot = usageHistogram.getSnapshot()
+
+    val poolUsageUpdate = HikariPoolUsageUpdate(
+      `75thPercentile` = usageSnapshot.get75thPercentile(),
+      `95thPercentile` = usageSnapshot.get95thPercentile(),
+      `98thPercentile` = usageSnapshot.get98thPercentile(),
+      `99thPercentile` = usageSnapshot.get99thPercentile(),
+      `999thPercentile` = usageSnapshot.get999thPercentile(),
+      max = usageSnapshot.getMax().toDouble,
+      min = usageSnapshot.getMin().toDouble,
+      median = usageSnapshot.getMedian(),
+      mean = usageSnapshot.getMean()
+    )
+
+    val activityUpdate = HikariActivityUpdate(
+      active = hikariMxBean.getActiveConnections,
+      idle = hikariMxBean.getIdleConnections,
+      waiting = hikariMxBean.getThreadsAwaitingConnection,
+      total = hikariMxBean.getTotalConnections,
+      maxThreads = slickMxBean.getMaxThreads,
+      activeThreads = slickMxBean.getActiveThreads,
+      maxQueueSize = slickMxBean.getMaxQueueSize,
+      queueSize = slickMxBean.getQueueSize
+    )
+
+    logger.info(poolUsageUpdate)
+    logger.info(activityUpdate)
+  }
+
+  private[this] var started: Boolean = false
+  private[this] var cancelOpt: Option[ScheduledFuture[_]] = None
+
+  override def start(): HikariLogging = {
+    if (!started) {
+      val metricRegistry = new MetricRegistry
+
+      mBeanServer.getMBeanInfo(aeBeanName)
+      mBeanServer.getMBeanInfo(poolBeanName)
+      mBeanServer.getMBeanInfo(poolConfigBeanName)
+
+      hikariDataSource.setMetricRegistry(metricRegistry)
+      val future = HikariLogging.scheduler.scheduleAtFixedRate(
+        logHikariStats,
+        interval.toMillis,
+        interval.toMillis,
+        TimeUnit.MILLISECONDS)
+      cancelOpt = Some(future)
+      started = true
+      this
+    } else {
+      this
+    }
+  }
+
+  override def stop(): HikariLogging = {
+    cancelOpt match {
+      case Some(cancel) =>
+        if (!cancel.isCancelled) {
+          val _: Boolean = cancel.cancel(true)
+          this
+        } else {
+          cancelOpt = None
+          this
+        }
+      case None =>
+        this
+    }
+  }
+}
+
+object HikariLogging extends BitcoinSLogger {
+  private[db] val scheduler = Executors.newScheduledThreadPool(1)
+
+  /** Returns a started hikari logger if configuration is correct, else None
+    * @param jdbcProfileComponent the database component we are logging for
+    * @param interval how often the hikari logs should be output
+    */
+  def fromJdbcProfileComponent[T <: DbAppConfig](
+      jdbcProfileComponent: JdbcProfileComponent[T],
+      interval: Duration): Option[HikariLogging] = {
+    val dataSource = jdbcProfileComponent.database.source
+    val moduleName = jdbcProfileComponent.appConfig.moduleName
+    dataSource match {
+      case hikariSource: HikariCPJdbcDataSource =>
+        val started = HikariLogging(hikariSource.ds, moduleName, interval)
+          .start()
+        Some(started)
+      case _: JdbcDataSource =>
+        val err = {
+          s"JdbcProfile Component is not a Hikari source=${jdbcProfileComponent.dbConfig.profile}"
+        }
+        logger.error(err)
+        None
+    }
+  }
+}