From b1d2953ae8688c53fc71a9da1b0a2d138f5a81c7 Mon Sep 17 00:00:00 2001 From: Yuxuan Jiang Date: Sat, 31 Oct 2026 18:36:17 +0800 Subject: [PATCH 1/4] Timestamp parameter samples at observation time --- tests/test_distributed_probe_tracing.py | 42 ++++ tests/test_parameter_observation_time.py | 235 ++++++++++++++++++ .../instrumentor/proxy_wrapper/proxy.py | 16 +- .../instrumentor/proxy_wrapper/subclass.py | 14 +- 4 files changed, 301 insertions(+), 6 deletions(-) create mode 100644 tests/test_parameter_observation_time.py diff --git a/tests/test_distributed_probe_tracing.py b/tests/test_distributed_probe_tracing.py index 4d14e4a7..4f0f94f7 100644 --- a/tests/test_distributed_probe_tracing.py +++ b/tests/test_distributed_probe_tracing.py @@ -126,6 +126,48 @@ def test_actual_events_and_bookkeeping_suppression(tmp_path: Path, mode: str) -> record["dump_loc"] == "distributed_probe.update.after" for record in variables ) + # The parameter values are observed around an in-place optimizer update. + # Their times must describe those observations, not an earlier Python + # attribute assignment. There is exactly one successful update here. + optimizer_pre = [ + record + for record in records + if record["function"] == "torch.optim.sgd.SGD.step" + and record["type"] == "function_call (pre)" + ] + optimizer_post = [ + record + for record in records + if record["function"] == "torch.optim.sgd.SGD.step" + and record["type"] == "function_call (post)" + ] + assert len(optimizer_pre) == len(optimizer_post) == 1 + pre_time = optimizer_pre[0]["time"] + post_time = optimizer_post[0]["time"] + assert isinstance(pre_time, int) and not isinstance(pre_time, bool) + assert isinstance(post_time, int) and not isinstance(post_time, bool) + for name in ("model.weight", "model.bias"): + before: list[dict[str, object]] = [] + after: list[dict[str, object]] = [] + for record in variables: + meta = record["meta_vars"] + assert isinstance(meta, dict) + if record["var_name"] != name or meta["step"] != 4: + continue + if record["dump_loc"] == "distributed_probe.update.before": + before.append(record) + elif record["dump_loc"] == "distributed_probe.update.after": + after.append(record) + assert len(before) == len(after) == 1 + before_time = before[0]["time"] + after_time = after[0]["time"] + assert isinstance(before_time, int) and not isinstance(before_time, bool) + assert isinstance(after_time, int) and not isinstance(after_time, bool) + assert before_time < pre_time < post_time < after_time + before_attrs = before[0]["attributes"] + after_attrs = after[0]["attributes"] + assert isinstance(before_attrs, dict) and isinstance(after_attrs, dict) + assert before_attrs["data"] != after_attrs["data"] else: assert report["registered_parameter_names"] == [] assert variables == [] diff --git a/tests/test_parameter_observation_time.py b/tests/test_parameter_observation_time.py new file mode 100644 index 00000000..3ccb16a1 --- /dev/null +++ b/tests/test_parameter_observation_time.py @@ -0,0 +1,235 @@ +"""A sampled parameter describes its observation time, not its last assignment.""" + +from __future__ import annotations + +import gc +import weakref +from dataclasses import dataclass +from types import ModuleType +from typing import Literal + +import pytest +import torch + +import traincheck.config.config as config +from traincheck.instrumentor.proxy_wrapper import proxy, subclass +from traincheck.instrumentor.proxy_wrapper.proxy_config import tensor_dump_format +from traincheck.instrumentor.proxy_wrapper.proxy_registry import VarRegistry + + +@dataclass +class Clock: + now: int = 100 + calls: int = 0 + + def __call__(self) -> int: + self.calls += 1 + return self.now + + +@dataclass +class TrackedParameter: + wrapper: proxy.Proxy | subclass.ProxyParameter + tensor: torch.Tensor + module: ModuleType + registry: VarRegistry + clock: Clock + records: list[dict[str, object]] + + +@pytest.fixture(params=("subclass", "proxy")) +def tracked( + request: pytest.FixtureRequest, monkeypatch: pytest.MonkeyPatch +) -> TrackedParameter: + style: object = request.param + assert style in ("subclass", "proxy") + registry = VarRegistry() + records: list[dict[str, object]] = [] + clock = Clock() + module = subclass if style == "subclass" else proxy + + def isolated_registry() -> VarRegistry: + return registry + + monkeypatch.setattr(module, "get_global_registry", isolated_registry) + monkeypatch.setattr(module, "get_timestamp_ns", clock) + monkeypatch.setattr(config, "DISABLE_WRAPPER", True) + monkeypatch.setattr(proxy.Proxy, "var_dict", {}) + monkeypatch.setitem(tensor_dump_format, "dump_tensor_hash", True) + monkeypatch.setitem(tensor_dump_format, "dump_tensor_stats", False) + monkeypatch.setitem(tensor_dump_format, "dump_tensor_full", False) + + def capture_record(record: dict[str, object]) -> None: + records.append(record) + + def capture_legacy_record(**fields: object) -> None: + records.append( + { + "time": fields["time"], + "mode": fields["change_type"], + "attributes": fields["var_attributes"], + "dump_loc": fields["dump_loc"], + } + ) + + monkeypatch.setattr(subclass, "dump_trace_VAR", capture_record) + monkeypatch.setattr(proxy.Proxy.jsondumper, "dump_json", capture_legacy_record) + source = torch.nn.Parameter(torch.tensor([1.0, 2.0])) + wrapper: proxy.Proxy | subclass.ProxyParameter + if style == "subclass": + wrapper = subclass.ProxyParameter( + source, + var_name="model.weight", + var_type="torch.nn.Parameter", + should_dump_trace=False, + ) + tensor = wrapper + else: + wrapper = proxy.Proxy(source, var_name="model.weight", should_dump_trace=False) + tensor = source + registry.add_var(wrapper, "model.weight", "torch.nn.Parameter") + assert wrapper.__dict__["last_update_timestamp"] == 100 + clock.calls = 0 + monkeypatch.setattr(config, "DISABLE_WRAPPER", False) + return TrackedParameter(wrapper, tensor, module, registry, clock, records) + + +def sample( + tracked: TrackedParameter, phase: Literal["sample", "selective-sample"] +) -> None: + if phase == "sample": + tracked.registry.dump_sample( + dump_loc="test", dump_config={"torch.nn.Parameter": {}} + ) + else: + tracked.registry.dump_modified( + dump_loc="test", dump_config={"torch.nn.Parameter": {}} + ) + + +def attributes(record: dict[str, object]) -> dict[str, object]: + value = record["attributes"] + if not isinstance(value, dict) or not all(isinstance(key, str) for key in value): + raise TypeError("Parameter attributes must be a string-keyed dictionary") + return {key: item for key, item in value.items()} + + +@pytest.mark.parametrize("phase", ["sample", "selective-sample"]) +def test_samples_of_in_place_mutations_have_fresh_times( + tracked: TrackedParameter, phase: Literal["sample", "selective-sample"] +) -> None: + rng_before = torch.get_rng_state().clone() + tracked.clock.now = 200 + sample(tracked, phase) + with torch.no_grad(): + tracked.tensor.add_(3) + # In-place tensor mutation does not notify the Python assignment hook. A + # selective sample requires the caller to mark the object eligible again. + tracked.registry.add_var(tracked.wrapper, "model.weight", "torch.nn.Parameter") + tracked.clock.now = 300 + sample(tracked, phase) + + assert len(tracked.records) == 2 + before, after = tracked.records + assert before["time"] == 200 + assert after["time"] == 300 + assert before["mode"] == after["mode"] == phase + assert attributes(before)["data"] != attributes(after)["data"] + assert tracked.wrapper.__dict__["last_update_timestamp"] == 100 + if tracked.module is proxy: + assert proxy.Proxy.var_dict["model.weight"].last_update_timestamp == 100 + assert tracked.registry.registry["model.weight"].stale is True + assert tracked.clock.calls == 2 + if phase == "selective-sample": + # Observing a variable must not make it eligible for another modified-only + # sample. The registry's normal stale-entry skip reads no new timestamp. + sample(tracked, phase) + assert len(tracked.records) == 2 + assert tracked.clock.calls == 2 + torch.testing.assert_close( + tracked.tensor.detach(), torch.tensor([4.0, 5.0]), rtol=0, atol=0 + ) + torch.testing.assert_close(torch.get_rng_state(), rng_before, rtol=0, atol=0) + + +@pytest.mark.parametrize("phase", ["sample", "selective-sample"]) +def test_time_is_captured_before_metadata_conversion( + tracked: TrackedParameter, + monkeypatch: pytest.MonkeyPatch, + phase: Literal["sample", "selective-sample"], +) -> None: + def metadata_after_clock_advance(owner: object) -> dict[str, int]: + assert owner is tracked.wrapper + tracked.clock.now = 900 + return {"step": 1} + + monkeypatch.setattr(tracked.module, "get_meta_vars", metadata_after_clock_advance) + tracked.clock.now = 200 + sample(tracked, phase) + assert len(tracked.records) == 1 + assert tracked.records[0]["time"] == 200 + assert tracked.clock.now == 900 + assert tracked.clock.calls == 1 + + +@pytest.mark.parametrize("phase", ["update", "call", "iter"]) +def test_non_sample_records_keep_assignment_time( + tracked: TrackedParameter, phase: str +) -> None: + tracked.clock.now = 200 + tracked.wrapper.dump_trace(phase=phase, dump_loc="test") + assert len(tracked.records) == 1 + assert tracked.records[0]["time"] == 100 + assert tracked.clock.calls == 0 + assert tracked.wrapper.__dict__["last_update_timestamp"] == 100 + assert tracked.registry.registry["model.weight"].stale is False + + +def test_disabled_dump_does_not_read_clock_or_emit( + tracked: TrackedParameter, monkeypatch: pytest.MonkeyPatch +) -> None: + monkeypatch.setattr(config, "DISABLE_WRAPPER", True) + tracked.wrapper.dump_trace(phase="sample", dump_loc="test") + assert tracked.records == [] + assert tracked.clock.calls == 0 + assert tracked.wrapper.__dict__["last_update_timestamp"] == 100 + assert tracked.registry.registry["model.weight"].stale is False + + +@pytest.mark.parametrize("tracked", ["subclass"], indirect=True) +def test_retired_parameter_does_not_read_clock_or_emit( + tracked: TrackedParameter, +) -> None: + model = torch.nn.Linear(2, 1) + subclass.proxy_parameter(model, parent_name="owned", should_dump_trace=False) + parameter = model.weight + assert isinstance(parameter, subclass.ProxyParameter) + reference = weakref.ref(model) + del model + gc.collect() + assert reference() is None + assert list(tracked.registry.registry) == ["model.weight"] + tracked.clock.calls = 0 + parameter.dump_trace(phase="sample", dump_loc="retired") + assert tracked.clock.calls == 0 + assert tracked.records == [] + + +@pytest.mark.parametrize("phase", ["sample", "selective-sample"]) +def test_failed_sample_propagates_without_changing_assignment_time( + tracked: TrackedParameter, + monkeypatch: pytest.MonkeyPatch, + phase: Literal["sample", "selective-sample"], +) -> None: + failure = RuntimeError("metadata conversion failed") + + def fail_conversion(owner: object, value: object) -> dict[str, object]: + raise failure + + monkeypatch.setattr(tracked.module, "dump_attributes", fail_conversion) + with pytest.raises(RuntimeError) as caught: + sample(tracked, phase) + assert caught.value is failure + assert tracked.records == [] + assert tracked.wrapper.__dict__["last_update_timestamp"] == 100 + assert tracked.registry.registry["model.weight"].stale is True diff --git a/traincheck/instrumentor/proxy_wrapper/proxy.py b/traincheck/instrumentor/proxy_wrapper/proxy.py index 4def285b..ab57c14f 100644 --- a/traincheck/instrumentor/proxy_wrapper/proxy.py +++ b/traincheck/instrumentor/proxy_wrapper/proxy.py @@ -159,7 +159,12 @@ def __deepcopy__(self, memo): new_copy.__dict__[attr_name] = copy.deepcopy(attr_value, memo) return new_copy - def dump_trace(self, phase, dump_loc): + def dump_trace(self, phase: str, dump_loc: str | None) -> None: + """Timestamp samples when observed without changing mutation bookkeeping. + + Update/call/iteration records retain their existing update-event time. + Metadata capture is not atomic under concurrent application mutation. + """ if config.DISABLE_WRAPPER: return @@ -174,13 +179,16 @@ def dump_trace(self, phase, dump_loc): if obj._version == Proxy.var_dict[self.__dict__["var_name"]].version: return - last_update_timestamp = self.__dict__["last_update_timestamp"] - if not isinstance(obj, torch.nn.Module): + observation_time = ( + get_timestamp_ns() + if phase in ("sample", "selective-sample") + else self.__dict__["last_update_timestamp"] + ) self.jsondumper.dump_json( process_id=self.process_id, thread_id=self.thread_id, - time=last_update_timestamp, + time=observation_time, meta_vars=get_meta_vars(self), var_name=var_name, var_type=typename(obj, is_runtime=True), diff --git a/traincheck/instrumentor/proxy_wrapper/subclass.py b/traincheck/instrumentor/proxy_wrapper/subclass.py index baf2838a..7bfdb470 100644 --- a/traincheck/instrumentor/proxy_wrapper/subclass.py +++ b/traincheck/instrumentor/proxy_wrapper/subclass.py @@ -216,6 +216,12 @@ def register_object(self) -> None: ) def dump_trace(self, phase: str, dump_loc: str | None) -> None: + """Record samples at observation start, retaining update-event times. + + In-place tensor updates need not invoke __setattr__. Sampling must not + backdate current values to that hook or mark an observation as a mutation. + Concurrent model mutation during metadata capture remains unsupported. + """ if config.DISABLE_WRAPPER or not self._model_tracking_enabled(): return @@ -230,7 +236,11 @@ def dump_trace(self, phase: str, dump_loc: str | None) -> None: # if obj._version == Proxy.var_dict[self.__dict__["var_name"]].version: # return - last_update_timestamp = self.__dict__["last_update_timestamp"] + observation_time = ( + get_timestamp_ns() + if phase in ("sample", "selective-sample") + else self.__dict__["last_update_timestamp"] + ) # TODO # if not isinstance(obj, torch.nn.Module): @@ -238,7 +248,7 @@ def dump_trace(self, phase: str, dump_loc: str | None) -> None: { "process_id": self.process_id, "thread_id": self.thread_id, - "time": last_update_timestamp, + "time": observation_time, "meta_vars": get_meta_vars(self), "var_name": var_name, "var_type": "torch.nn.Parameter", From 219d2f25f855ae60b915200ca4740ede9119428c Mon Sep 17 00:00:00 2001 From: Yuxuan Jiang Date: Sat, 31 Oct 2026 18:39:51 +0800 Subject: [PATCH 2/4] Explain distributed normalization coverage gaps from raw traces --- .../ring18-normalization-coverage-20261031.md | 62 +++++++++++++++++++ 1 file changed, 62 insertions(+) create mode 100644 docs/measurements/ring18-normalization-coverage-20261031.md diff --git a/docs/measurements/ring18-normalization-coverage-20261031.md b/docs/measurements/ring18-normalization-coverage-20261031.md new file mode 100644 index 00000000..bff0fb55 --- /dev/null +++ b/docs/measurements/ring18-normalization-coverage-20261031.md @@ -0,0 +1,62 @@ +# Why the local-mean loss-normalization fault was missed + +Audit date: 2026-10-31. Read-only source and saved-run analysis; no new training was launched by this audit. Baseline core: `754277ae87e2189cebf16b405940bef1fee5904c`; workload/tracing: `15ed99cc2d72853ebeb44a665b3a91d8923dd99e`. Source locations below refer to `b1d2953ae8688c53fc71a9da1b0a2d138f5a81c7`, whose timestamp change does not alter these relevant functions. + +## Conclusion + +The observed miss has three concrete causes, earlier than checker execution: the wrong scale is never recorded, numerical loss/gradient contents are absent from the API records, and the implemented/selected relation families do not express the global-token normalization equation. Fixing parameter observation timestamps alone will not close these gaps. The existing rules all activated; this is not evidence of a checker hang or wholly dormant rule set. + +## Raw evidence and reproducibility + +Six unmodified raw API logs were read from `ring18:/home/yuxuan/experiments/traincheck-distributed-20261031/runs/{api-fp32-full,api-fp32-control,api-fp32-fault}/payload/rank{0,1}/trace/trace_API_*.log` and saved under `/Users/matt/gitrepos/traincheck/outputs/ring18-timestamp-20261031/normalization-audit/raw/`. Export archive `api-traces.tar.gz` is 749,999 bytes, SHA256 `aaa98a3b90f79d3ea294389043343ece0852358d1662918db6f362325697ec47`. `normalization-audit/audit.json` in that local output directory records each raw log's hash and byte count, complete function/count and type-schema inventories, every direct float argument/count, unmodified cross-entropy/backward records, and unmodified failed-rule details. Original frozen rules and coverage files remain at `/Users/matt/gitrepos/traincheck/outputs/ring18-distributed-20261031/evidence-bundle/analysis`. + +Reproduce the JSON analysis with: + +```sh +/Users/matt/miniconda3/bin/python3.12 /Users/matt/gitrepos/traincheck/outputs/ring18-timestamp-20261031/normalization-audit/audit.py +``` + +Every raw log has 3,752 events: 1,876 pre/post call pairs across 90 distinct functions. All six have identical function counts, typed argument/return structural inventories, and direct float-argument values/counts. This is a coverage/type comparison, **not whole-trace equality**: no IDs/timestamps were stripped from raw records and no claims of exact output parity follow from these inventories. + +## Where the fault-specific information disappears + +1. `tools/distributed_probe/workload.py:459-471`: `local_tokens`, the count tensor, `dist.all_reduce`, extraction of `global_tokens`, and `loss_scale()` execute inside `session.suppress()`, outside the traced update. These values are in run metrics, not API trace inputs. The metrics are not fed into the inference engine. Healthy scale is `2/32 = 0.0625`; faulty scales are `1/10 = 0.1` on rank 0 and `1/22` on rank 1. See `loss_scale()` at lines 125-134. +2. The actual use is `loss = token_loss(logits, batch) * scale` (`workload.py:491`), not a wrapped user API with an explicit scale argument. `tracer.py:974-980` skips magic methods including `Tensor.__mul__`. `config.py:258` sets `INSTR_DESCRIPTORS=False`; `tracer.py:1166-1170,1234-1238` also excludes Tensor method descriptors. Actual raw coverage contains no `__mul__`, `.sum`, `.item`, `.div`, `.mean`, or `all_reduce` calls. `_foreach_mul_` appears four times as part of gradient clipping; it is unrelated to application loss scaling. Exact floating values `0.0625`, `0.1`, and `1/22` occur zero times anywhere within the raw args, kwargs, or returns of all six logs. +3. API primitive serialization itself preserves float values (`dumper.py:574-581`), so this is not float rounding or JSON loss. Wrapped cross-entropy appears eight times/rank/run, followed by eight `Tensor.backward` calls. Its output has metadata `shape=[16], nbytes=64, dtype=torch.float32`; `backward`'s receiver has `shape=[], nbytes=4, dtype=torch.float32`. Neither record has tensor numerical `data` or its hash. API `var_to_serializable` delegates tensor objects to `obj_to_serializable`, which explicitly calls `convert_var_to_dict(..., include_tensor_data=False)` (`dumper.py:541-543`). Enabling the tensor-hash setting does not override this API-path flag. It applies when tensor data dumping is actually requested, such as variable/model sampling. +4. The parser preserves the recorded typed args/kwargs/returns: `trace/utils.py:39-53` skips flattening those fields, and `trace/types.py:157-167` exposes them on `FuncCallEvent`. There is no missing numeric scale for the parser to recover, and no recorded loss tensor contents to compare. A later loss `.item()` used for metrics is also inside the suppressed bookkeeping scope (`workload.py:507-517`). + +## Why the learned relations do not compensate + +Both ranks learned the same family counts except one distinctness rule: + +| Relation | Rank 0 | Rank 1 | What it can establish here | +| --- | ---: | ---: | --- | +| APIContainRelation | 117 | 117 | Call/variable containment; optional exact argument constraints | +| ConsistentOutputRelation | 222 | 222 | Returned tensor metadata equals a learned value | +| ConsistentInputOutputRelation | 246 | 246 | Equality between input/output tensor properties | +| DistinctArgumentRelation | 5 | 6 | Recorded positional argument metadata differs across calls | +| ThresholdRelation | 2 | 2 | Output tensor property bounded by a named `min`/`max` input | +| ConsistencyRelation | 0 | 0 | No variable records were fed to these API-only rank-local inferences | + +- `get_events_of_funcs_with_tensors()` filters `ANALYSIS_SKIP_FUNC_NAMES` (`consistency_transient_vars.py:247-256`), including `torch.nn.functional` and `torch._tensor.Tensor.backward` (`config.py:67-91`). Thus even their available shape/dtype metadata does not generate transient consistency/threshold rules. DistinctArgumentRelation uses the same skip list (`DistinctArgumentRelation.py:42-56`). +- `get_input_tensors()` explicitly selects tensor/parameter argument types (`consistency_transient_vars.py:194-213`). ConsistentInputOutputRelation generates equality hypotheses by intersecting tensor-property values (`:692-750`); it does not use arbitrary primitive scalar arguments to infer products or ratios. +- ConsistentOutputRelation generates tensor-property-to-constant rules (`:303-433`), not a relation constraining arbitrary scalar inputs. +- ThresholdRelation reads only numeric inputs whose parameter names contain `min` or `max` (`:216-244`), and only considers output metadata close to those bounds during generation. Both learned rules are `clip_grad_norm_().output[0].is_cuda <= max_norm` and `is_leaf <= max_norm`, with `max_norm=1.0`. They compare boolean metadata because Python treats bool as int; they do **not** bound the returned gradient norm's numeric value. No threshold rule concerns loss normalization. +- APIContain can in principle constrain captured scalar child-call arguments, but the scale's multiply call was never captured; even adding capture would yield at best a reference-specific constant argument rule, not the equation `scale * global_valid_tokens == world_size`. +- FunctionLeadRelation and FunctionCoverRelation were explicitly disabled for these runs. Their event-order/coverage semantics would not supply the missing arithmetic relation. +- Adding model parameter VAR records, fixing their timestamps, or joining rank traces does not by itself establish correct normalization: in this fault, DDP still synchronizes identical faulty parameters on both ranks. Parameter equality therefore passes the fault. Correctness requires observing loss weights/counts or comparing with a mathematical/global-batch gradient reference. + +All 592/593 frozen rules were active on fresh healthy and faulty traces, with zero dormant, unobserved, or unknown outcomes in the recorded coverage. Rank 0 had two healthy violations and one faulty violation; rank 1 had two in each. No fault-only rule identity was violated. Checkers can stop after the first violation for an individual rule, so 'active' does not mean every opportunity was visited. + +## Healthy alarms, separately from the miss + +The shared containment alarm is directly explainable. Rule 23's saved child `Embedding.forward` argument includes `_TRAINCHECK_weight_ID=139983274014448` for rank 0 (`139772221489616` for rank 1). All eight actual child calls are present in both fresh healthy and fault runs. `containment-windows.json` additionally verifies that each of the eight DDP forward intervals contains exactly one complete Embedding forward call, on the same PID/TID, in every run; this is not merely global presence. Comparing every saved receiver field with the raw child receiver shows exactly one changed field, this process-local weight ID. For healthy rank 0 the new ID is `140486160791280`; for healthy rank 1 it is `140303637676896`. `APIParam.check_event_match()` (`base_cls.py:437-463`) calls `Arguments.check_for_violation()` (`:243-250`), which compares saved values exactly. This identity literal rejects the child despite the call being present. The coverage field `identity_bearing_invariants=0` counts precondition identity clauses, not this literal in relation parameters. + +The other healthy violations are DistinctArgument rules: rank-0 rule 240 on LayerNorm and rank-1 rule 519 on TransformerEncoderLayer. Their recorded failing call pairs are both in step 1 and have byte-for-byte equal `args` dictionaries, including the same `_TRAINCHECK_data_ID`, shape/dtype, and flags. The checker compares these dictionaries (`DistinctArgumentRelation.py:127-170,438-448`), so its failure is consistent with its input. The trace has no tensor values, and the dumped ID is `id(tensor.data)` (`dumper.py:474-477`), not a content identity. This evidence alone cannot prove whether the underlying input values were equal or whether allocator reuse caused the repeated ID; do not describe it as proven numerical argument duplication or a demonstrated allocator bug. + +## Smallest meaningful next changes (proposals, not implemented) + +1. Add a narrow typed normalization observation at the loss-scaling boundary: update/microbatch/rank, reduction semantics, local/global valid-token counts, DDP divisor/world size, and applied scalar. Keep it separate from existing independent-oracle measurements. Alternatively opt into the specific scale/multiply APIs, but denominator provenance still needs observation. This is an observability addition, not an inference-speed improvement. +2. Add and test a declared contract for this workload, `scale * global_valid_tokens ≈ world_size` (or `scale ≈ world_size/global_valid_tokens` with an explicit float tolerance and supported DDP reduction contract). This should reject both erroneous ranks immediately while allowing varying global token counts. It is a new arithmetic contract, **not** evidence the current learned engine detected it. A generic scalar-constant learner is a smaller inference extension but overfits this fixed-count probe and must not be presented as general distributed normalization verification. +3. Before claiming agent benefit, repair the cross-run identity-literal containment false alarm independently, and distinguish metadata distinctness from tensor-content distinctness. Do not hide these healthy alarms by deleting IDs in evaluation. Preserve a healthy varying-token-count control, an equal-count case where local means are mathematically valid, FP32/BF16 behavior, and explicit unsupported/unknown outcomes. +4. Retain the combined-global-batch gradient oracle as independent fault ground truth. Use it to evaluate any new contract's detection/false-positive behavior; do not train the contract on fault labels or count oracle assertions as existing TrainCheck alarms. From a6232194b5395bbc7417208ac87161510d3ba5d3 Mon Sep 17 00:00:00 2001 From: Yuxuan Jiang Date: Sat, 31 Oct 2026 18:47:01 +0800 Subject: [PATCH 3/4] Preserve NumPy timestamp precision in coverage observations --- tests/test_coverage_numpy_timestamps.py | 157 +++++++++++++++++++++++ tools/fresh_validation/check_coverage.py | 42 +++++- 2 files changed, 196 insertions(+), 3 deletions(-) create mode 100644 tests/test_coverage_numpy_timestamps.py diff --git a/tests/test_coverage_numpy_timestamps.py b/tests/test_coverage_numpy_timestamps.py new file mode 100644 index 00000000..f189981b --- /dev/null +++ b/tests/test_coverage_numpy_timestamps.py @@ -0,0 +1,157 @@ +"""Coverage observes valid dataframe timestamps without losing nanoseconds.""" + +from __future__ import annotations + +import json + +import numpy as np +import pandas as pd +import pytest + +from tools.fresh_validation import check_coverage as coverage +from tools.fresh_validation.contracts import mapping, required, sequence +from traincheck.instrumentor.tracer import TraceLineType +from traincheck.invariant.base_cls import ( + GroupedPreconditions, + Invariant, + Preconditions, + UnconditionalPrecondition, + VarTypeParam, +) +from traincheck.invariant.consistency_relation import ConsistencyRelation +from traincheck.trace.trace_pandas import TracePandas + +START = 2**53 + 1 +END = START + 10 + + +def integer_timestamp_trace(values: list[int]) -> TracePandas: + rows: list[dict[str, object]] = [] + for index, value in enumerate(values): + for timestamp in (START, END): + rows.append( + { + "type": TraceLineType.STATE_CHANGE, + "time": timestamp, + "process_id": 1, + "thread_id": 2, + "var_name": f"weight-{index}", + "var_type": "torch.nn.Parameter", + "attributes.value": value, + } + ) + return TracePandas(pd.DataFrame(rows), truncate_incomplete_func_calls=False) + + +def consistency_rule() -> Invariant: + return Invariant( + ConsistencyRelation, + [ + VarTypeParam("torch.nn.Parameter", "value"), + VarTypeParam("torch.nn.Parameter", "value"), + ], + GroupedPreconditions({"var": Preconditions([UnconditionalPrecondition()])}), + "fixture value agreement with integer nanosecond timestamps", + ) + + +@pytest.mark.parametrize("values,passed", [([7, 7], True), ([7, 8], False)]) +def test_real_pandas_final_lifetime_preserves_checker_parity( + values: list[int], passed: bool +) -> None: + trace = integer_timestamp_trace(values) + for attributes in trace.get_var_insts().values(): + state = attributes["value"][-1] + assert isinstance(state.liveness.end_time, np.int64) + assert state.liveness.end_time == END + rule = consistency_rule() + observed = coverage.observe(trace, rule) + direct = coverage.observe(integer_timestamp_trace(values), rule, enabled=False) + assert observed["status"] == "completed", observed + assert observed["checker_result"] == direct["checker_result"] + assert observed["check_passed"] is passed + assert observed["coverage_observed"] is True + assert observed["active"] is True + assert observed["opportunities"] == observed["decisions_completed"] == 1 + decisions = observed["decision_records"] + assert len(decisions) == 1 + decision = mapping(decisions[0], "decision") + pair = sequence(required(decision, "variable_value_pair"), "variable pair") + assert len(pair) == 2 + for raw in pair: + identity = mapping(raw, "identity") + for key, expected in ( + ("event_time", END), + ("liveness_start", START), + ("liveness_end", END), + ): + assert isinstance(identity[key], int) and not isinstance( + identity[key], bool + ) + assert identity[key] == expected + # The emitted observation uses ordinary JSON scalars, with exact large ints. + encoded = json.dumps(decisions, allow_nan=False) + assert json.loads(encoded) == decisions + + +@pytest.mark.parametrize( + "value,expected", + [ + (START, START), + (2**100, 2**100), + (np.int64(START), START), + (np.int64(2**63 - 1), 2**63 - 1), + (np.uint64(2**64 - 1), 2**64 - 1), + (np.int32(-3), -3), + (0.125, 0.125), + (np.float16(0.125), 0.125), + (np.float32(0.1), float(np.float32(0.1))), + (np.float64(0.125), 0.125), + (np.longdouble(0.125), 0.125), + ], +) +def test_timestamp_scalar_conversion_is_exact( + value: object, expected: int | float +) -> None: + actual = coverage.dataframe_timestamp(value, "fixture time") + assert type(actual) is type(expected) + assert actual == expected + assert json.loads(json.dumps(actual, allow_nan=False)) == expected + + +@pytest.mark.parametrize( + "value", + [ + True, + np.bool_(False), + None, + "123", + {}, + [], + complex(1, 0), + np.complex64(1), + float("nan"), + float("inf"), + float("-inf"), + np.float32("nan"), + np.float32("inf"), + np.float64("-inf"), + np.timedelta64(1, "ns"), + np.timedelta64(1, "D"), + np.datetime64("2026-01-01"), + pd.NA, + ], +) +def test_timestamp_rejects_invalid_or_nonfinite_values(value: object) -> None: + with pytest.raises(ValueError, match="fixture time"): + coverage.dataframe_timestamp(value, "fixture time") + + +def test_extended_float_must_be_exactly_representable() -> None: + # Some platforms implement longdouble as float64. Exercise extra precision + # only where NumPy actually supplies it; ordinary float64 is covered above. + if np.finfo(np.longdouble).nmant > np.finfo(np.float64).nmant: + value = np.longdouble(1) + np.finfo(np.longdouble).eps + assert value != float(value) + with pytest.raises(ValueError, match="fixture time"): + coverage.dataframe_timestamp(value, "fixture time") diff --git a/tools/fresh_validation/check_coverage.py b/tools/fresh_validation/check_coverage.py index 9a1a648b..48acb321 100644 --- a/tools/fresh_validation/check_coverage.py +++ b/tools/fresh_validation/check_coverage.py @@ -23,6 +23,8 @@ from typing import Literal, TypeAlias, TypedDict from unittest.mock import patch +import numpy as np + from traincheck.invariant import read_inv_file from traincheck.invariant.base_cls import ( APIParam, @@ -214,6 +216,36 @@ def identity_scalar(value: object, context: str) -> int | float | str: return result +def dataframe_timestamp(value: object, context: str) -> int | float: + """Convert observed dataframe time scalars to exact, finite JSON numbers. + + Pandas reductions can leave NumPy scalars in AttrState liveness bounds even + when source-event dictionaries contain builtin numbers. Keep integer + nanoseconds as integers, including beyond float64's exact-integer range. + Extended NumPy floating values are accepted only if conversion to Python's + float preserves their value. This boundary does not relax JSON validators. + """ + if isinstance(value, (bool, np.bool_)): + raise ValueError(f"{context} must be a timestamp number, not a boolean") + if isinstance(value, np.integer): + # NumPy also classifies timedelta64 as an integer. A duration's unit + # cannot be inferred as this trace's numeric nanosecond timestamp. + if isinstance(value, np.timedelta64): + raise ValueError(f"{context} must be a timestamp number, not a duration") + return int(value) + if isinstance(value, np.floating): + converted = float(value) + if not math.isfinite(converted) or value != converted: + raise ValueError( + f"{context} must be finite and exactly representable as a Python float" + ) + return converted + result = number(value, context) + if isinstance(result, float) and not math.isfinite(result): + raise ValueError(f"{context} must be finite") + return result + + def variable_value_identity(state: object, param: object) -> VariableValueIdentity: if not isinstance(state, AttrState) or not isinstance(param, VarTypeParam): raise ValueError("Consistency decisions require AttrState and VarTypeParam") @@ -226,9 +258,13 @@ def variable_value_identity(state: object, param: object) -> VariableValueIdenti "var_name": string(required(record, "var_name"), "var_name"), "var_type": string(required(record, "var_type"), "var_type"), "attribute": string(param.attr_name, "attribute"), - "event_time": number(required(record, "time"), "time"), - "liveness_start": number(state.liveness.start_time, "liveness.start_time"), - "liveness_end": number(state.liveness.end_time, "liveness.end_time"), + "event_time": dataframe_timestamp(required(record, "time"), "time"), + "liveness_start": dataframe_timestamp( + state.liveness.start_time, "liveness.start_time" + ), + "liveness_end": dataframe_timestamp( + state.liveness.end_time, "liveness.end_time" + ), } From 1df0ee5d9f3c8d31c58111215dd69f11b35dfba8 Mon Sep 17 00:00:00 2001 From: Yuxuan Jiang Date: Sat, 31 Oct 2026 18:50:45 +0800 Subject: [PATCH 4/4] Record verified Ring18 timestamp and invariant checking results --- .../ring18-parameter-timestamps-20261031.md | 199 ++++++++++++++++++ 1 file changed, 199 insertions(+) create mode 100644 docs/measurements/ring18-parameter-timestamps-20261031.md diff --git a/docs/measurements/ring18-parameter-timestamps-20261031.md b/docs/measurements/ring18-parameter-timestamps-20261031.md new file mode 100644 index 00000000..dcd76546 --- /dev/null +++ b/docs/measurements/ring18-parameter-timestamps-20261031.md @@ -0,0 +1,199 @@ +# Parameter observation timestamp correction on Ring18 + +## Change and measurement scope + +Baseline: `3bdb3ac8566954b187798ae7222189464f28e312` (#166). +Training candidate: `b1d2953ae8688c53fc71a9da1b0a2d138f5a81c7` (#167). +The later coverage-observer correction is separate from the training code; its +revision and rerun are recorded below. No training artifacts are rewritten. + +Registry samples previously reused `last_update_timestamp`, which tracks Python +attribute assignments. In-place optimizer updates need not invoke that hook. +Both parameter trackers now timestamp `sample` and `selective-sample` at the +start of metadata observation, without updating mutation bookkeeping. Assignment, +call, iteration, and observer event timing remains unchanged. Suppressed and +retired variables remain silent; conversion failures still propagate. + +These are observation times, not exact mutation times. The probe deliberately +samples before and after the whole training update. Its after-update sample lies +after `AdamW.step`'s API post-event; this correction does not manufacture an +APIContain relation placing the change inside that call. Concurrent application +mutation during metadata capture remains unsupported. No synthetic timestamp +offsets, row sorting changes, deduplication, or inference rule changes are used. + +## Matched two-GPU experiment + +Ring18 GPUs 0 and 1: NVIDIA A16, PyTorch 2.2.2+cu121, Python 3.10.14. Existing +`DS-1801` environment reused without installation or modification. The unchanged +probe is a 5,504-parameter Transformer (27 parameter tensors), DDP with two +microbatches per update, AdamW, clipping, scheduler, deterministic synthetic +batches, dropout zero, and four updates. Save/resume cases split at update two. +See [the original qualification](ring18-distributed-20261031.md) for the complete +workload and independent global-batch gradient oracle. + +All nine phases completed with exit zero, unchanged source hashes and no +supervisor stop: fresh old-code subclass, fresh plain FP32, candidate subclass +FP32 reference/control/fault, candidate BF16, candidate subclass save, plain +resume from the new subclass checkpoint, and subclass resume from the previous +plain checkpoint. Only idle GPUs were selected. Each phase was bounded to 180 s; +the supervisor's memory accounting covers its process group, not torchrun's +separate worker sessions. These are correctness trials, not an overhead study. + +### Timestamp and record evidence + +The paired FP32 denominator is **216 parameter/update pairs**: 27 parameters × +4 updates × 2 ranks. Each pair has one before and one after record. + +| Measurement | Fresh baseline | Candidate FP32 | +| --- | ---: | ---: | +| Complete before/after pairs | 216/216 | 216/216 | +| Changed data hashes | 216/216 | 216/216 | +| After samples not later than optimizer post-event | 216/216 | 0/216 | +| Before/after timestamps equal despite changed hashes | 54/216 | 0/216 | +| Raw API records, both ranks | 7,504 | 7,504 | +| Raw VAR records, both ranks | 594 | 594 | +| Duplicate API event keys / malformed call pairs | 0 / 0 | 0 / 0 | + +Across all six candidate subclass phases, **1,080/1,080 parameter/update pairs** +have complete samples, changed hashes, strictly increasing sample times, a before +sample preceding optimizer pre, and an after sample following optimizer post. +No missing/duplicate samples, unexpected samples, or malformed API call pairs +were found. Plain phases emitted no trace records. The existing tensor hash +samples the first row; it is not a proof of full tensor equality. + +### Complete application-state evidence + +All **eight complete checkpoint comparisons** pass, covering both ranks and 274 +tensor pairs per comparison. Model parameters, gradients, optimizer state, +scheduler state, saved CPU/CUDA RNG and all provenance fields are compared without +dropping fields or normalizing IDs/values. Whole checkpoint file hashes also +match. The comparisons cover baseline/candidate, plain/candidate, fresh control, +both checkpoint directions, BF16, the faulty training run, and the saved halfway +state. The loader maps tensors to CPU; storage aliasing and original device +placement are not reconstructed by this comparison. + +The independent gradient oracle is unchanged: healthy FP32 maximum error +`4.470348358154297e-08`, healthy BF16 `0.0005645751953125`, faulty local-mean +normalization `0.06958316266536713`. The fault still leaves ranks in exact +parameter agreement. This oracle is separate from TrainCheck invariant checking. + +## Regression validation + +- Same 21 focused tests: old source **8 failed / 13 passed**, candidate **21 passed**. + Tests cover both trackers and sample modes, actual in-place mutations/hashes, + observation-start ordering, RNG/value preservation, unchanged mutation times, + registry staleness, suppression, retired ownership, and conversion exceptions. +- Real SGD API/VAR disk-trace test: old source **1 failed / 2 passed**; fixed + version passes within **66 affected tests** on macOS. This verifies sample + multiplicity, API chronology, changed hashes, and exact model/loss behavior. +- The combined affected suite, including all new regressions, passes on Ring18: + **87 passed in 36.19 s**, with CUDA visible to the existing CUDA-enabled Torch + build. This does not fix the separate CUDA-hidden startup limitation recorded + in the original qualification report. +- Pinned pre-commit hooks pass. Configured mypy passes on 79 core files; both + changed test modules pass strict scoped mypy and explicit pinned Ruff, Black, + and isort checks. Legacy untyped bodies remain outside full checker coverage. + +## Normalization coverage + +The [raw-trace diagnosis](ring18-normalization-coverage-20261031.md) explains the +previous API-only miss and healthy false alarms. The applied normalization scalar +was not traced, numeric loss data was excluded, and current relations do not +encode global-token normalization. Correct timestamp chronology alone does not +supply that missing mathematical contract. + +### Combined API and parameter inference + +Rank-local inference on the corrected full FP32 reference learned 596 rules on +rank 0 and 605 on rank 1, using pandas, one worker, and the same disabled +FunctionLead/FunctionCover families as the original study. These are new frozen +rule sets; they must not be compared by index with the earlier API-only rules. +Inference completed in 31.91 s and 20.13 s respectively (single operational runs, +not a performance comparison). + +The first fresh-control/fault checks each exposed one observer error: +`liveness.end_time must be a number`. Pandas supplies `numpy.int64` from +`Series.max()` for final state endpoints, while the coverage helper accepted only +builtin numeric types. These are valid finite timestamps, not absent state. The +original reports retain that rule as unknown and overall counts as null. + +Observer-only correction `a6232194b5395bbc7417208ac87161510d3ba5d3` validates the +three observed timestamp fields at their dataframe boundary. NumPy integer +nanoseconds remain exact integers, including beyond `2**53`; finite floating +scalars require lossless conversion. Boolean, datetime/duration, missing, +nonfinite and otherwise malformed values remain errors. Generic external JSON +validators, inference logic, and checker predicates are unchanged. + +Two real-pandas lifetime cases fail before this correction. All 55 targeted +coverage tests pass after it locally, including observer-on/off checker-result +parity for both a satisfied and a violated rule, precision, and invalid types. +They also pass on Ring18 (**55 passed in 4.34 s**). The composed local suite for +both fixes passes together (**142 passed in 22.61 s**). The changed reusable tool +and its new tests pass strict scoped mypy plus pinned lint/format checks; the +configured mypy hook does not select tools/tests, so those explicit checks matter. +The fixed checks use a separate `checking-source` snapshot and `analysis-fixed` +outputs, retaining the original failed observations and reusing byte-identical +trace files and frozen rules. No training or inference is repeated for this fix. + +All four corrected checks complete successfully, with no observer/checker errors, +unknown outcomes, or dormant rules: + +| Rank | Rules active | Healthy violations | Fault violations | Fault-only rule identities | +| --- | ---: | ---: | ---: | --- | +| 0 | 596/596 | 9 | 8 | None | +| 1 | 605/605 | 15 | 17 | DistinctArgument rules 240 and 293 | + +Each recovered ConsistencyRelation passes. Every previously completed per-rule +report is exactly unchanged, including decision arrays and IDs; input trace/rule +hash maps match before and after the observer fix. This comparison concerns +per-rule results, not whole-report equality: harness provenance and the formerly +unknown rule necessarily change. Active coverage does not imply every opportunity +was visited, since a checker can stop at a rule's first violation. + +The two rank-1 fault-only alarms concern repeated LayerNorm input metadata at step +4 and Linear input metadata at step 3. Each failing pair has equal serialized +argument dictionaries, including a repeated `_TRAINCHECK_data_ID`, but no numeric +tensor data/hash. Neither rule constrains normalization or its coefficient. +These are observed fault-only metadata signals; the evidence does not establish +that they diagnose normalization, prove allocator reuse, or prove equal numerical +inputs. The healthy violations remain visible. An agent-benefit or reliable +normalization-detection claim is not supported by this pilot. + +## Reproduction and artifacts + +Local evidence root: +`/Users/matt/gitrepos/traincheck/outputs/ring18-timestamp-20261031`. +Remote root: `ring18:/home/yuxuan/experiments/traincheck-timestamp-20261031`. +The previous evidence root remains unchanged. Large traces and checkpoints are +outside Git. `results.json` preserves phase provenance, source hashes, every +sample pair's actual times/hashes, full metrics, and complete comparisons. +`run_matrix.py` records exact commands and chosen GPU usage before every phase; +`audit_results.py` performs the validated audit. Source copies use the previously +verified baseline plus the exact signed commit diff, with all four changed file +hashes verified after upload. An interrupted full archive upload was not used. + +The downloaded `evidence.tar.gz` contains **185 manifest-verified files**, +3,464,265 bytes, SHA256 +`6c18774e8d5611a368e0e28295e15b4703870c697abfb594ffdc9d9b5b01250b`. +It preserves original and corrected coverage outputs as well as training states. +All 161 training-source Python files and all 162 checking-source Python files +match their respective committed revisions exactly. The final process audit +finds no remaining study processes and all eight GPUs idle. See +`retrieval-verification.json`, `fixed-coverage-comparison.json`, and the extracted +`evidence-bundle/evidence/` for verification details. The separate six-log API +audit archive is identified in the normalization report; large new API traces +remain on Ring18 with their hashes recorded in `results.json`. + +Run from the remote root using its existing runtime: + +```sh +PYTHONDONTWRITEBYTECODE=1 /home/yuxuan/miniconda3/envs/DS-1801/bin/python run_matrix.py +PYTHONPATH="$PWD/source" /home/yuxuan/miniconda3/envs/DS-1801/bin/python audit_results.py +``` + +The matrix requires fresh phase output directories and refuses existing ones. +For a new study, copy the source and operator scripts to another isolated root +and update their explicit root constants. Do not overwrite the preserved runs. + +Limits retained: no FSDP, changed topology, partial accumulation windows, +stochastic dropout, DataLoader cursor, FP16 GradScaler, or agent-effect claim.