diff --git a/main/src/main/scala/sbt/internal/GCMonitor.scala b/main/src/main/scala/sbt/internal/GCMonitor.scala index e83b53ac3..aacd8fac3 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 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 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..02356e0a3 --- /dev/null +++ b/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)) + } +} 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..d9593ef79 --- /dev/null +++ b/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}") +}