Fix bottleneck analyser, duplicate console output, and add CPU affinity - #17
Merged
Merged
Conversation
monitor.py divides process-tree CPU by the logical core count before writing cpu_percent, so a single-threaded EddyPro saturating one core of twenty recorded ~5% -- far below the 70/90% thresholds the classifier compared it against. Every run was therefore classified as "NONE: no clear bottleneck ... headroom to increase max_processes", advice that was correct only by coincidence and that would have read identically on a fully saturated machine. Confirmed against a real 7-day run whose eddypro_rp phase sustained 100.3% of one core (p95) while cpu_percent read 5.0% and the machine sat at 23.1%. The classifier now: - judges machine saturation on system_cpu_percent, because each parallel worker's monitor sees only its own process tree and so can never observe that the machine as a whole is full; - adds a CPU_SINGLE_CORE verdict from cpu_percent_of_core, naming the case where the workload is pinned by single-thread speed while cores sit idle -- the normal state for eddypro_rp, and the one that actually justifies raising max_processes; - falls back to the normalised figure when system_cpu_percent is absent, so older metrics files stay classifiable. The new single_core_bound_percent threshold (default 95) is tunable via performance_thresholds. The HTML report gains separate machine-wide and percent-of-one-core columns, replacing a single normalised figure that reads as near-zero for any single-threaded run.
setup_logging always attaches a stdout StreamHandler, so with both stream_output: true and log_eddypro_output: true -- the shipped defaults -- the streaming loop's print() duplicated every line the logger had already emitted. Measured on a 7-day run: 44 560 log lines per site-year before, 22 196 after. It doubled log-file size and halved the interval between log rotations on multi-hour runs. The direct echo is now used only when the logger is not already mirroring output, so live progress still works with log_eddypro_output: false. The tests assert on print() rather than on captured log records: the logger is called exactly once either way, so a caplog-based test passes against the very bug it is meant to catch.
CPU utilisation cannot distinguish a saturated fast core from a saturated slow one. On Intel hybrid CPUs (12th gen and later) Windows parks a long-running background process on the efficiency cores; measured on a 12700K the same workload took 241 s pinned to the performance cores and 474-501 s unpinned, while cpu_percent_of_core read 96-103% in every case. Nothing in the metrics revealed that half the machine's performance was missing. The monitor now counts completed work items and records work_items and work_items_per_s alongside the CPU and disk series; the analyser derives mean_seconds_per_work_item and the HTML report shows it. `run` points this at the binned-cospectra directory, which EddyPro fills one file per flux averaging period. Opt-in via progress_dir; runs without one are unaffected. The tests deliberately go through create_monitor and MonitoredOperation rather than constructing PerformanceMonitor directly: the first cut of this accepted progress_dir at every layer but never forwarded it to the constructor, so every run silently recorded zeros, and a test that built the monitor directly would have passed.
Intel hybrid CPUs (12th generation and later) mix performance cores with efficiency cores, and the OS parks long-running background work on the efficiency ones. eddypro_rp is single-threaded, so this costs roughly a factor of two: measured on an i7-12700K, one year of 10 Hz data took 241 s pinned and 474-501 s unpinned. CPU monitoring cannot see it -- a saturated efficiency core reports the same ~100% of a core as a saturated performance one -- so the loss is silent. Pinning also removed the run-to-run variance entirely; the two pinned runs agreed to the second while the unpinned pair differed by 5.7%. cpu_affinity accepts: null leave scheduling to the OS (default, unchanged behaviour) performance auto-detect the performance cores and pin to them [0, 1, 2, ...] pin to these logical CPU indices Applied once in cmd_run and cmd_scenarios; child processes inherit affinity, so this covers the ProcessPoolExecutor workers and the EddyPro executables they launch. Auto-detection derives the split from the core counts -- performance cores carry two hardware threads and efficiency cores one, so p_cores = logical - physical, occupying logical indices 0..2*p_cores-1. Where that cannot be determined (no SMT, or no efficiency cores) the affinity is left unchanged, which is the correct outcome rather than a failure. An unrecognised value is logged and ignored: a failed optimisation must not stop a multi-hour run.
- CONFIG.md: document cpu_affinity with the measured pinned-vs-unpinned figures and how auto-detection works; note that the CPU verdict is now judged machine-wide; add single_core_bound_percent to the thresholds table. - MULTI_YEAR_RUNS.md: replace the "each worker's CPU% is a share of the machine" paragraph with a table explaining what each of the three CPU columns actually answers, since cpu_percent reading ~5% for a saturated core is the thing that misleads; add CPU_SINGLE_CORE to the traffic-light table; add a section on hybrid-CPU core placement. - REPORTING.md: document work_items and work_items_per_s.
The format hook invoked sys.executable, which is whichever interpreter runs the hook -- typically the system Python, where neither black nor ruff is installed. Its "tool not installed, tolerate silently" path only caught FileNotFoundError, but `python -m ruff` with ruff absent exits non-zero with a normal message rather than raising, so every edit reported "No module named ruff" and exited 2. The hook now prefers .venv (Windows and POSIX layouts) and treats a "No module named" result as the tool being unavailable rather than as a lint failure.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Found while running a full end-to-end validation of the pipeline: 7 days per
year, 3 years, two sites (GL-ZaF at 10 Hz, GL-Dsk at 20 Hz), every run repeated
after a discarded warm-up.
Fixes
The bottleneck analyser could not detect a CPU bottleneck.
monitor.pydivides process-tree CPU by the logical core count, so a single-threaded
EddyPro saturating one core of twenty recorded ~5% against 70/90% thresholds.
Every run came back
NONE: no clear bottleneck ... headroom to increase max_processes— correct only by coincidence, and identical to what it wouldsay on a fully saturated machine. Measured on a real run:
cpu_percent(÷20)cpu_percent_of_coresystem_cpu_percentNow judges machine saturation on
system_cpu_percent(the only column aparallel worker can see the whole machine through) and adds a
CPU_SINGLE_COREverdict. Falls back to the old figure when the system columnis absent, so older metrics files stay classifiable.
EddyPro output was written to the console twice.
setup_loggingalwaysattaches a stdout handler, so with the shipped defaults the streaming loop's
print()duplicated every logged line: 44 560 log lines per site-year before,22 196 after.
The format hook never ran. It invoked
sys.executable— the system Python,which has no
blackorruff— and its tolerate-missing path only caughtFileNotFoundError, so every edit exited 2 with "No module named ruff".Additions
cpu_affinityconfig option. On hybrid CPUs the OS parks long-runningbackground work on the efficiency cores.
eddypro_rpis single-threaded, soone year of 10 Hz data took 241 s pinned vs 474–501 s unpinned — and CPU
monitoring cannot see it, because a saturated E-core reads the same ~100% of a
core as a saturated P-core. Pinning also removed run-to-run variance entirely.
Accepts
performance(auto-detect), an explicit CPU list, or null (default,unchanged).
Throughput signal.
work_items/work_items_per_sfrom thebinned-cospectra count, plus
mean_seconds_per_work_itemin the report. Thisis what makes the above detectable: identical CPU, half the work done.
Validation results
Multiprocessing scales cleanly across years — 2.80× on 3 workers (GL-ZaF,
93% efficiency), 2.93× (GL-Dsk, 98%) — and output is byte-identical to
sequential across all 24 files compared. Disk peaked under 10 MB/s against a
450 MB/s threshold and memory at 29 MB per worker, so neither constrains
anything. Monitoring overhead is below run-to-run noise.
Also worth recording: 20 Hz data costs 3.6× more than 10 Hz, not 2×.
Notes for review
CPU_SINGLE_COREis a new value forprimary_bottleneck; nothing in-repoparses it, but downstream consumers of the manifest would see it.
eddypro_binned_cospectra, which only existswhen spectral output is enabled. Without it
work_itemsstays 0 — itdegrades quietly rather than erroring, so the diagnostic is not universal.
threads are numbered first. It returns None rather than guessing when the
topology is unexpected.
221 tests pass; ruff, black, mypy and the pre-commit suite clean.