This is an automated email from the ASF dual-hosted git repository.
asf-gitbox-commits pushed a commit to branch UNOMI-979-scheduler-lock-lease
in repository https://gitbox.apache.org/repos/asf/unomi.git
The following commit(s) were added to refs/heads/UNOMI-979-scheduler-lock-lease
by this push:
new cb25ad27b UNOMI-979: Sample per-process CPU and disk I/O during
integration tests
cb25ad27b is described below
commit cb25ad27b07b34facb83cd5adff76b057855f7fb
Author: Serge Huber <[email protected]>
AuthorDate: Mon Aug 17 21:09:29 2026 +0200
UNOMI-979: Sample per-process CPU and disk I/O during integration tests
The integration tests take about 59 minutes on OpenSearch against 40 on
Elasticsearch, and the existing metrics could not explain it. They cover
memory
only: both engines showed ample heap headroom, no swap and no warnings, so
the
gap was clearly not memory. System load hinted at the answer - the *slower*
engine ran at a *lower* load, median 0.15 against 0.77 on a 2-vCPU runner -
but
system load alone cannot say whether a run is computing, blocked on disk, or
waiting on a remote call.
Adds six columns to memory-samples.tsv: karaf_cpu_pct, karaf_io_read_mb_s,
karaf_io_write_mb_s, search_cpu_pct, search_io_read_mb_s,
search_io_write_mb_s.
They are appended, so existing column positions are untouched and older
sample
files still summarize. The summary gains cpu.mean/peak per process, io.peak
per
process, cpu.idle.samples.pct, and cpu.warning.mostly.idle, which fires when
neither process uses meaningful CPU and I/O is negligible - the signature
of a
run whose time goes on waiting rather than work.
CPU is a true interval percentage, not ps(1)'s %cpu: that is an average
over the
whole process lifetime, so a JVM busy during startup reads as busy forever
and
is useless for spotting a stall. On Linux, which is what CI runs and the
only
place these numbers are compared between runs, it deltas /proc/<pid>/stat
between samples. macOS has no procfs and falls back to ps, which is not
comparable with a Linux sample; the code says so where it matters.
The sample interval drops from 30s to 10s. At 30s a single sample spans
several
integration tests, so a stall cannot be attributed to the test that caused
it.
To keep that from tripling the load the sampler puts on the machine it is
measuring, the search engine's memory, CPU and block I/O now come from ONE
docker stats call per sample rather than the two an obvious implementation
would
use.
Also fixes a pre-existing bug found while testing: it_memory_find_karaf_pid
used
pgrep, which exits non-zero when nothing matches, and under set -euo
pipefail
that aborted the whole sample. Since the sampler starts before Karaf does,
every
sample taken during startup was silently discarded - exactly the window
where
the search engine is booting and its resource use is most interesting.
Verified on macOS and in an ubuntu:24.04 container using mawk, as
ubuntu-latest
does. On Linux: 100.0% for a saturated process, 0.0% for an idle one, 0 for
a
dead pid, 94 MB/s for a real writer, correct summaries under mawk, and a
clean
start/stop cycle. Fault injection confirms a bug in this script cannot fail
a
build: a syntax error only warns, a broken helper still yields samples, a
hung
sampler is killed promptly by stop, and an unwritable directory, corrupt
cache
or absent docker CLI all degrade to zeros.
Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
---
build.sh | 8 +-
itests/lib/it-run-memory.sh | 184 +++++++++++++++++++++++++++++++++++++++++---
itests/sample-it-memory.sh | 9 ++-
3 files changed, 184 insertions(+), 17 deletions(-)
diff --git a/build.sh b/build.sh
index 6c93ecb71..408768e32 100755
--- a/build.sh
+++ b/build.sh
@@ -279,7 +279,9 @@ RESOLVER_DEBUG=false
KEEP_CONTAINER=false
IT_SEARCH_ENGINE_LOGS=false
IT_MEMORY_SAMPLER=true
-IT_MEMORY_INTERVAL=30
+# 10s, matching itests/sample-it-memory.sh: at 30s a single sample spans
several ITs, so a
+# stall cannot be attributed to the test that caused it.
+IT_MEMORY_INTERVAL=10
JAVADOC=false
NO_JAVADOC=false
LOG_FILE=""
@@ -328,7 +330,7 @@ EOF
echo -e " ${CYAN}--keep-container${NC} Keep search engine
container running after tests (for post-failure inspection)"
echo -e " ${CYAN}--search-engine-logs${NC} Stream search engine
Docker logs to the Maven console during integration tests"
echo -e " ${CYAN}--no-memory-sampler${NC} Disable JVM/system
memory sampling during integration tests"
- echo -e " ${CYAN}--memory-interval SEC${NC} Memory sample interval
in seconds (default: 30)"
+ echo -e " ${CYAN}--memory-interval SEC${NC} Memory sample interval
in seconds (default: 10)"
echo -e " ${CYAN}--javadoc${NC} Build and validate
Javadoc after install (doclint errors fail; public/protected tag gaps warn)"
echo -e " ${CYAN}--no-javadoc${NC} Skip
Javadoc/checkstyle validation (overrides --ci; use when another job already ran
it)"
echo -e " ${CYAN}--ci${NC} CI mode: no Karaf,
non-interactive, includes Javadoc"
@@ -373,7 +375,7 @@ EOF
echo " --keep-container Keep search engine container running
after tests (for post-failure inspection)"
echo " --search-engine-logs Stream search engine Docker logs to
the Maven console during integration tests"
echo " --no-memory-sampler Disable JVM/system memory sampling
during integration tests"
- echo " --memory-interval SEC Memory sample interval in seconds
(default: 30)"
+ echo " --memory-interval SEC Memory sample interval in seconds
(default: 10)"
echo " --javadoc Build and validate Javadoc after
install (doclint errors fail; public/protected tag gaps warn)"
echo " --no-javadoc Skip Javadoc/checkstyle validation
(overrides --ci; use when another job already ran it)"
echo " --ci CI mode: no Karaf, non-interactive,
includes Javadoc"
diff --git a/itests/lib/it-run-memory.sh b/itests/lib/it-run-memory.sh
index 1c8f43466..8c61cdd5b 100644
--- a/itests/lib/it-run-memory.sh
+++ b/itests/lib/it-run-memory.sh
@@ -27,7 +27,7 @@ IT_MEMORY_SAMPLER_LOG="memory-sampler.log"
IT_MEMORY_SAMPLER_CACHE="memory-sampler.cache"
IT_MEMORY_SWAP_PRESSURE_MB=2048
-IT_MEMORY_TSV_HEADER=$'timestamp_utc\tkaraf_pid\tkaraf_heap_used_mb\tkaraf_heap_max_mb\tkaraf_gct_s\tes_heap_used_mb\tes_heap_max_mb\tdocker_rss_mb\tsystem_mem_available_mb\tsystem_swap_used_mb\tsystem_load_1m'
+IT_MEMORY_TSV_HEADER=$'timestamp_utc\tkaraf_pid\tkaraf_heap_used_mb\tkaraf_heap_max_mb\tkaraf_gct_s\tes_heap_used_mb\tes_heap_max_mb\tdocker_rss_mb\tsystem_mem_available_mb\tsystem_swap_used_mb\tsystem_load_1m\tkaraf_cpu_pct\tkaraf_io_read_mb_s\tkaraf_io_write_mb_s\tsearch_cpu_pct\tsearch_io_read_mb_s\tsearch_io_write_mb_s'
_IT_MEMORY_OS=""
@@ -350,7 +350,12 @@ it_memory_parse_docker_mem_to_mb() {
}
it_memory_find_karaf_pid() {
- pgrep -f 'org.apache.karaf.main.Main' 2>/dev/null | head -1
+ # `|| true`: pgrep exits non-zero when nothing matches, and with `set -euo
pipefail` that
+ # aborted the whole sample. The sampler starts before Karaf does, so every
sample taken
+ # during startup was discarded -- exactly the window where the search
engine is booting and
+ # its resource use is most interesting. No match now yields an empty pid,
which the callers
+ # and the summarizer already treat as "no Karaf yet" (guarded by `if ($2+0
> 0)`).
+ pgrep -f 'org.apache.karaf.main.Main' 2>/dev/null | head -1 || true
}
it_memory_karaf_max_mb_cached() {
@@ -446,21 +451,139 @@ it_memory_search_engine_stats() {
echo -e "$(it_memory_mb_from_bytes
"${used_bytes:-0}")\t$(it_memory_mb_from_bytes "${max_bytes:-0}")"
}
-it_memory_docker_rss_mb() {
+# --- CPU and disk I/O sampling
-------------------------------------------------
+#
+# Added to answer "is the run CPU-bound, I/O-bound, or waiting?". The memory
columns alone
+# could not distinguish a busy run from an idle one blocked on a remote call,
which is exactly
+# the question raised by the Elasticsearch/OpenSearch IT duration gap: system
load was near
+# idle on the slower engine, so the extra time was spent waiting rather than
computing.
+#
+# CPU is measured as a TRUE INTERVAL PERCENTAGE, not ps(1)'s %cpu -- that is
an average over the
+# whole process lifetime, so a JVM that was busy at startup reads as busy
forever and the number
+# is useless for spotting a stall. On Linux -- which is what CI runs, and the
only place these
+# numbers are compared across runs -- we delta /proc/<pid>/stat between
samples for a true
+# interval figure. macOS has no procfs, so it falls back to ps(1)'s lifetime
average: good enough
+# to see that a process is alive and roughly how hard it has worked, but NOT
comparable with a
+# Linux sample and not to be read as "CPU right now". Everything here is
best-effort: a missing
+# file, a dead pid or an absent docker CLI yields 0 and never fails a run.
+
+# Stores "value timestamp" pairs so the next sample can compute a delta.
+_it_memory_counter_cache() {
+ local target_dir="$1" key="$2"
+ echo "$target_dir/.it-memory-counter-$key"
+}
+
+# Echoes the per-second rate between this reading and the previous one, or 0
on the first call.
+_it_memory_rate_per_sec() {
+ local target_dir="$1" key="$2" value="$3"
+ local cache prev_value prev_ts now delta_v delta_t
+ cache="$(_it_memory_counter_cache "$target_dir" "$key")"
+ now="$(date +%s)"
+
+ if [ -r "$cache" ]; then
+ read -r prev_value prev_ts < "$cache" 2>/dev/null || true
+ fi
+ printf '%s %s\n' "$value" "$now" > "$cache" 2>/dev/null || true
+
+ if [ -z "${prev_value:-}" ] || [ -z "${prev_ts:-}" ]; then
+ echo "0"
+ return
+ fi
+ delta_t=$((now - prev_ts))
+ [ "$delta_t" -le 0 ] && { echo "0"; return; }
+ delta_v="$(awk -v a="$value" -v b="$prev_value" 'BEGIN { d = a - b; print
(d > 0 ? d : 0) }')"
+ awk -v d="$delta_v" -v t="$delta_t" 'BEGIN { printf "%.2f", d / t }'
+}
+
+# Interval CPU% for a pid. >100 is legitimate on multi-core (sum across
threads).
+it_memory_process_cpu_pct() {
+ local target_dir="$1" pid="${2:-}"
+ local ticks hz cpu_s rate
+
+ if [ -z "$pid" ] || [ "$pid" = "0" ] || ! kill -0 "$pid" 2>/dev/null; then
+ echo "0"
+ return
+ fi
+
+ if it_memory_is_linux && [ -r "/proc/$pid/stat" ]; then
+ # Fields 14 (utime) and 15 (stime), in clock ticks. comm (field 2) is
parenthesised and
+ # may itself contain spaces AND parentheses, so split after the LAST
')' rather than the
+ # first: a process named e.g. "java (worker)" otherwise shifts every
subsequent index.
+ ticks="$(awk '{
+ i = length($0)
+ while (i > 0 && substr($0, i, 1) != ")") i--
+ n = split(substr($0, i + 2), f, " ")
+ if (n >= 13) print f[12] + f[13]; else print 0
+ }' "/proc/$pid/stat" 2>/dev/null)"
+ [ -z "$ticks" ] && { echo "0"; return; }
+ hz="$(getconf CLK_TCK 2>/dev/null || echo 100)"
+ cpu_s="$(awk -v t="$ticks" -v hz="$hz" 'BEGIN { printf "%.4f", t / hz
}')"
+ rate="$(_it_memory_rate_per_sec "$target_dir" "cpu-$pid" "$cpu_s")"
+ awk -v r="$rate" 'BEGIN { printf "%.1f", r * 100 }'
+ return
+ fi
+
+ # macOS / no procfs: lifetime average, better than nothing for a local run.
+ ps -o %cpu= -p "$pid" 2>/dev/null | tr -d ' ' | awk 'NF { printf "%.1f",
$1; found = 1 } END { if (!found) print 0 }'
+}
+
+# Interval disk read/write in MB/s for a pid (Linux only; /proc/<pid>/io).
+it_memory_process_io_mb_s() {
+ local target_dir="$1" pid="${2:-}"
+ local read_bytes write_bytes read_rate write_rate
+
+ if [ -z "$pid" ] || [ "$pid" = "0" ] || ! it_memory_is_linux || [ ! -r
"/proc/$pid/io" ]; then
+ echo -e "0\t0"
+ return
+ fi
+
+ read_bytes="$(awk '/^read_bytes:/ { print $2 }' "/proc/$pid/io"
2>/dev/null)"
+ write_bytes="$(awk '/^write_bytes:/ { print $2 }' "/proc/$pid/io"
2>/dev/null)"
+ read_rate="$(_it_memory_rate_per_sec "$target_dir" "ior-$pid"
"${read_bytes:-0}")"
+ write_rate="$(_it_memory_rate_per_sec "$target_dir" "iow-$pid"
"${write_bytes:-0}")"
+ awk -v r="$read_rate" -v w="$write_rate" 'BEGIN { printf "%.2f\t%.2f", r /
1048576, w / 1048576 }'
+}
+
+# One docker stats call per sample, returning RSS, CPU% and block I/O together.
+#
+# Deliberately a single invocation: `docker stats --no-stream` costs ~1s and
briefly loads the
+# daemon, and the sampler now runs 3x more often (10s rather than 30s). Two
calls per sample
+# would have meant six times the docker traffic of the original sampler,
perturbing the very
+# run being measured and tripling the exposure to a hung daemon. CPUPerc is
already an interval
+# measurement; BlockIO is cumulative and is deltaed here.
+#
+# Echoes: rss_mb \t cpu_pct \t io_read_mb_s \t io_write_mb_s
+it_memory_docker_sample() {
local target_dir="$1"
- local container rss
+ local container stats mem cpu blockio read_raw write_raw read_b write_b
read_rate write_rate
if ! command -v docker >/dev/null 2>&1; then
- echo "0"
+ echo -e "0\t0\t0\t0"
return
fi
container="$(it_memory_resolve_docker_container "$target_dir")"
- rss="$(docker stats --no-stream --format '{{.MemUsage}}' "$container"
2>/dev/null | head -1 | cut -d/ -f1 | tr -d ' ')"
+ stats="$(docker stats --no-stream --format
'{{.MemUsage}}|{{.CPUPerc}}|{{.BlockIO}}' "$container" 2>/dev/null | head -1)"
+ if [ -z "$stats" ]; then
+ echo -e "0\t0\t0\t0"
+ return
+ fi
+
+ mem="$(echo "$stats" | cut -d'|' -f1 | cut -d/ -f1 | tr -d ' ')"
+ cpu="$(echo "$stats" | cut -d'|' -f2 | tr -d ' %')"
+ blockio="$(echo "$stats" | cut -d'|' -f3)"
+ read_raw="$(echo "$blockio" | cut -d/ -f1 | tr -d ' ')"
+ write_raw="$(echo "$blockio" | cut -d/ -f2 | tr -d ' ')"
+ read_b="$(it_memory_parse_docker_mem_to_mb "$read_raw")"
+ write_b="$(it_memory_parse_docker_mem_to_mb "$write_raw")"
+ read_rate="$(_it_memory_rate_per_sec "$target_dir" "dior" "${read_b:-0}")"
+ write_rate="$(_it_memory_rate_per_sec "$target_dir" "diow"
"${write_b:-0}")"
- it_memory_parse_docker_mem_to_mb "$rss"
+ printf '%s\t%.1f\t%.2f\t%.2f\n' \
+ "$(it_memory_parse_docker_mem_to_mb "$mem")" "${cpu:-0}"
"${read_rate:-0}" "${write_rate:-0}"
}
+
it_memory_system_stats() {
local mem_available swap_used load_1m
@@ -482,13 +605,22 @@ it_memory_sample_once() {
es_line="$(it_memory_search_engine_stats "$port")"
sys_line="$(it_memory_system_stats)"
- printf '%s\t%s\t%s\t%s\t%s\t%s\n' \
+ # One docker call per sample; split into the RSS column (8) and the CPU/IO
columns (15-17).
+ local docker_line docker_rss docker_cpu_io
+ docker_line="$(it_memory_docker_sample "$target_dir")"
+ docker_rss="$(printf '%s' "$docker_line" | cut -f1)"
+ docker_cpu_io="$(printf '%s' "$docker_line" | cut -f2-4)"
+
+ printf '%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n' \
"$(date -u +%Y-%m-%dT%H:%M:%SZ)" \
"${karaf_pid:-0}" \
"$karaf_line" \
"$es_line" \
- "$(it_memory_docker_rss_mb "$target_dir")" \
- "$sys_line"
+ "${docker_rss:-0}" \
+ "$sys_line" \
+ "$(it_memory_process_cpu_pct "$target_dir" "$karaf_pid")" \
+ "$(it_memory_process_io_mb_s "$target_dir" "$karaf_pid")" \
+ "${docker_cpu_io:-$(printf '0\t0\t0')}"
}
it_memory_write_samples_header() {
@@ -508,7 +640,7 @@ it_memory_summarize_samples() {
awk -F'\t' -v summary="$summary_file" -v
swap_pressure_mb="$IT_MEMORY_SWAP_PRESSURE_MB" '
NR == 1 { next }
- NF < 11 { next }
+ NF < 11 { next } # pre-CPU/IO samples still summarize
{
samples++
if ($2+0 > 0) {
@@ -524,6 +656,18 @@ it_memory_summarize_samples() {
if ($11+0 > peak_load) peak_load = $11+0
if (samples == 1) first_swap = $10+0
last_swap = $10+0
+ # CPU / IO columns are absent in samples written before they were
added.
+ if (NF >= 17) {
+ cpu_samples++
+ karaf_cpu_sum += $12+0; if ($12+0 > peak_karaf_cpu)
peak_karaf_cpu = $12+0
+ search_cpu_sum += $15+0; if ($15+0 > peak_search_cpu)
peak_search_cpu = $15+0
+ io_sum += $13+0 + $14+0 + $16+0 + $17+0
+ if ($13+0 + $14+0 > peak_karaf_io) peak_karaf_io = $13+0 +
$14+0
+ if ($16+0 + $17+0 > peak_search_io) peak_search_io = $16+0 +
$17+0
+ # "Idle" = neither process using meaningful CPU: the signature
of a run that is
+ # waiting on latency rather than doing work.
+ if ($12+0 < 10 && $15+0 < 10) idle_samples++
+ }
}
END {
if (samples == 0) exit 1
@@ -541,6 +685,24 @@ it_memory_summarize_samples() {
printf("memory.min.system.mem.available.mb=%d\n", min_mem_avail+0)
>> summary
printf("memory.peak.system.swap.used.mb=%d\n", peak_swap+0) >>
summary
printf("memory.peak.system.load.1m=%.2f\n", peak_load+0) >> summary
+ if (cpu_samples > 0) {
+ printf("cpu.samples.count=%d\n", cpu_samples) >> summary
+ printf("cpu.mean.karaf.pct=%.1f\n", karaf_cpu_sum /
cpu_samples) >> summary
+ printf("cpu.peak.karaf.pct=%.1f\n", peak_karaf_cpu+0) >>
summary
+ printf("cpu.mean.search.pct=%.1f\n", search_cpu_sum /
cpu_samples) >> summary
+ printf("cpu.peak.search.pct=%.1f\n", peak_search_cpu+0) >>
summary
+ printf("cpu.idle.samples.pct=%d\n", idle_samples * 100 /
cpu_samples) >> summary
+ printf("io.peak.karaf.mb.s=%.2f\n", peak_karaf_io+0) >> summary
+ printf("io.peak.search.mb.s=%.2f\n", peak_search_io+0) >>
summary
+ printf("io.mean.total.mb.s=%.2f\n", io_sum / cpu_samples) >>
summary
+ # Mostly-idle CPU with negligible I/O means the run is
latency-bound: time is
+ # going on waiting (polls, refresh intervals, timeouts), not
on work.
+ if (idle_samples * 100 / cpu_samples >= 70 && io_sum /
cpu_samples < 5) {
+ printf("cpu.warning.mostly.idle=true\n") >> summary
+ } else {
+ printf("cpu.warning.mostly.idle=false\n") >> summary
+ }
+ }
printf("memory.karaf.headroom.pct=%d\n", karaf_headroom+0) >>
summary
printf("memory.search.headroom.pct=%d\n", es_headroom+0) >> summary
if (swap_pressure) {
diff --git a/itests/sample-it-memory.sh b/itests/sample-it-memory.sh
index 19e0d5d5c..e0469bd02 100755
--- a/itests/sample-it-memory.sh
+++ b/itests/sample-it-memory.sh
@@ -39,7 +39,10 @@ source "$SCRIPT_DIR/lib/it-run.sh"
source "$SCRIPT_DIR/lib/it-run-memory.sh"
TARGET_DIR="$SCRIPT_DIR/target"
-INTERVAL=30
+# 10s, down from 30s: at 30s a sample covers several ITs at once, so a stall
cannot be
+# attributed to the test that caused it. Each sample is a few cheap reads plus
one
+# `docker stats --no-stream`, and a 50-minute run produces ~300 rows (a few
tens of KB).
+INTERVAL=10
SEARCH_PORT=""
PRINT_ONLY=false
COMMAND=""
@@ -58,7 +61,7 @@ Commands:
Options:
--target-dir DIR IT target directory (default: itests/target)
- --interval SEC Sample interval in seconds for start (default: 30)
+ --interval SEC Sample interval in seconds for start (default: 10)
--port PORT Search engine HTTP port override
--print-only With operator-note: print to stdout instead of writing
file
-h, --help Show this help
@@ -78,7 +81,7 @@ parse_args() {
;;
--interval)
shift
- INTERVAL="${1:-30}"
+ INTERVAL="${1:-10}"
;;
--port)
shift
