Merge pull request #6082 from nafg/develop

GCMonitor improvements

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 GC. " +
+      s"[Heap: ${gbString(runtime.freeMemory())} free " +
+      s"of ${gbString(runtime.totalMemory())}, " +
+      s"max ${gbString(runtime.maxMemory())}] " +
+      "Consider increasing the JVM heap using `-Xmx` or try " +
+      "a different collector, e.g. `-XX:+UseG1GC`, for better performance."
+    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,62 @@
+/*
+ * sbt
+ * Copyright 2011 - 2018, Lightbend, Inc.
+ * Copyright 2008 - 2010, Mark Harrah
+ * Licensed under Apache License 2.0 (see LICENSE)
+ */
+
+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, 10000))(simulate(20000))
+    assertResult(List(5100, 10000, 10000))(simulate(30000))
+    assertResult(List(5100, 10000, 10000, 10000))(simulate(40000))
+  }
+
+  test("GC time = 0.5 * time") {
+    val simulate = simulateBy(_ / 2)
+    assertResult(List())(simulate(10000))
+    assertResult(List())(simulate(20000))
+    assertResult(List())(simulate(30000))
+    assertResult(List())(simulate(40000))
+  }
+
+  test("GC time = 2 * time") {
+    val simulate = simulateBy(_ * 2)
+    assertResult(List(5200))(simulate(5000))
+    assertResult(List(5200))(simulate(10000))
+    assertResult(List(5200, 20000))(simulate(20000))
+    assertResult(List(5200, 20000, 20000))(simulate(30000))
+    assertResult(List(5200, 20000, 20000, 20000))(simulate(40000))
+  }
+}

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

@@ -0,0 +1,30 @@
+/*
+ * sbt
+ * Copyright 2011 - 2018, Lightbend, Inc.
+ * Copyright 2008 - 2010, Mark Harrah
+ * Licensed under Apache License 2.0 (see LICENSE)
+ */
+
+package sbt.internal
+
+import sbt.internal.util.ConsoleLogger
+
+import scala.concurrent.duration._
+import scala.util.Random
+
+object StressGCMonitor {
+  var list = List.empty[Int]
+
+  def main(args: Array[String]): Unit = {
+    new GCMonitor(ConsoleLogger())
+    val deadline = Deadline.now + 10.seconds
+    while (!deadline.isOverdue()) {
+      println(deadline.timeLeft.toSeconds + " seconds left...")
+      list = List.fill(1000 * 1000 * 100)(Random.nextInt(100))
+      System.gc()
+      Thread.sleep(10)
+    }
+  }
+
+  def print(): Unit = println(s"random number: ${list.sum}")
+}