From fdce1eb7e6d0f88a2ac4ac84c2c594c446d30bf3 Mon Sep 17 00:00:00 2001
From: Ethan Atkins <contact@ethanatkins.com>
Date: Sat, 5 Sep 2020 12:30:08 -0700
Subject: [PATCH] Add gc monitor to warn users about excessive gc

It is not uncommon in large projects for the jvm to silently be running
frequent full gcs in the background. This can slow progress to a crawl.
Usually the fix is to bump the -Xmx parameter but if the users do not
realize that their tasks are slow because of gc thrashing, they may not
think to do that. This PR adds a monitor that hooks into the jvm's event
notification system to keep track of how much time is spent in GC. If
the ratio of the amount of time in gc to the total elapsed time exceeds
some threshold, we emit a warning.

I was motivated to do this because publishLocal can take forever in the
zinc project because a 1G heap isn't big enough.
---
 main/src/main/scala/sbt/MainLoop.scala        |  2 +
 .../main/scala/sbt/internal/GCMonitor.scala   | 68 +++++++++++++++++++
 .../src/main/scala/sbt/internal/SysProp.scala | 15 ++++
 3 files changed, 85 insertions(+)
 create mode 100644 main/src/main/scala/sbt/internal/GCMonitor.scala

diff --git a/main/src/main/scala/sbt/MainLoop.scala b/main/src/main/scala/sbt/MainLoop.scala
index 62c7ff285..1adf3e0d2 100644
--- a/main/src/main/scala/sbt/MainLoop.scala
+++ b/main/src/main/scala/sbt/MainLoop.scala
@@ -153,6 +153,7 @@ object MainLoop {
     val superShellThreshold =
       state.get(Keys.superShellThreshold.key).getOrElse(SysProp.supershellThreshold)
     val taskProgress = new TaskProgress(superShellSleep, superShellThreshold)
+    val gcMonitor = if (SysProp.gcMonitor) Some(new sbt.internal.GCMonitor(state.log)) else None
     try {
       ErrorHandling.wideConvert {
         state
@@ -193,6 +194,7 @@ object MainLoop {
         state.log.error("\n")
         state.handleError(oom)
     } finally {
+      gcMonitor.foreach(_.close())
       context.close()
       taskProgress.close()
     }
diff --git a/main/src/main/scala/sbt/internal/GCMonitor.scala b/main/src/main/scala/sbt/internal/GCMonitor.scala
new file mode 100644
index 000000000..95437ee46
--- /dev/null
+++ b/main/src/main/scala/sbt/internal/GCMonitor.scala
@@ -0,0 +1,68 @@
+/*
+ * sbt
+ * Copyright 2011 - 2018, Lightbend, Inc.
+ * Copyright 2008 - 2010, Mark Harrah
+ * Licensed under Apache License 2.0 (see LICENSE)
+ */
+
+package sbt.internal
+
+import javax.management.{ Notification, 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 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] def handleNotification(
+      notification: Notification,
+      bean: GarbageCollectorMXBean,
+      info: (LinkedBlockingQueue[(Deadline, Long)], AtomicLong, AtomicReference[Deadline])
+  ): Unit = {
+    val (queue, lastCollectionTime, lastWarned) = info
+    val now = Deadline.now
+    val collectionTime = bean.getCollectionTime
+    val elapsed = collectionTime - lastCollectionTime.getAndSet(collectionTime)
+    queue.removeIf { case (d, _) => (d + window).isOverdue }
+    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(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 for better performance."
+      logger.warn(msg)
+    }
+  }
+
+  val removers = ManagementFactory.getGarbageCollectorMXBeans.asScala.flatMap {
+    case e: NotificationEmitter =>
+      val queue = new LinkedBlockingQueue[(Deadline, Long)]
+      val lastCollectionTime = new AtomicLong(0L)
+      val lastLogged = new AtomicReference(Deadline(0.millis))
+      val listener: NotificationListener =
+        (notification, queue) =>
+          queue match {
+            case (
+                q: LinkedBlockingQueue[(Deadline, Long)] @unchecked,
+                lct: AtomicLong,
+                ll: AtomicReference[Deadline] @unchecked
+                ) =>
+              handleNotification(notification, e, (q, lct, ll))
+            case _ =>
+          }
+      e.addNotificationListener(listener, null, (queue, lastCollectionTime, lastLogged))
+      Some(() => e.removeNotificationListener(listener))
+    case _ => None
+  }
+  override def close(): Unit = {
+    removers.foreach(_.apply())
+  }
+}
diff --git a/main/src/main/scala/sbt/internal/SysProp.scala b/main/src/main/scala/sbt/internal/SysProp.scala
index 2f4e95953..51d7a1d6e 100644
--- a/main/src/main/scala/sbt/internal/SysProp.scala
+++ b/main/src/main/scala/sbt/internal/SysProp.scala
@@ -60,6 +60,17 @@ object SysProp {
       case _ => default
     }
 
+  def double(name: String, default: Double): Double =
+    sys.props.get(name) match {
+      case Some(str) =>
+        try {
+          str.toDouble
+        } catch {
+          case NonFatal(_) => default
+        }
+      case _ => default
+    }
+
   // System property style:
   //   1. use sbt. prefix
   //   2. prefer short nouns
@@ -137,6 +148,10 @@ object SysProp {
         ("ms", 6)
     }
 
+  def gcMonitor: Boolean = getOrTrue("sbt.gc.monitor")
+  def gcWindow: FiniteDuration = int("sbt.gc.monitor.window", 10).seconds
+  def gcRatio: Double = double("sbt.gc.monitor.ratio", 0.5)
+
   /** Generate build.properties if missing. */
   def genBuildProps: Boolean =
     booleanOpt("sbt.genbuildprops") match {