From 26f6c34b7a71ab6bd9a5e2e88be8764785ebb247 Mon Sep 17 00:00:00 2001 From: tianfenghan Date: Mon, 21 Sep 2026 17:20:53 +0800 Subject: [PATCH] ci: collect PHPT performance metrics --- .github/scripts/observe-command.sh | 212 +++++++++++++++++++++++ .github/scripts/observe-tpc.sh | 14 ++ .github/scripts/summarize-tpc-metrics.py | 111 ++++++++++++ .github/workflows/linux-x64.yml | 26 ++- 4 files changed, 361 insertions(+), 2 deletions(-) create mode 100755 .github/scripts/observe-command.sh create mode 100755 .github/scripts/observe-tpc.sh create mode 100755 .github/scripts/summarize-tpc-metrics.py diff --git a/.github/scripts/observe-command.sh b/.github/scripts/observe-command.sh new file mode 100755 index 00000000..f307a69c --- /dev/null +++ b/.github/scripts/observe-command.sh @@ -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 -- [arguments ...]" >&2 + exit 2 +fi +if [[ $2 != "--" ]]; then + echo "Usage: $0 -- [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}" diff --git a/.github/scripts/observe-tpc.sh b/.github/scripts/observe-tpc.sh new file mode 100755 index 00000000..d3d25e1d --- /dev/null +++ b/.github/scripts/observe-tpc.sh @@ -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" "$@" diff --git a/.github/scripts/summarize-tpc-metrics.py b/.github/scripts/summarize-tpc-metrics.py new file mode 100755 index 00000000..c1e5ffe6 --- /dev/null +++ b/.github/scripts/summarize-tpc-metrics.py @@ -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]} ", 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()) diff --git a/.github/workflows/linux-x64.yml b/.github/workflows/linux-x64.yml index 7df7e588..47726eeb 100644 --- a/.github/workflows/linux-x64.yml +++ b/.github/workflows/linux-x64.yml @@ -481,11 +481,33 @@ jobs: c++ --version - name: Run compiler PHPT suite with bootstrap compiler + shell: bash + env: + TYPEPHP_OBSERVED_BINARY: ./tpc + TYPEPHP_TPC_METRICS_FILE: ${{ github.workspace }}/build/phpt-metrics/tpc-invocations.tsv run: | - mkdir -p build - php run-tests.php -q -j8 --compiler ./tpc \ + mkdir -p build/phpt-metrics + .github/scripts/observe-command.sh build/phpt-metrics -- \ + php run-tests.php -q -j8 --compiler .github/scripts/observe-tpc.sh \ -w build/failed-tests.txt -W build/test-results.txt tests/compiler + - name: Summarize PHPT compiler metrics + if: always() + shell: bash + run: | + python3 .github/scripts/summarize-tpc-metrics.py \ + build/phpt-metrics/tpc-invocations.tsv \ + | tee build/phpt-metrics/tpc-invocations-summary.txt + + - name: Upload PHPT performance metrics + if: always() + uses: actions/upload-artifact@v4 + with: + name: phpt-metrics-linux-x64-php-${{ matrix.php }}-zts + if-no-files-found: warn + retention-days: 14 + path: build/phpt-metrics + - name: Package tested Linux compiler if: startsWith(github.ref, 'refs/tags/') && matrix.php == '8.5' shell: bash