Merge pull request #3384 from mtomko/starvation-clock

Starvation clock timestamp

Author: djspiewak

core/js/src/main/scala/cats/effect/CpuStarvationCheckPlatform.scala

@@ -0,0 +1,27 @@
+/*
+ * Copyright 2020-2022 Typelevel
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package cats.effect
+
+import scala.concurrent.duration.FiniteDuration
+import scala.scalajs.js
+
+private[effect] abstract class CpuStarvationCheckPlatform { this: CpuStarvationCheck.type =>
+
+  def format(when: FiniteDuration): String =
+    new js.Date(when.toMillis.toDouble).toISOString()
+
+}

core/jvm-native/src/main/scala/cats/effect/CpuStarvationCheckPlatform.scala

@@ -0,0 +1,29 @@
+/*
+ * Copyright 2020-2022 Typelevel
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package cats.effect
+
+import scala.concurrent.duration.FiniteDuration
+
+import java.time.Instant
+import java.time.format.DateTimeFormatter
+
+private[effect] abstract class CpuStarvationCheckPlatform { this: CpuStarvationCheck.type =>
+
+  def format(when: FiniteDuration): String =
+    DateTimeFormatter.ISO_INSTANT.format(Instant.ofEpochMilli(when.toMillis))
+
+}

core/shared/src/main/scala/cats/effect/CpuStarvationCheck.scala

@@ -22,35 +22,36 @@ import cats.effect.unsafe.IORuntimeConfig
 import cats.syntax.all._
 
 import scala.concurrent.duration.{Duration, FiniteDuration}
-
-private[effect] object CpuStarvationCheck {
+private[effect] object CpuStarvationCheck extends CpuStarvationCheckPlatform {
 
   def run(runtimeConfig: IORuntimeConfig, metrics: CpuStarvationMetrics): IO[Nothing] = {
     import runtimeConfig._
 
     val threshold = cpuStarvationCheckInterval * (1 + cpuStarvationCheckThreshold)
 
-    val warning = mkWarning(cpuStarvationCheckInterval * cpuStarvationCheckThreshold)
+    val warning: FiniteDuration => String =
+      mkWarning(cpuStarvationCheckInterval * cpuStarvationCheckThreshold)
 
     def go(initial: FiniteDuration): IO[Nothing] =
       IO.sleep(cpuStarvationCheckInterval) >> IO.monotonic.flatMap { now =>
         val delta = now - initial
 
         metrics.recordClockDrift(delta - cpuStarvationCheckInterval) >>
-          (Console[IO].errorln(warning) *> metrics.incCpuStarvationCount)
-            .whenA(delta >= threshold) >>
-          go(now)
+          IO.realTime
+            .flatMap(fd =>
+              (Console[IO].errorln(warning(fd)) *> metrics.incCpuStarvationCount)
+                .whenA(delta >= threshold)) >> go(now)
       }
 
     IO.monotonic.flatMap(go(_)).delayBy(cpuStarvationCheckInitialDelay)
   }
 
-  private[this] def mkWarning(threshold: Duration) =
-    s"""|[WARNING] Your app's responsiveness to a new asynchronous event (such as a
-        |new connection, an upstream response, or a timer) was in excess of $threshold.
-        |Your CPU is probably starving. Consider increasing the granularity
-        |of your delays or adding more cedes. This may also be a sign that you are
-        |unintentionally running blocking I/O operations (such as File or InetAddress)
+  private[this] def mkWarning(threshold: Duration)(when: FiniteDuration) =
+    s"""|${format(when)} [WARNING] Your app's responsiveness to a new asynchronous 
+        |event (such as a new connection, an upstream response, or a timer) was in excess
+        |of $threshold. Your CPU is probably starving. Consider increasing the 
+        |granularity of your delays or adding more cedes. This may also be a sign that you
+        |are unintentionally running blocking I/O operations (such as File or InetAddress)
         |without the blocking combinator.""".stripMargin
 
 }

docs/core/starvation-and-tuning.md

@@ -3,12 +3,14 @@ id: starvation-and-tuning
 title: Starvation and Tuning
 ---
 
-All Cats Effect applications constructed via `IOApp` have an automatic mechanism which periodically checks to see if the application runtime is starving for compute resources. If you ever see warnings which look like the following, they are the result of this mechanism automatically detecting that the responsiveness of your application runtime is below the configured threshold.
+All Cats Effect applications constructed via `IOApp` have an automatic mechanism which periodically checks to see if the application runtime is starving for compute resources. If you ever see warnings which look like the following, they are the result of this mechanism automatically detecting that the responsiveness of your application runtime is below the configured threshold. Note that the timestamp is the time when the starvation was detected, which is not precisely the time when starvation (or the task that is responsible) began.
 
 ```
-[WARNING] Your CPU is probably starving. Consider increasing the granularity
-of your delays or adding more cedes. This may also be a sign that you are
-unintentionally running blocking I/O operations (such as File or InetAddress)
+2023-01-28T00:16:24.101Z [WARNING] Your app's responsiveness to a new asynchronous 
+event (such as a new connection, an upstream response, or a timer) was in excess
+of 40 milliseconds. Your CPU is probably starving. Consider increasing the 
+granularity of your delays or adding more cedes. This may also be a sign that you
+are unintentionally running blocking I/O operations (such as File or InetAddress)
 without the blocking combinator.
 ```
 

docs/faq.md

@@ -74,9 +74,11 @@ Note that this is just a specific example to demonstrate why running an non-bloc
 Cats Effect 3.4.0 introduced a default-enabled *starvation checker*, which produces warnings like the following:
 
 ```
-[WARNING] Your CPU is probably starving. Consider increasing the granularity
-of your delays or adding more cedes. This may also be a sign that you are
-unintentionally running blocking I/O operations (such as File or InetAddress)
+2023-01-28T00:16:24.101Z [WARNING] Your app's responsiveness to a new asynchronous 
+event (such as a new connection, an upstream response, or a timer) was in excess
+of 40 milliseconds. Your CPU is probably starving. Consider increasing the 
+granularity of your delays or adding more cedes. This may also be a sign that you
+are unintentionally running blocking I/O operations (such as File or InetAddress)
 without the blocking combinator.
 ```
 

tests/jvm/src/test/scala/cats/effect/IOAppSpec.scala

@@ -201,6 +201,12 @@ class IOAppSpec extends Specification {
           val err = h.stderr()
           err must not(contain("[WARNING] Failed to register Cats Effect CPU"))
           err must contain("[WARNING] Your app's responsiveness")
+          // we use a regex because time has too many corner cases - a test run at just the wrong
+          // moment on new year's eve, etc
+          err must beMatching(
+            // (?s) allows matching across line breaks
+            """(?s)^\d{4}-[01]\d-[0-3]\dT[012]\d:[0-6]\d:[0-6]\d(?:\.\d{1,3})?Z \[WARNING\] Your app's responsiveness.*"""
+          )
         }
 
         "custom runtime installed as global" in {