Periodically Log JVM Memory and GC Usage

Closes: #3522

Author: alexanderkiel

.github/scripts/check-jvm-metrics-log.sh

@@ -0,0 +1,11 @@
+#!/bin/bash
+set -euo pipefail
+
+script_dir="$(dirname "$(readlink -f "$0")")"
+. "$script_dir/util.sh"
+
+compose_file="$1"
+
+log_line="$(docker compose -f "$compose_file" logs | grep "Heap:" | head -1)"
+
+test_non_empty "JVM metrics log line" "$log_line"

.github/workflows/build.yml

@@ -1577,6 +1577,9 @@ jobs:
       run: curl -sf http://localhost:8082/metrics
       if: ${{ matrix.variant == 'distributed' }}
 
+    - name: Check JVM Metrics Log
+      run: .github/scripts/check-jvm-metrics-log.sh .github/${{ matrix.variant }}-test/docker-compose.yml
+
     - name: Docker Stats
       run: docker stats --no-stream
       if: always()

AGENTS.md

@@ -42,6 +42,10 @@ Rigorous adherence to these patterns is required:
     * Require `[blaze.test-util :as tu]`.
     * Call `(test/use-fixtures :each tu/fixture)`.
 
+## Documentation
+
+* **Environment Variables:** Every new environment variable introduced via `#blaze/cfg` in `resources/blaze.edn` must be documented in `docs/deployment/environment-variables.md`, following the existing format (heading, description, default value, since badge).
+
 ## Verification & Workflow
 
 When starting to work on an issue, you can use the GitHub CLI to fetch the issue details: `gh issue view <issue-number>`
@@ -51,7 +55,7 @@ Before finishing a task, ensure the following commands pass:
 1.  **Format:** `make fmt`
 2.  **Lint:** `make lint` (Uses `clj-kondo`)
 3.  **Test:** `make test` (Runs module and root tests)
-4.  **Coverage:** `make test-coverage` (Checks for adequate test coverage)
+4.  **Coverage:** `make test-coverage` (Checks for adequate test coverage — must be **≥ 95% forms**)
 
 After verification, when working on an issue:
 

deps.edn

@@ -16,6 +16,9 @@
   blaze/interaction
   {:local/root "modules/interaction"}
 
+  blaze/jvm-metrics-logger
+  {:local/root "modules/jvm-metrics-logger"}
+
   blaze/openid-auth
   {:local/root "modules/openid-auth"}
 

docs/deployment/environment-variables.md

@@ -358,6 +358,24 @@ one of trace, debug, info, warn or error
 
 **Default:** info
 
+#### `JVM_METRICS_LOGGER_NORMAL_INTERVAL` <Badge type="warning" text="Since 1.7"/>
+
+The interval at which JVM heap, non-heap, and GC metrics are logged at INFO level during normal operation (heap below the warn threshold). Must be an ISO-8601 duration string.
+
+**Default:** PT5M
+
+#### `JVM_METRICS_LOGGER_WARN_INTERVAL` <Badge type="warning" text="Since 1.7"/>
+
+The interval at which JVM heap, non-heap, and GC metrics are logged at WARN level when heap usage is at or above the warn threshold. Must be an ISO-8601 duration string.
+
+**Default:** PT1M
+
+#### `JVM_METRICS_LOGGER_WARN_THRESHOLD` <Badge type="warning" text="Since 1.7"/>
+
+The heap usage percentage (1–99) at or above which metrics are logged at WARN level and at the shorter warn interval.
+
+**Default:** 80
+
 #### `JAVA_TOOL_OPTIONS`
 
 | Name                      | Default | Since | Description                                                  |

modules/jvm-metrics-logger/Makefile

@@ -0,0 +1,32 @@
+fmt:
+	cljfmt check src test deps.edn tests.edn
+
+lint:
+	clj-kondo --lint src test deps.edn
+
+prep:
+	$(MAKE) -C ../module-base prep
+	clojure -X:deps prep
+
+test: prep
+	clojure -M:test:kaocha --profile :ci
+
+test-coverage: prep
+	clojure -M:test:coverage
+
+deps-tree:
+	clojure -X:deps tree
+
+deps-list:
+	clojure -X:deps list
+
+cloc-prod:
+	cloc src
+
+cloc-test:
+	cloc test
+
+clean:
+	rm -rf .clj-kondo/.cache .cpcache target
+
+.PHONY: fmt lint prep test test-coverage deps-tree deps-list cloc-prod cloc-test clean

modules/jvm-metrics-logger/deps.edn

@@ -0,0 +1,28 @@
+{:deps
+ {blaze/module-base
+  {:local/root "../module-base"}
+
+  blaze/scheduler
+  {:local/root "../scheduler"}}
+
+ :aliases
+ {:test
+  {:extra-paths ["test"]
+
+   :extra-deps
+   {blaze/module-test-util
+    {:local/root "../module-test-util"}}}
+
+  :kaocha
+  {:extra-deps
+   {lambdaisland/kaocha
+    {:mvn/version "1.91.1392"}}
+
+   :main-opts ["-m" "kaocha.runner"]}
+
+  :coverage
+  {:extra-deps
+   {lambdaisland/kaocha-cloverage
+    {:mvn/version "1.1.89"}}
+
+   :main-opts ["-m" "kaocha.runner" "--profile" "coverage"]}}}

modules/jvm-metrics-logger/src/blaze/jvm_metrics_logger.clj

@@ -0,0 +1,100 @@
+(ns blaze.jvm-metrics-logger
+  (:require
+   [blaze.module :as m]
+   [blaze.scheduler :as sched]
+   [blaze.scheduler.spec]
+   [clojure.spec.alpha :as s]
+   [clojure.string :as str]
+   [integrant.core :as ig]
+   [java-time.api :as time]
+   [taoensso.timbre :as log])
+  (:import
+   [java.lang.management GarbageCollectorMXBean ManagementFactory MemoryUsage]))
+
+(set! *warn-on-reflection* true)
+
+(s/def ::normal-interval time/duration?)
+
+(s/def ::warn-interval time/duration?)
+
+(s/def ::warn-threshold (s/and int? #(<= 1 % 99)))
+
+(defn- format-bytes [bytes]
+  (if (>= bytes 1073741824)
+    (format "%.1f GB" (/ bytes 1073741824.0))
+    (format "%.0f MB" (/ bytes 1048576.0))))
+
+(defn- heap-pct ^long [^MemoryUsage usage]
+  (let [max (.getMax usage)]
+    (if (pos? max)
+      (long (* 100 (/ (.getUsed usage) max)))
+      0)))
+
+(defn- format-gc [^GarbageCollectorMXBean gc]
+  (let [cnt (.getCollectionCount gc)
+        time-s (/ (.getCollectionTime gc) 1000.0)]
+    (format "%s %d %s %.1fs" (.getName gc) cnt
+            (if (= 1 cnt) "collection" "collections") time-s)))
+
+(defn heap-usage-string
+  "Returns a human-readable string summarising the current JVM heap, non-heap
+  and GC metrics. Exported as a public function to facilitate testing."
+  []
+  (let [heap     ^MemoryUsage (.getHeapMemoryUsage (ManagementFactory/getMemoryMXBean))
+        non-heap ^MemoryUsage (.getNonHeapMemoryUsage (ManagementFactory/getMemoryMXBean))
+        pct      (heap-pct heap)
+        gcs      (seq (ManagementFactory/getGarbageCollectorMXBeans))
+        gc-part  (when gcs (str ", GC: " (str/join ", " (map format-gc gcs))))]
+    (format "Heap: %s used / %s committed / %s max (%d%%), Non-Heap: %s used / %s committed%s"
+            (format-bytes (.getUsed heap))
+            (format-bytes (.getCommitted heap))
+            (format-bytes (.getMax heap))
+            pct
+            (format-bytes (.getUsed non-heap))
+            (format-bytes (.getCommitted non-heap))
+            (or gc-part ""))))
+
+(defn log-metrics!
+  "Reads current JVM metrics and logs them at the appropriate level based on
+  `warn-threshold` (percentage). Returns nil."
+  [warn-threshold]
+  (let [heap ^MemoryUsage (.getHeapMemoryUsage (ManagementFactory/getMemoryMXBean))
+        pct  (heap-pct heap)]
+    (if (>= pct warn-threshold)
+      (log/warn "High heap usage -" (heap-usage-string))
+      (log/info (heap-usage-string))))
+  nil)
+
+(defmethod m/pre-init-spec :blaze/jvm-metrics-logger [_]
+  (s/keys :req-un [:blaze/scheduler]
+          :opt-un [::normal-interval ::warn-interval ::warn-threshold]))
+
+(defmethod ig/init-key :blaze/jvm-metrics-logger
+  [_ {:keys [scheduler normal-interval warn-interval warn-threshold]
+      :or {normal-interval (time/minutes 5)
+           warn-interval (time/minutes 1)
+           warn-threshold 80}}]
+  (log/info "Start JVM metrics logger")
+  (let [normal-nanos  (time/as normal-interval :nanos)
+        last-info-log (atom 0)]
+    {:future
+     (sched/schedule-at-fixed-rate
+      scheduler
+      (fn []
+        (let [heap ^MemoryUsage (.getHeapMemoryUsage (ManagementFactory/getMemoryMXBean))
+              pct  (heap-pct heap)
+              now  (System/nanoTime)]
+          (cond
+            (>= pct warn-threshold)
+            (log-metrics! warn-threshold)
+
+            (>= (- now @last-info-log) normal-nanos)
+            (do (reset! last-info-log now)
+                (log-metrics! warn-threshold)))))
+      warn-interval
+      warn-interval)}))
+
+(defmethod ig/halt-key! :blaze/jvm-metrics-logger
+  [_ {:keys [future]}]
+  (log/info "Stop JVM metrics logger")
+  (sched/cancel future false))

modules/jvm-metrics-logger/test/blaze/jvm_metrics_logger_test.clj

@@ -0,0 +1,100 @@
+(ns blaze.jvm-metrics-logger-test
+  (:require
+   [blaze.jvm-metrics-logger :as jml]
+   [blaze.module-spec]
+   [blaze.module.test-util :refer [given-failed-system with-system]]
+   [blaze.scheduler.spec]
+   [blaze.test-util :as tu]
+   [clojure.spec.alpha :as s]
+   [clojure.spec.test.alpha :as st]
+   [clojure.test :as test :refer [deftest is testing]]
+   [integrant.core :as ig]
+   [java-time.api :as time]
+   [taoensso.timbre :as log]))
+
+(set! *warn-on-reflection* true)
+(st/instrument)
+(log/set-min-level! :trace)
+
+(test/use-fixtures :each tu/fixture)
+
+(def config
+  {:blaze/jvm-metrics-logger
+   {:scheduler (ig/ref :blaze/scheduler)
+    :normal-interval (time/seconds 5)
+    :warn-interval (time/seconds 1)
+    :warn-threshold 80}
+
+   :blaze/scheduler {}})
+
+(deftest init-test
+  (testing "nil config"
+    (given-failed-system {:blaze/jvm-metrics-logger nil}
+      :key := :blaze/jvm-metrics-logger
+      :reason := ::ig/build-failed-spec
+      [:cause-data ::s/problems 0 :pred] := `map?))
+
+  (testing "missing scheduler"
+    (given-failed-system {:blaze/jvm-metrics-logger {}}
+      :key := :blaze/jvm-metrics-logger
+      :reason := ::ig/build-failed-spec
+      [:cause-data ::s/problems 0 :pred] := `(fn ~'[%] (contains? ~'% :scheduler))))
+
+  (testing "invalid scheduler"
+    (given-failed-system (assoc-in config [:blaze/jvm-metrics-logger :scheduler] ::invalid)
+      :key := :blaze/jvm-metrics-logger
+      :reason := ::ig/build-failed-spec
+      [:cause-data ::s/problems 0 :via] := [:blaze/scheduler]
+      [:cause-data ::s/problems 0 :val] := ::invalid))
+
+  (testing "invalid warn-threshold"
+    (given-failed-system (assoc-in config [:blaze/jvm-metrics-logger :warn-threshold] 0)
+      :key := :blaze/jvm-metrics-logger
+      :reason := ::ig/build-failed-spec
+      [:cause-data ::s/problems 0 :via] := [::jml/warn-threshold]
+      [:cause-data ::s/problems 0 :val] := 0))
+
+  (testing "success"
+    (with-system [system config]
+      (is (some? (get system :blaze/jvm-metrics-logger))))))
+
+(deftest heap-usage-string-test
+  (testing "returns a string containing heap info"
+    (let [result (jml/heap-usage-string)]
+      (is (string? result))
+      (is (re-find #"Heap:" result))
+      (is (re-find #"Non-Heap:" result))
+      (is (re-find #"\d+%" result))))
+
+  (testing "includes GC info when collectors are present"
+    (let [result (jml/heap-usage-string)]
+      (is (re-find #"GC:" result)))))
+
+(deftest log-metrics-test
+  (testing "logs at info level when below threshold"
+    (is (nil? (jml/log-metrics! 100))))
+
+  (testing "logs at warn level when at or above threshold"
+    (is (nil? (jml/log-metrics! 0)))))
+
+(deftest scheduled-info-task-test
+  (testing "info task fires and logs without error when heap is below threshold"
+    (with-system [_ {:blaze/jvm-metrics-logger
+                     {:scheduler (ig/ref :blaze/scheduler)
+                      :normal-interval (time/millis 50)
+                      :warn-interval (time/millis 50)
+                      :warn-threshold 99}
+                     :blaze/scheduler {}}]
+      (Thread/sleep 200)
+      (is true))))
+
+(deftest scheduled-warn-task-test
+  (testing "warn task fires and logs without error when heap is above threshold"
+    (with-system [_ {:blaze/jvm-metrics-logger
+                     {:scheduler (ig/ref :blaze/scheduler)
+                      :normal-interval (time/seconds 60)
+                      :warn-interval (time/millis 50)
+                      :warn-threshold 1}
+                     :blaze/scheduler {}}]
+      (Thread/sleep 200)
+      (is true))))

modules/jvm-metrics-logger/tests.edn

@@ -0,0 +1,10 @@
+#kaocha/v1
+ #merge
+  [{}
+   #profile {:ci {:reporter kaocha.report/documentation
+                  :color? false}
+             :coverage {:plugins [:kaocha.plugin/cloverage]
+                        :cloverage/opts
+                        {:codecov? true}
+                        :reporter kaocha.report/documentation
+                        :color? false}}]