Skip to content

Commit 96d5676

Browse files
committed
Harden H1 trace source completeness
1 parent 7da2310 commit 96d5676

4 files changed

Lines changed: 217 additions & 17 deletions

File tree

flagscale/runner/tracing/analyzer.py

Lines changed: 99 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -209,6 +209,7 @@ def scan(
209209
*,
210210
now_monotonic_s: float,
211211
now_unix_ns: int,
212+
trace_source_issues: dict[tuple[int, int], tuple[str, ...]] | None = None,
212213
) -> list[Finding]:
213214
findings: list[Finding] = []
214215
if self.detect_heartbeat_timeouts:
@@ -242,6 +243,7 @@ def scan(
242243
elapsed_s=elapsed_s,
243244
detection_phase=detection_phase,
244245
timeout_s=timeout_s,
246+
trace_source_issues=trace_source_issues,
245247
)
246248
self._emit_once(("collective_missing_enter", *key), missing, findings)
247249

@@ -366,22 +368,23 @@ def _detect_missing_enter(
366368
elapsed_s: float,
367369
detection_phase: str,
368370
timeout_s: float,
371+
trace_source_issues: dict[tuple[int, int], tuple[str, ...]] | None,
369372
) -> Finding:
370373
entered = sorted(collective.enters)
371374
missing = sorted(set(range(collective.expected_nranks)) - set(entered))
372375
members = self._comm_members.get((collective.run_id, collective.comm_uid_hash), {})
373376
rank_status: list[dict[str, Any]] = []
374377
known_states: list[str] = []
375-
trace_event_loss_possible = False
378+
source_states: list[str] = []
376379
for comm_rank in missing:
377380
global_rank = members.get(comm_rank)
378381
status: dict[str, Any] = {"comm_rank": comm_rank, "rank": global_rank}
379382
heartbeat = self._heartbeats.get(global_rank) if global_rank is not None else None
380-
probe_status = self._probe_status.get(global_rank) if global_rank is not None else None
381-
dropped_events = _as_int(
382-
probe_status.get("dropped_events") if probe_status else 0, default=0
383+
source = self._trace_source_status(
384+
global_rank,
385+
trace_source_issues=trace_source_issues,
383386
)
384-
trace_event_loss_possible = trace_event_loss_possible or dropped_events > 0
387+
source_states.append(str(source["status"]))
385388
if heartbeat is None:
386389
status["heartbeat"] = "unknown"
387390
else:
@@ -395,21 +398,35 @@ def _detect_missing_enter(
395398
}
396399
)
397400
known_states.append(state)
398-
status["probe_dropped_events"] = dropped_events
401+
status["probe_dropped_events"] = source["dropped_events"]
402+
status["trace_source"] = source
399403
rank_status.append(status)
400404

401-
if trace_event_loss_possible:
405+
if "unavailable" in source_states:
406+
source_coverage = "insufficient"
407+
reason = "trace_source_unavailable"
408+
confidence = "unknown"
409+
elif "incomplete" in source_states:
410+
source_coverage = "insufficient"
411+
reason = "trace_source_incomplete"
412+
confidence = "unknown"
413+
elif "lossy" in source_states:
414+
source_coverage = "degraded"
402415
reason = "probe_event_loss_possible"
403416
confidence = "suspected"
404-
elif "stale" in known_states:
405-
reason = "rank_exit_or_crash_suspected"
406-
confidence = "suspected"
407-
elif known_states and all(state == "alive" for state in known_states):
408-
reason = "rank_alive_but_not_entered"
409-
confidence = "observed"
410417
else:
411-
reason = "missing_rank_status_unknown"
412-
confidence = "observed"
418+
source_coverage = "sufficient"
419+
if "stale" in known_states:
420+
reason = "rank_exit_or_crash_suspected"
421+
confidence = "suspected"
422+
elif known_states and all(state == "alive" for state in known_states):
423+
reason = "rank_alive_but_not_entered"
424+
confidence = "observed"
425+
else:
426+
reason = "missing_rank_status_unknown"
427+
confidence = "observed"
428+
429+
trace_event_loss_possible = source_coverage != "sufficient"
413430

414431
first_event = next(iter(collective.enters.values()))
415432
return Finding(
@@ -430,10 +447,77 @@ def _detect_missing_enter(
430447
"threshold_reason": self._threshold_reason(detection_phase),
431448
"reason": reason,
432449
"confidence": confidence,
450+
"trace_source_coverage": source_coverage,
433451
"trace_event_loss_possible": trace_event_loss_possible,
434452
},
435453
)
436454

455+
def _trace_source_status(
456+
self,
457+
global_rank: int | None,
458+
*,
459+
trace_source_issues: dict[tuple[int, int], tuple[str, ...]] | None,
460+
) -> dict[str, Any]:
461+
"""Describe whether absence of a trace event is usable evidence."""
462+
463+
issues: list[str] = []
464+
if global_rank is None:
465+
return {
466+
"status": "unavailable",
467+
"pid": None,
468+
"dropped_events": 0,
469+
"issues": ["communicator_rank_not_mapped"],
470+
}
471+
472+
process = self._processes.get(global_rank)
473+
probe_status = self._probe_status.get(global_rank)
474+
process_pid = _as_int(process.event.get("pid"), default=-1) if process is not None else -1
475+
status_pid = (
476+
_as_int(probe_status.get("pid"), default=-1) if probe_status is not None else -1
477+
)
478+
if process is None:
479+
issues.append("process_start_not_observed")
480+
if probe_status is None:
481+
issues.append("probe_status_not_observed")
482+
if process_pid >= 0 and status_pid >= 0 and process_pid != status_pid:
483+
issues.append("probe_status_pid_mismatch")
484+
485+
pid = process_pid if process_pid >= 0 else status_pid
486+
if trace_source_issues is not None and pid >= 0:
487+
source_key = (global_rank, pid)
488+
if source_key not in trace_source_issues:
489+
issues.append("trace_file_not_observed")
490+
else:
491+
issues.extend(trace_source_issues[source_key])
492+
493+
dropped_events = _as_int(
494+
probe_status.get("dropped_events") if probe_status else 0,
495+
default=0,
496+
)
497+
unavailable_issues = {
498+
"process_start_not_observed",
499+
"probe_status_not_observed",
500+
"probe_status_pid_mismatch",
501+
"trace_file_not_observed",
502+
}
503+
if unavailable_issues.intersection(issues):
504+
source_status = "unavailable"
505+
elif issues:
506+
source_status = "incomplete"
507+
elif dropped_events > 0:
508+
source_status = "lossy"
509+
else:
510+
# This proves that the source was loaded and that the collector has
511+
# observed no concrete loss signal. It intentionally does not claim
512+
# continuous writer liveness.
513+
source_status = "available"
514+
return {
515+
"status": source_status,
516+
"pid": pid if pid >= 0 else None,
517+
"dropped_events": dropped_events,
518+
"issues": sorted(set(issues)),
519+
}
520+
437521
def _collective_detection_phase(self, collective: _CollectiveRound) -> str:
438522
"""Return a stable phase for one collective round.
439523

flagscale/runner/tracing/monitor.py

Lines changed: 47 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020
import json
2121
import logging
2222
import os
23+
import re
2324
import signal
2425
import time
2526
from pathlib import Path
@@ -29,6 +30,8 @@
2930

3031
logger = logging.getLogger("flagscale.tracing")
3132

33+
_TRACE_SOURCE_PATTERN = re.compile(r"^rank_(\d+)_pid_(\d+)\.jsonl$")
34+
3235

3336
class JsonlTailer:
3437
"""Incrementally read complete JSON lines from per-process trace files."""
@@ -37,22 +40,55 @@ def __init__(self, trace_dir: Path) -> None:
3740
self.trace_dir = trace_dir
3841
self._offsets: dict[Path, int] = {}
3942
self._remainders: dict[Path, str] = {}
43+
self._source_paths: dict[tuple[int, int], Path] = {}
44+
self._source_issues: dict[tuple[int, int], set[str]] = {}
45+
46+
@staticmethod
47+
def _source_key(path: Path) -> tuple[int, int] | None:
48+
match = _TRACE_SOURCE_PATTERN.fullmatch(path.name)
49+
if match is None:
50+
return None
51+
return int(match.group(1)), int(match.group(2))
52+
53+
def source_issues(self) -> dict[tuple[int, int], tuple[str, ...]]:
54+
"""Return collector-visible source files and permanent/transient issues."""
55+
56+
return {
57+
source: tuple(sorted(self._source_issues.get(source, set())))
58+
for source in self._source_paths
59+
}
4060

4161
def poll(self) -> list[dict]:
4262
events: list[dict] = []
43-
for path in sorted(self.trace_dir.glob("rank_*_pid_*.jsonl")):
63+
paths = sorted(self.trace_dir.glob("rank_*_pid_*.jsonl"))
64+
visible_paths = set(paths)
65+
for source, path in self._source_paths.items():
66+
if path not in visible_paths:
67+
self._source_issues.setdefault(source, set()).add("trace_file_missing")
68+
69+
for path in paths:
70+
source = self._source_key(path)
71+
if source is not None:
72+
self._source_paths[source] = path
73+
issues = self._source_issues.setdefault(source, set())
74+
issues.discard("trace_file_missing")
75+
issues.discard("trace_read_error")
4476
offset = self._offsets.get(path, 0)
4577
try:
4678
size = path.stat().st_size
4779
if size < offset:
4880
offset = 0
4981
self._remainders.pop(path, None)
82+
if source is not None:
83+
issues.add("trace_file_truncated")
5084
with path.open("r", encoding="utf-8", errors="replace") as file_obj:
5185
file_obj.seek(offset)
5286
chunk = file_obj.read()
5387
self._offsets[path] = file_obj.tell()
5488
except OSError as exc:
5589
logger.debug("Could not read %s: %s", path, exc)
90+
if source is not None:
91+
issues.add("trace_read_error")
5692
continue
5793

5894
if not chunk:
@@ -62,14 +98,20 @@ def poll(self) -> list[dict]:
6298
for line in lines:
6399
if not line.endswith(("\n", "\r")):
64100
self._remainders[path] = line
101+
if source is not None:
102+
issues.add("partial_json_record")
65103
continue
66104
try:
67105
event = json.loads(line)
68106
except json.JSONDecodeError:
69107
logger.warning("Ignored malformed trace line in %s", path)
108+
if source is not None:
109+
issues.add("malformed_json_record")
70110
continue
71111
if isinstance(event, dict):
72112
events.append(event)
113+
if source is not None and path not in self._remainders:
114+
issues.discard("partial_json_record")
73115
return events
74116

75117

@@ -112,7 +154,8 @@ def run_monitor(args: argparse.Namespace) -> int:
112154
delayed_enter_threshold_s=args.delayed_enter_threshold,
113155
checkpoint_timeout_s=args.checkpoint_timeout,
114156
)
115-
tailers = [JsonlTailer(trace_dir)]
157+
trace_tailer = JsonlTailer(trace_dir)
158+
tailers = [trace_tailer]
116159
if args.heartbeat_dir:
117160
tailers.append(JsonlTailer(Path(args.heartbeat_dir)))
118161
stopping = False
@@ -140,6 +183,7 @@ def request_stop(_signum, _frame) -> None:
140183
findings = analyzer.scan(
141184
now_monotonic_s=time.monotonic(),
142185
now_unix_ns=time.time_ns(),
186+
trace_source_issues=trace_tailer.source_issues(),
143187
)
144188
_append_findings(output, findings)
145189

@@ -174,6 +218,7 @@ def request_stop(_signum, _frame) -> None:
174218
analyzer.scan(
175219
now_monotonic_s=time.monotonic(),
176220
now_unix_ns=time.time_ns(),
221+
trace_source_issues=trace_tailer.source_issues(),
177222
),
178223
)
179224
break

tests/unit_tests/runner/tracing/test_analyzer.py

Lines changed: 60 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -52,6 +52,11 @@ def _ingest(analyzer, event, observed=1.0, unix_ns=1_000_000_000):
5252
)
5353

5454

55+
def _ingest_probe_source(analyzer, rank, pid=10):
56+
_ingest(analyzer, _event("process_start", rank=rank, pid=pid))
57+
_ingest(analyzer, _event("probe_status", rank=rank, pid=pid, dropped_events=0))
58+
59+
5560
def test_missing_enter_reports_live_missing_rank_without_claiming_crash():
5661
analyzer = TraceAnalyzer(
5762
run_id=RUN_ID,
@@ -60,6 +65,7 @@ def test_missing_enter_reports_live_missing_rank_without_claiming_crash():
6065
)
6166
_ingest(analyzer, _event("comm_init", rank=0, comm_rank=0))
6267
_ingest(analyzer, _event("comm_init", rank=1, comm_rank=1))
68+
_ingest_probe_source(analyzer, rank=1)
6369
_ingest(
6470
analyzer,
6571
_event(
@@ -82,7 +88,9 @@ def test_missing_enter_reports_live_missing_rank_without_claiming_crash():
8288
assert finding.hang_type == "collective_missing_enter"
8389
assert finding.details["missing_comm_ranks"] == [1]
8490
assert finding.details["reason"] == "rank_alive_but_not_entered"
91+
assert finding.details["trace_source_coverage"] == "sufficient"
8592
assert finding.details["missing_rank_status"][0]["heartbeat"] == "alive"
93+
assert finding.details["missing_rank_status"][0]["trace_source"]["status"] == "available"
8694

8795

8896
def test_missing_enter_correlates_a_stale_heartbeat_as_suspected_crash():
@@ -92,6 +100,7 @@ def test_missing_enter_correlates_a_stale_heartbeat_as_suspected_crash():
92100
collective_timeout_s=2,
93101
)
94102
_ingest(analyzer, _event("comm_init", rank=1, comm_rank=1))
103+
_ingest_probe_source(analyzer, rank=1)
95104
_ingest(analyzer, _event("heartbeat", rank=1), observed=1.0)
96105
_ingest(analyzer, _event("nccl_call", rank=0, comm_rank=0), observed=1.0)
97106

@@ -228,6 +237,7 @@ def test_missing_enter_is_downgraded_when_probe_dropped_events():
228237
collective_timeout_s=2,
229238
)
230239
_ingest(analyzer, _event("comm_init", rank=1, comm_rank=1))
240+
_ingest(analyzer, _event("process_start", rank=1))
231241
_ingest(
232242
analyzer,
233243
_event("heartbeat", rank=1),
@@ -240,3 +250,53 @@ def test_missing_enter_is_downgraded_when_probe_dropped_events():
240250

241251
assert findings[0].details["reason"] == "probe_event_loss_possible"
242252
assert findings[0].details["confidence"] == "suspected"
253+
assert findings[0].details["trace_source_coverage"] == "degraded"
254+
255+
256+
def test_missing_enter_is_unknown_when_probe_source_was_not_observed():
257+
analyzer = TraceAnalyzer(
258+
run_id=RUN_ID,
259+
heartbeat_timeout_s=10,
260+
collective_timeout_s=2,
261+
)
262+
_ingest(analyzer, _event("comm_init", rank=1, comm_rank=1))
263+
_ingest(analyzer, _event("heartbeat", rank=1), observed=1)
264+
_ingest(analyzer, _event("nccl_call", rank=0, comm_rank=0), observed=1)
265+
266+
findings = analyzer.scan(now_monotonic_s=5, now_unix_ns=5_000_000_000)
267+
268+
assert findings[0].details["reason"] == "trace_source_unavailable"
269+
assert findings[0].details["confidence"] == "unknown"
270+
assert findings[0].details["trace_source_coverage"] == "insufficient"
271+
source = findings[0].details["missing_rank_status"][0]["trace_source"]
272+
assert source["status"] == "unavailable"
273+
assert source["issues"] == ["probe_status_not_observed", "process_start_not_observed"]
274+
275+
276+
def test_missing_enter_is_unknown_when_trace_file_is_incomplete():
277+
analyzer = TraceAnalyzer(
278+
run_id=RUN_ID,
279+
heartbeat_timeout_s=10,
280+
collective_timeout_s=2,
281+
)
282+
_ingest(analyzer, _event("comm_init", rank=1, comm_rank=1))
283+
_ingest_probe_source(analyzer, rank=1)
284+
_ingest(analyzer, _event("heartbeat", rank=1), observed=1)
285+
_ingest(analyzer, _event("nccl_call", rank=0, comm_rank=0), observed=1)
286+
287+
findings = analyzer.scan(
288+
now_monotonic_s=5,
289+
now_unix_ns=5_000_000_000,
290+
trace_source_issues={(1, 10): ("partial_json_record",)},
291+
)
292+
293+
assert findings[0].details["reason"] == "trace_source_incomplete"
294+
assert findings[0].details["confidence"] == "unknown"
295+
assert findings[0].details["trace_source_coverage"] == "insufficient"
296+
source = findings[0].details["missing_rank_status"][0]["trace_source"]
297+
assert source == {
298+
"status": "incomplete",
299+
"pid": 10,
300+
"dropped_events": 0,
301+
"issues": ["partial_json_record"],
302+
}

0 commit comments

Comments
 (0)