From 1c258b8fc90d4654da3b2104daf4d7ad58bd5631 Mon Sep 17 00:00:00 2001 From: Naftoli Gugenheim <98384+nafg@users.noreply.github.com> Date: Thu, 12 Nov 2020 02:36:58 -0500 Subject: [PATCH] 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/scala/sbt/internal/GCMonitor.scala | 89 +++++++++++++------ .../scala/sbt/internal/GCMonitorTest.scala | 55 ++++++++++++ 2 files changed, 117 insertions(+), 27 deletions(-) create mode 100644 main/src/test/scala/sbt/internal/GCMonitorTest.scala diff --git a/main/src/main/scala/sbt/internal/GCMonitor.scala b/main/src/main/scala/sbt/internal/GCMonitor.scala index e83b53ac3..3e702e161 100644 --- a/main/src/main/scala/sbt/internal/GCMonitor.scala +++ b/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 diff --git a/main/src/test/scala/sbt/internal/GCMonitorTest.scala b/main/src/test/scala/sbt/internal/GCMonitorTest.scala new file mode 100644 index 000000000..7bc6b5978 --- /dev/null +++ b/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)) + } +}