From af7346f5657c535f77556c86a0c8d140e1802082 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 1/5] Program to manually test GCMonitor --- .../scala/sbt/internal/StressGCMonitor.scala | 23 +++++++++++++++++++ 1 file changed, 23 insertions(+) create mode 100644 main/src/test/scala/sbt/internal/StressGCMonitor.scala diff --git a/main/src/test/scala/sbt/internal/StressGCMonitor.scala b/main/src/test/scala/sbt/internal/StressGCMonitor.scala new file mode 100644 index 000000000..c8f9cbf82 --- /dev/null +++ b/main/src/test/scala/sbt/internal/StressGCMonitor.scala @@ -0,0 +1,23 @@ +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}") +} 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 2/5] 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)) + } +} From 6cca595420e99d2b53e213c81d515462700dddf7 Mon Sep 17 00:00:00 2001 From: Naftoli Gugenheim <98384+nafg@users.noreply.github.com> Date: Thu, 12 Nov 2020 14:25:10 -0500 Subject: [PATCH 3/5] Add file headers --- main/src/test/scala/sbt/internal/GCMonitorTest.scala | 7 +++++++ main/src/test/scala/sbt/internal/StressGCMonitor.scala | 7 +++++++ 2 files changed, 14 insertions(+) diff --git a/main/src/test/scala/sbt/internal/GCMonitorTest.scala b/main/src/test/scala/sbt/internal/GCMonitorTest.scala index 7bc6b5978..067ea15c1 100644 --- a/main/src/test/scala/sbt/internal/GCMonitorTest.scala +++ b/main/src/test/scala/sbt/internal/GCMonitorTest.scala @@ -1,3 +1,10 @@ +/* + * 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 diff --git a/main/src/test/scala/sbt/internal/StressGCMonitor.scala b/main/src/test/scala/sbt/internal/StressGCMonitor.scala index c8f9cbf82..d9593ef79 100644 --- a/main/src/test/scala/sbt/internal/StressGCMonitor.scala +++ b/main/src/test/scala/sbt/internal/StressGCMonitor.scala @@ -1,3 +1,10 @@ +/* + * 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 From 889b101cbd5b835074b58d0c3de3047ce78ce81e Mon Sep 17 00:00:00 2001 From: Naftoli Gugenheim <98384+nafg@users.noreply.github.com> Date: Thu, 12 Nov 2020 14:48:35 -0500 Subject: [PATCH 4/5] Update tests for fixed GCMonitor --- .../scala/sbt/internal/GCMonitorTest.scala | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/main/src/test/scala/sbt/internal/GCMonitorTest.scala b/main/src/test/scala/sbt/internal/GCMonitorTest.scala index 067ea15c1..02356e0a3 100644 --- a/main/src/test/scala/sbt/internal/GCMonitorTest.scala +++ b/main/src/test/scala/sbt/internal/GCMonitorTest.scala @@ -38,25 +38,25 @@ class GCMonitorTest extends FunSuite { 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)) + 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(5050))(simulate(20000)) - assertResult(List(5050, 5050))(simulate(30000)) - assertResult(List(5050, 5050, 5050))(simulate(40000)) + 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, 20200))(simulate(20000)) - assertResult(List(5200, 20200, 20200))(simulate(30000)) - assertResult(List(5200, 20200, 20200, 20200))(simulate(40000)) + assertResult(List(5200, 20000))(simulate(20000)) + assertResult(List(5200, 20000, 20000))(simulate(30000)) + assertResult(List(5200, 20000, 20000, 20000))(simulate(40000)) } } From 3c2565722a18b7bad295bb4328fbc5b65282b0d0 Mon Sep 17 00:00:00 2001 From: nafg <98384+nafg@users.noreply.github.com> Date: Sat, 14 Nov 2020 23:56:46 -0500 Subject: [PATCH 5/5] Tweak warning text --- main/src/main/scala/sbt/internal/GCMonitor.scala | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/main/src/main/scala/sbt/internal/GCMonitor.scala b/main/src/main/scala/sbt/internal/GCMonitor.scala index 3e702e161..aacd8fac3 100644 --- a/main/src/main/scala/sbt/internal/GCMonitor.scala +++ b/main/src/main/scala/sbt/internal/GCMonitor.scala @@ -64,12 +64,12 @@ class GCMonitor(logger: Logger) extends GCMonitorBase with AutoCloseable { 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 " + + val msg = s"$amountMsg were spent in GC. " + + s"[Heap: ${gbString(runtime.freeMemory())} free " + s"of ${gbString(runtime.totalMemory())}, " + - s"max ${gbString(runtime.maxMemory())}" + 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) }