GCMonitor: Unit tests, refactor, and improve

* Refactor so as to be testable
 * Queue stores the _beginning_ timestamp of each GC time delta
 * Message states the correct time over which the GC time was recorded
 * Add heap stats from java.lang.Runtime to the message

main/src/main/scala/sbt/internal/GCMonitor.scala

@@ -7,48 +7,83 @@
 
 package sbt.internal
 
-import javax.management.{ Notification, NotificationEmitter, NotificationListener }
+import javax.management.{ NotificationEmitter, NotificationListener }
 import java.lang.management.ManagementFactory
-import java.lang.management.GarbageCollectorMXBean
 import java.util.concurrent.LinkedBlockingQueue
-import java.util.concurrent.atomic.{ AtomicLong, AtomicReference }
+import java.util.concurrent.atomic.AtomicReference
 import scala.concurrent.duration._
 import scala.collection.JavaConverters._
 import scala.util.Try
 import sbt.util.Logger
 
-class GCMonitor(logger: Logger) extends AutoCloseable {
-  private[this] val window =
-    Try(System.getProperty("sbt.gc.monitor.window", "10").toInt).getOrElse(10).seconds
-  private[this] val ratio =
-    Try(System.getProperty("sbt.gc.monitor.ratio", "0.5").toDouble).getOrElse(0.5)
-  private[this] val queue = new LinkedBlockingQueue[(FiniteDuration, Long)]
-  private[this] val lastWarned = new AtomicReference(Deadline(0.millis))
-  private[this] def handleNotification(
-      notification: Notification,
-      bean: GarbageCollectorMXBean,
-      totalCollectionTime: AtomicLong
+trait GCMonitorBase {
+  protected def window: FiniteDuration
+
+  protected def ratio: Double
+
+  protected val queue = new LinkedBlockingQueue[(FiniteDuration, Long)]
+  protected val queueScala = queue.asScala
+  private[this] val lastWarned = new AtomicReference(Deadline(Int.MinValue.millis))
+
+  protected def emitWarning(total: Long, over: Option[Long]): Unit
+
+  val startTime = System.currentTimeMillis()
+
+  private[internal] def totalCollectionTimeChanged(
+      nowMillis: Long,
+      collectionTime: Long,
+      collectionTimeStore: AtomicReference[(FiniteDuration, Long)]
   ): Unit = {
-    val now = notification.getTimeStamp.millis
-    val collectionTime = bean.getCollectionTime
-    val elapsed = collectionTime - totalCollectionTime.getAndSet(collectionTime)
+    val now = nowMillis.millis
+    val (lastTimestamp, lastCollectionTime) = collectionTimeStore.getAndSet(now -> collectionTime)
+    val elapsed = collectionTime - lastCollectionTime
     queue.removeIf { case (whenEventHappened, _) => now > whenEventHappened + window }
-    queue.add(now -> elapsed)
-    val total = queue.asScala.foldLeft(0L) { case (total, (_, t)) => total + t }
-    if ((total > window.toMillis * ratio) && (lastWarned.get + window).isOverdue) {
-      lastWarned.set(Deadline.now)
-      val msg = s"${total / 1000.0} seconds of the last $window were spent in garbage " +
-        "collection. You may want to increase the project heap size using `-Xmx` or try " +
-        "a different gc algorithm, e.g. `-XX:+UseG1GC`, for better performance."
-      logger.warn(msg)
+    queue.add(lastTimestamp -> elapsed)
+    val total = queueScala.foldLeft(0L) { case (total, (_, t)) => total + t }
+    val over = queueScala.headOption.map(nowMillis - _._1.toMillis)
+    if ((total > window.toMillis * ratio) && (lastWarned.get + window).time <= now) {
+      lastWarned.set(Deadline(now))
+      emitWarning(total, over)
     }
   }
+}
+
+class GCMonitor(logger: Logger) extends GCMonitorBase with AutoCloseable {
+  override protected def window =
+    Try(System.getProperty("sbt.gc.monitor.window", "10").toInt).getOrElse(10).seconds
+
+  override protected def ratio =
+    Try(System.getProperty("sbt.gc.monitor.ratio", "0.5").toDouble).getOrElse(0.5)
+
+  final val GB = 1024 * 1024 * 1024.0
+  val runtime = Runtime.getRuntime
+  def gbString(n: Long) = f"${n / GB}%.2fGB"
+
+  override protected def emitWarning(total: Long, over: Option[Long]): Unit = {
+    val totalSeconds = total / 1000.0
+    val amountMsg = over.fold(totalSeconds + " seconds") { d =>
+      "In the last " + (d / 1000.0).ceil.toInt + f" seconds, $totalSeconds (${total.toDouble / d * 100}%.1f%%)"
+    }
+    val msg = s"$amountMsg were spent in garbage collection. " +
+      "You may want to increase the project heap size using `-Xmx` or try " +
+      "a different gc algorithm, e.g. `-XX:+UseG1GC`, for better performance. " +
+      s"Heap: ${gbString(runtime.freeMemory())} free " +
+      s"of ${gbString(runtime.totalMemory())}, " +
+      s"max ${gbString(runtime.maxMemory())}"
+    logger.warn(msg)
+  }
 
   val removers = ManagementFactory.getGarbageCollectorMXBeans.asScala.flatMap {
     case bean: NotificationEmitter =>
-      val elapsedTime = new AtomicLong(bean.getCollectionTime)
+      val collectionTimeStore =
+        new AtomicReference(System.currentTimeMillis().millis -> bean.getCollectionTime)
       val listener: NotificationListener =
-        (notification, _) => handleNotification(notification, bean, elapsedTime)
+        (notification, _) =>
+          totalCollectionTimeChanged(
+            notification.getTimeStamp,
+            bean.getCollectionTime,
+            collectionTimeStore
+          )
       bean.addNotificationListener(listener, null, null)
       Some(() => bean.removeNotificationListener(listener))
     case _ => None

main/src/test/scala/sbt/internal/GCMonitorTest.scala

@@ -0,0 +1,55 @@
+package sbt.internal
+
+import java.util.concurrent.atomic.AtomicReference
+
+import org.scalatest.FunSuite
+
+import scala.collection.mutable.ListBuffer
+import scala.concurrent.duration._
+
+class GCMonitorTest extends FunSuite {
+  class TestMonitor extends GCMonitorBase {
+    val loggedTotals = ListBuffer.empty[Long]
+    override protected val window = 10.seconds
+    override protected val ratio = 0.5
+
+    override protected def emitWarning(total: Long, over: Option[Long]): Unit =
+      loggedTotals += total
+  }
+
+  val collectionTimeStore = new AtomicReference(0.millis -> 0L)
+
+  def simulateBy(f: Long => Long): Long => List[Long] = { duration =>
+    collectionTimeStore.set(0.millis -> 0)
+    val testMonitor = new TestMonitor
+    for (x <- 0L to duration by 100)
+      testMonitor.totalCollectionTimeChanged(x, f(x), collectionTimeStore)
+    testMonitor.loggedTotals.toList
+  }
+
+  test("GC time = time") {
+    val simulate = simulateBy(identity)
+    assertResult(List())(simulate(5000))
+    assertResult(List(5100))(simulate(10000))
+    assertResult(List(5100, 10100))(simulate(20000))
+    assertResult(List(5100, 10100, 10100))(simulate(30000))
+    assertResult(List(5100, 10100, 10100, 10100))(simulate(40000))
+  }
+
+  test("GC time = 0.5 * time") {
+    val simulate = simulateBy(_ / 2)
+    assertResult(List())(simulate(10000))
+    assertResult(List(5050))(simulate(20000))
+    assertResult(List(5050, 5050))(simulate(30000))
+    assertResult(List(5050, 5050, 5050))(simulate(40000))
+  }
+
+  test("GC time = 2 * time") {
+    val simulate = simulateBy(_ * 2)
+    assertResult(List(5200))(simulate(5000))
+    assertResult(List(5200))(simulate(10000))
+    assertResult(List(5200, 20200))(simulate(20000))
+    assertResult(List(5200, 20200, 20200))(simulate(30000))
+    assertResult(List(5200, 20200, 20200, 20200))(simulate(40000))
+  }
+}