parent
846c4f3656
commit
26f6c34b7a
4 changed files with 361 additions and 2 deletions
@ -0,0 +1,212 @@ |
||||
#!/usr/bin/env bash |
||||
|
||||
# Collect low-frequency host and process metrics while preserving the observed |
||||
# command's stdout, stderr, and exit status. |
||||
|
||||
set -u |
||||
|
||||
if [[ $# -lt 3 ]]; then |
||||
echo "Usage: $0 <output-directory> -- <command> [arguments ...]" >&2 |
||||
exit 2 |
||||
fi |
||||
if [[ $2 != "--" ]]; then |
||||
echo "Usage: $0 <output-directory> -- <command> [arguments ...]" >&2 |
||||
exit 2 |
||||
fi |
||||
|
||||
output_dir=$1 |
||||
shift 2 |
||||
mkdir -p "${output_dir}" |
||||
|
||||
metadata_file="${output_dir}/environment.txt" |
||||
samples_file="${output_dir}/resources.log" |
||||
processes_file="${output_dir}/processes.log" |
||||
memory_maps_file="${output_dir}/tpc-memory.log" |
||||
time_file="${output_dir}/command-time.txt" |
||||
disk_file="${output_dir}/disk-usage.txt" |
||||
|
||||
cgroup_dir=/sys/fs/cgroup |
||||
if [[ -r /proc/self/cgroup ]]; then |
||||
cgroup_v2_path=$(awk -F: '$1 == "0" { print $3; exit }' /proc/self/cgroup) |
||||
if [[ -n ${cgroup_v2_path} && -d /sys/fs/cgroup${cgroup_v2_path} ]]; then |
||||
cgroup_dir=/sys/fs/cgroup${cgroup_v2_path} |
||||
fi |
||||
fi |
||||
|
||||
write_environment() { |
||||
{ |
||||
echo "timestamp_utc=$(date -u +%Y-%m-%dT%H:%M:%SZ)" |
||||
echo "runner_image=${ImageOS:-unknown}" |
||||
echo "runner_image_version=${ImageVersion:-unknown}" |
||||
echo "runner_arch=${RUNNER_ARCH:-unknown}" |
||||
echo "workspace=${GITHUB_WORKSPACE:-$PWD}" |
||||
echo |
||||
uname -a |
||||
echo |
||||
lscpu |
||||
echo |
||||
free -b |
||||
echo |
||||
df -B1 -T . /tmp |
||||
echo |
||||
ulimit -a |
||||
echo |
||||
cat /proc/self/cgroup |
||||
echo |
||||
echo "cgroup_directory=${cgroup_dir}" |
||||
for source in \ |
||||
"${cgroup_dir}/cpu.max" \ |
||||
"${cgroup_dir}/cpuset.cpus.effective" \ |
||||
"${cgroup_dir}/memory.max" \ |
||||
"${cgroup_dir}/memory.swap.max" \ |
||||
"${cgroup_dir}/pids.max"; do |
||||
if [[ -r ${source} ]]; then |
||||
echo "${source}=$(cat "${source}")" |
||||
fi |
||||
done |
||||
echo |
||||
sed -n -E '/^(MemTotal|MemFree|MemAvailable|Buffers|Cached|SwapCached|SwapTotal|SwapFree|Dirty|Writeback|AnonPages|Mapped|Slab|SReclaimable|PageTables):/p' /proc/meminfo |
||||
} >"${metadata_file}" 2>&1 |
||||
} |
||||
|
||||
write_binary_details() { |
||||
local binary=${TYPEPHP_OBSERVED_BINARY:-./tpc} |
||||
local details_file="${output_dir}/binary.txt" |
||||
|
||||
{ |
||||
echo "path=${binary}" |
||||
stat "${binary}" |
||||
echo |
||||
file "${binary}" |
||||
echo |
||||
size -A "${binary}" |
||||
echo |
||||
readelf -lW "${binary}" |
||||
echo |
||||
ldd "${binary}" |
||||
} >"${details_file}" 2>&1 || true |
||||
} |
||||
|
||||
write_resource_sample() { |
||||
local label=$1 |
||||
local source |
||||
|
||||
{ |
||||
echo "===== ${label} $(date -u +%Y-%m-%dT%H:%M:%SZ) =====" |
||||
echo "loadavg=$(cat /proc/loadavg)" |
||||
sed -n '1p' /proc/stat |
||||
free -b |
||||
df -B1 . /tmp |
||||
|
||||
for source in /proc/pressure/cpu /proc/pressure/memory /proc/pressure/io; do |
||||
if [[ -r ${source} ]]; then |
||||
echo "--- ${source}" |
||||
cat "${source}" |
||||
fi |
||||
done |
||||
|
||||
echo "--- /proc/meminfo" |
||||
sed -n -E '/^(MemFree|MemAvailable|Buffers|Cached|SwapCached|SwapFree|Dirty|Writeback|AnonPages|Mapped|Slab|SReclaimable|PageTables):/p' /proc/meminfo |
||||
|
||||
echo "--- /proc/vmstat" |
||||
sed -n -E '/^(pgfault|pgmajfault|pswpin|pswpout|pgscan_[^ ]+|pgsteal_[^ ]+|workingset_refault_[^ ]+|nr_dirty|nr_writeback) /p' /proc/vmstat |
||||
|
||||
for source in \ |
||||
"${cgroup_dir}/cpu.stat" \ |
||||
"${cgroup_dir}/cpu.pressure" \ |
||||
"${cgroup_dir}/memory.current" \ |
||||
"${cgroup_dir}/memory.peak" \ |
||||
"${cgroup_dir}/memory.events" \ |
||||
"${cgroup_dir}/memory.pressure" \ |
||||
"${cgroup_dir}/io.stat" \ |
||||
"${cgroup_dir}/io.pressure"; do |
||||
if [[ -r ${source} ]]; then |
||||
echo "--- ${source}" |
||||
cat "${source}" |
||||
fi |
||||
done |
||||
} >>"${samples_file}" 2>&1 |
||||
|
||||
{ |
||||
echo "===== ${label} $(date -u +%Y-%m-%dT%H:%M:%SZ) =====" |
||||
ps -eo pid,ppid,etimes,pcpu,pmem,rss,vsz,min_flt,maj_flt,stat,comm --sort=-rss | head -n 31 |
||||
} >>"${processes_file}" 2>&1 |
||||
} |
||||
|
||||
write_tpc_memory_sample() { |
||||
local label=$1 |
||||
local pid |
||||
|
||||
{ |
||||
echo "===== ${label} $(date -u +%Y-%m-%dT%H:%M:%SZ) =====" |
||||
while read -r pid; do |
||||
[[ -n ${pid} ]] || continue |
||||
echo "--- pid=${pid}" |
||||
sed -n -E '/^(Name|Pid|PPid|VmPeak|VmSize|VmRSS|RssAnon|RssFile|RssShmem|VmSwap):/p' "/proc/${pid}/status" 2>/dev/null || true |
||||
sed -n -E '/^(Rss|Pss|Pss_Dirty|Shared_Clean|Shared_Dirty|Private_Clean|Private_Dirty|Anonymous|Swap):/p' "/proc/${pid}/smaps_rollup" 2>/dev/null || true |
||||
done < <(pgrep -x tpc 2>/dev/null || true) |
||||
} >>"${memory_maps_file}" 2>&1 |
||||
} |
||||
|
||||
write_disk_usage() { |
||||
local label=$1 |
||||
|
||||
{ |
||||
echo "===== ${label} $(date -u +%Y-%m-%dT%H:%M:%SZ) =====" |
||||
if [[ -e ./tpc ]]; then |
||||
stat --format='tpc bytes=%s blocks=%b block_size=%B' ./tpc |
||||
fi |
||||
df -B1 -T . /tmp |
||||
} >>"${disk_file}" 2>&1 |
||||
} |
||||
|
||||
observed_pid='' |
||||
interrupted=0 |
||||
|
||||
forward_signal() { |
||||
interrupted=1 |
||||
if [[ -n ${observed_pid} ]]; then |
||||
kill -TERM "${observed_pid}" 2>/dev/null || true |
||||
fi |
||||
} |
||||
|
||||
trap forward_signal INT TERM |
||||
|
||||
write_environment |
||||
write_binary_details |
||||
write_disk_usage before |
||||
write_resource_sample before |
||||
|
||||
/usr/bin/time -v -o "${time_file}" -- "$@" & |
||||
observed_pid=$! |
||||
|
||||
# Poll once per second so completion is delayed by at most one second. The |
||||
# expensive snapshot is taken only once every 20 seconds. |
||||
sample_count=0 |
||||
while kill -0 "${observed_pid}" 2>/dev/null; do |
||||
sleep 1 |
||||
sample_count=$((sample_count + 1)) |
||||
if ((sample_count % 20 == 0)) && kill -0 "${observed_pid}" 2>/dev/null; then |
||||
write_resource_sample "sample-${sample_count}s" |
||||
fi |
||||
if ((sample_count % 60 == 0)) && kill -0 "${observed_pid}" 2>/dev/null; then |
||||
write_tpc_memory_sample "sample-${sample_count}s" |
||||
fi |
||||
done |
||||
|
||||
wait "${observed_pid}" |
||||
status=$? |
||||
observed_pid='' |
||||
|
||||
write_resource_sample after |
||||
write_disk_usage after |
||||
|
||||
echo "Observed command resource summary:" |
||||
cat "${time_file}" |
||||
echo "Detailed samples: ${output_dir}" |
||||
|
||||
if ((interrupted != 0)) && ((status == 0)); then |
||||
status=143 |
||||
fi |
||||
|
||||
exit "${status}" |
||||
@ -0,0 +1,14 @@ |
||||
#!/usr/bin/env bash |
||||
|
||||
# Keep per-invocation compiler metrics separate from the compiler's output so |
||||
# run-tests.php sees exactly the same stdout, stderr, and exit status. |
||||
|
||||
set -u |
||||
|
||||
script_dir=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd) |
||||
project_dir=$(cd "${script_dir}/../.." && pwd) |
||||
metrics_file=${TYPEPHP_TPC_METRICS_FILE:-${project_dir}/build/phpt-metrics/tpc-invocations.tsv} |
||||
|
||||
exec /usr/bin/time -q -a -o "${metrics_file}" \ |
||||
-f $'%x\t%e\t%U\t%S\t%P\t%M\t%F\t%R\t%I\t%O\t%c\t%w\t%C' \ |
||||
"${project_dir}/tpc" "$@" |
||||
@ -0,0 +1,111 @@ |
||||
#!/usr/bin/env python3 |
||||
|
||||
"""Summarize the append-only GNU time records produced by observe-tpc.sh.""" |
||||
|
||||
from __future__ import annotations |
||||
|
||||
import csv |
||||
import math |
||||
import pathlib |
||||
import statistics |
||||
import sys |
||||
|
||||
|
||||
COLUMNS = ( |
||||
"exit", |
||||
"wall_seconds", |
||||
"user_seconds", |
||||
"system_seconds", |
||||
"cpu_percent", |
||||
"max_rss_kb", |
||||
"major_faults", |
||||
"minor_faults", |
||||
"filesystem_inputs", |
||||
"filesystem_outputs", |
||||
"involuntary_context_switches", |
||||
"voluntary_context_switches", |
||||
"command", |
||||
) |
||||
|
||||
|
||||
def percentile(values: list[float], fraction: float) -> float: |
||||
ordered = sorted(values) |
||||
if not ordered: |
||||
return 0.0 |
||||
index = max(0, math.ceil(len(ordered) * fraction) - 1) |
||||
return ordered[index] |
||||
|
||||
|
||||
def main() -> int: |
||||
if len(sys.argv) != 2: |
||||
print(f"Usage: {sys.argv[0]} <tpc-invocations.tsv>", file=sys.stderr) |
||||
return 2 |
||||
|
||||
metrics_path = pathlib.Path(sys.argv[1]) |
||||
if not metrics_path.is_file(): |
||||
print(f"No compiler invocation metrics found at {metrics_path}") |
||||
return 0 |
||||
|
||||
records: list[dict[str, str]] = [] |
||||
malformed = 0 |
||||
with metrics_path.open(newline="", encoding="utf-8", errors="replace") as stream: |
||||
for row in csv.reader(stream, delimiter="\t"): |
||||
if len(row) < len(COLUMNS): |
||||
malformed += 1 |
||||
continue |
||||
if len(row) > len(COLUMNS): |
||||
row = row[: len(COLUMNS) - 1] + ["\t".join(row[len(COLUMNS) - 1 :])] |
||||
records.append(dict(zip(COLUMNS, row))) |
||||
|
||||
if not records: |
||||
print(f"No complete compiler invocation records found (malformed={malformed})") |
||||
return 0 |
||||
|
||||
wall = [float(record["wall_seconds"]) for record in records] |
||||
user = [float(record["user_seconds"]) for record in records] |
||||
system = [float(record["system_seconds"]) for record in records] |
||||
rss = [int(record["max_rss_kb"]) for record in records] |
||||
major_faults = [int(record["major_faults"]) for record in records] |
||||
minor_faults = [int(record["minor_faults"]) for record in records] |
||||
fs_inputs = [int(record["filesystem_inputs"]) for record in records] |
||||
fs_outputs = [int(record["filesystem_outputs"]) for record in records] |
||||
involuntary_switches = [int(record["involuntary_context_switches"]) for record in records] |
||||
voluntary_switches = [int(record["voluntary_context_switches"]) for record in records] |
||||
failed = sum(record["exit"] != "0" for record in records) |
||||
|
||||
print("Per-invocation tpc metrics") |
||||
print(f" invocations: {len(records)}") |
||||
print(f" failed: {failed}") |
||||
print(f" malformed records: {malformed}") |
||||
print(f" cumulative wall time: {sum(wall):.2f} s") |
||||
print(f" cumulative user time: {sum(user):.2f} s") |
||||
print(f" cumulative system time: {sum(system):.2f} s") |
||||
print(f" wall mean: {statistics.fmean(wall):.3f} s") |
||||
print(f" wall p50: {percentile(wall, 0.50):.3f} s") |
||||
print(f" wall p90: {percentile(wall, 0.90):.3f} s") |
||||
print(f" wall p95: {percentile(wall, 0.95):.3f} s") |
||||
print(f" wall p99: {percentile(wall, 0.99):.3f} s") |
||||
print(f" wall max: {max(wall):.3f} s") |
||||
print(f" max RSS: {max(rss)} KiB") |
||||
print(f" major page faults: {sum(major_faults)}") |
||||
print(f" minor page faults: {sum(minor_faults)}") |
||||
print(f" filesystem inputs: {sum(fs_inputs)}") |
||||
print(f" filesystem outputs: {sum(fs_outputs)}") |
||||
print(f" involuntary context switches: {sum(involuntary_switches)}") |
||||
print(f" voluntary context switches: {sum(voluntary_switches)}") |
||||
|
||||
print(" slowest invocations:") |
||||
for record in sorted(records, key=lambda item: float(item["wall_seconds"]), reverse=True)[:10]: |
||||
print( |
||||
" " |
||||
f"{float(record['wall_seconds']):.3f} s, " |
||||
f"RSS {int(record['max_rss_kb'])} KiB, " |
||||
f"major/minor faults {record['major_faults']}/{record['minor_faults']}: " |
||||
f"{record['command']}" |
||||
) |
||||
|
||||
return 0 |
||||
|
||||
|
||||
if __name__ == "__main__": |
||||
raise SystemExit(main()) |
||||
Loading…
Reference in new issue