Fix: flush stdout for nohup, log every sample, add timestamps

evaluate_v2.py

@@ -24,13 +24,14 @@ Changes from v1:
   - Standard-specific KPI checking (3 strategies)
   - Expanded lifecycle operation key matching
   - Saves generated text for error analysis
+  - Flushes stdout on every print (fixes nohup buffering)
 
 Usage:
     python evaluate_v2.py --adapter_path ./output --num_samples 200
     python evaluate_v2.py --adapter_path ./output --num_samples -1
 """
 
-import argparse, json, re, os, sys, math, torch
+import argparse, json, re, os, sys, math, time, torch
 from collections import defaultdict
 from datasets import load_dataset
 from transformers import (
@@ -41,6 +42,11 @@ from transformers import (
 from peft import PeftModel
 
 
+def log(msg: str):
+    """Print with flush so nohup logs update in real time."""
+    print(msg, flush=True)
+
+
 def parse_args():
     p = argparse.ArgumentParser()
     p.add_argument("--base_model", type=str, default="Qwen/Qwen3-8B")
@@ -83,10 +89,8 @@ def try_parse_json(text: str) -> tuple[dict | None, bool]:
 def _num_representations(val: float) -> list[str]:
     """Generate multiple string representations of a numeric value."""
     reps = [str(val)]
-    # Integer form: 99.0 → "99"
     if val == int(val):
         reps.append(str(int(val)))
-    # Also try with fewer/more decimal places
     reps.append(f"{val:.1f}")
     reps.append(f"{val:.0f}")
     return list(set(reps))
@@ -95,25 +99,20 @@ def _num_representations(val: float) -> list[str]:
 def _reliability_representations(rel_pct: float) -> list[str]:
     """Generate all plausible encodings of a reliability percentage."""
     reps = _num_representations(rel_pct)
-    
-    # Packet error rate: 99.999% → 1e-05
     per = 1 - rel_pct / 100
     if per > 0:
-        # Scientific notation forms
         exp = math.floor(math.log10(per))
         mantissa = per / (10 ** exp)
-        reps.append(f"1e-{abs(exp):02d}")  # "1e-07"
-        reps.append(f"1e-{abs(exp)}")       # "1e-7"
-        reps.append(f"{per:.0e}")           # "1e-02"
-        reps.append(f"{per}")               # "0.01"
+        reps.append(f"1e-{abs(exp):02d}")
+        reps.append(f"1e-{abs(exp)}")
+        reps.append(f"{per:.0e}")
+        reps.append(f"{per}")
         if mantissa == 1.0:
             reps.append(f"1e-{abs(exp):02d}")
         else:
             reps.append(f"{mantissa:.1f}e-{abs(exp):02d}")
-        # Also check as fraction
         if per < 1:
             reps.append(f"{per:.10f}".rstrip("0").rstrip("."))
-    
     return list(set(reps))
 
 
@@ -136,54 +135,21 @@ def _find_all_numbers(parsed: dict) -> list[float]:
 
 
 def _check_kpi_direct(parsed: dict, row: dict, flat: str) -> dict:
-    """
-    Direct KPI matching for standards that embed values as-is.
-    Works for: TMF921, intent_3gpp, CAMARA, ETSI ZSM.
-    Handles int/float representation differences (99 vs 99.0).
-    """
+    """Direct KPI matching for TMF921, intent_3gpp, CAMARA, ETSI ZSM."""
     results = {}
-
-    # Latency
-    target_lat = row["latency_ms"]
-    results["has_latency"] = any(rep in flat for rep in _num_representations(target_lat))
-
-    # Reliability (also check PER encoding e.g. 99.999% → 1e-05)
-    target_rel = row["reliability_pct"]
-    results["has_reliability"] = any(rep in flat for rep in _reliability_representations(target_rel))
-
-    # DL Throughput
-    target_dl = row["dl_throughput_mbps"]
-    results["has_dl_throughput"] = any(rep in flat for rep in _num_representations(target_dl))
-
-    # UL Throughput
-    target_ul = row["ul_throughput_mbps"]
-    results["has_ul_throughput"] = any(rep in flat for rep in _num_representations(target_ul))
-
-    # Max UEs
-    target_ues = row["max_ues"]
-    results["has_max_ues"] = any(rep in flat for rep in _num_representations(float(target_ues)))
-
+    results["has_latency"] = any(rep in flat for rep in _num_representations(row["latency_ms"]))
+    results["has_reliability"] = any(rep in flat for rep in _reliability_representations(row["reliability_pct"]))
+    results["has_dl_throughput"] = any(rep in flat for rep in _num_representations(row["dl_throughput_mbps"]))
+    results["has_ul_throughput"] = any(rep in flat for rep in _num_representations(row["ul_throughput_mbps"]))
+    results["has_max_ues"] = any(rep in flat for rep in _num_representations(float(row["max_ues"])))
     return results
 
 
 def _check_kpi_a1_policy(parsed: dict, row: dict, flat: str) -> dict:
-    """
-    A1 Policy KPI checking.
-    
-    A1 policies encode KPIs as 3GPP QoS parameters:
-      - reliability_pct → per (packet error rate): 99.999% → 1e-05
-      - latency_ms → pdb (packet delay budget): mapped via 5QI table, NOT same value
-      - throughput → gfbr/mfbr (guaranteed/maximum flow bitrate): combined, not DL/UL
-      - max_ues → not directly encoded (scope uses groupId)
-    
-    Strategy: check PER for reliability, check gfbr/mfbr presence for throughput,
-    check pdb presence for latency. These are TRANSFORMED values — the model correctly
-    maps intent KPIs to standards-specific parameters.
-    """
+    """A1 Policy: reliability→PER, latency→pdb, throughput→gfbr/mfbr."""
     results = {}
     all_nums = _find_all_numbers(parsed)
 
-    # Reliability: check PER encoding
     target_rel = row["reliability_pct"]
     rel_found = any(rep in flat for rep in _reliability_representations(target_rel))
     if not rel_found:
@@ -194,77 +160,34 @@ def _check_kpi_a1_policy(parsed: dict, row: dict, flat: str) -> dict:
             if per > 0 and n > 0 and abs(n - per) / max(per, 1e-15) < 0.1:
                 rel_found = True; break
     results["has_reliability"] = rel_found
-
-    # Latency: A1 uses pdb (packet delay budget) — check field exists
     results["has_latency"] = '"pdb"' in flat or '"packetdelaybudget"' in flat
-
-    # Throughput: A1 uses gfbr/mfbr — check fields exist
     has_tput = '"gfbr"' in flat or '"mfbr"' in flat or '"guaranteedflowbitrate"' in flat
     results["has_dl_throughput"] = has_tput
     results["has_ul_throughput"] = has_tput
-
-    # Max UEs: A1 uses scope.groupId — check scope exists
     results["has_max_ues"] = '"scope"' in flat or '"groupid"' in flat
-
     return results
 
 
 def _check_kpi_o1_nrm(parsed: dict, row: dict, flat: str) -> dict:
-    """
-    O1 NRM KPI checking.
-    
-    O-RAN O1 NRM translates intent KPIs into radio resource management configs:
-      - No direct KPI values — they become RRM policy ratios, cell parameters, etc.
-      - The correct evaluation is: does the output have the right ManagedElement structure
-        with appropriate NRCellDU, rrmPolicyMemberList, and frequency configs?
-    
-    Strategy: check for presence of key O1 NRM structural elements rather than
-    attempting value matching (which is fundamentally impossible for this standard).
-    """
+    """O1 NRM: structural element presence (KPIs→RRM policies, not direct values)."""
     results = {}
-
-    # Check for key O1 NRM QoS-related structural elements
-    results["has_latency"] = (
-        '"rrmpolicy"' in flat or '"nrcelldu"' in flat
-    )
-    results["has_reliability"] = (
-        '"operationalstate"' in flat or '"administrativestate"' in flat
-    )
-    results["has_dl_throughput"] = (
-        '"bschannelbwdl"' in flat or '"rrmpolicymaxratio"' in flat or '"arfcndl"' in flat
-    )
+    results["has_latency"] = '"rrmpolicy"' in flat or '"nrcelldu"' in flat
+    results["has_reliability"] = '"operationalstate"' in flat or '"administrativestate"' in flat
+    results["has_dl_throughput"] = '"bschannelbwdl"' in flat or '"rrmpolicymaxratio"' in flat or '"arfcndl"' in flat
     results["has_ul_throughput"] = (
         '"bschannelbwul"' in flat or '"rrmpolicymaxratio"' in flat or '"arfcnul"' in flat
-        or '"rrmpolicydedicatedratio"' in flat  # UL often uses dedicated ratio
-    )
-    results["has_max_ues"] = (
-        '"rrmpolicymemberlist"' in flat or '"snssai"' in flat
+        or '"rrmpolicydedicatedratio"' in flat
     )
-
+    results["has_max_ues"] = '"rrmpolicymemberlist"' in flat or '"snssai"' in flat
     return results
 
 
-# Standards where KPIs are directly embedded as numeric values
 DIRECT_KPI_LAYERS = {"tmf921", "intent_3gpp", "camara", "etsi_zsm"}
 
 
 def check_kpi_fields(parsed: dict, row: dict, target_layer: str) -> dict:
-    """
-    Standard-aware KPI checking with three strategies:
-    
-    1. Direct layers (TMF921, 3GPP, CAMARA, ETSI ZSM):
-       KPI values appear directly in JSON — use value matching with int/float tolerance.
-    
-    2. A1 Policy:
-       KPIs are transformed to 3GPP QoS parameters (PER, pdb, gfbr/mfbr).
-       Check transformed encodings + structural field presence.
-    
-    3. O1 NRM:
-       KPIs are translated to radio resource configs (RRM policies, cell parameters).
-       No direct numeric correspondence — evaluate via structural element presence.
-    """
+    """Standard-aware KPI checking: direct / A1 Policy / O1 NRM strategies."""
     flat = json.dumps(parsed).lower()
-
     if target_layer in DIRECT_KPI_LAYERS:
         return _check_kpi_direct(parsed, row, flat)
     elif target_layer == "a1_policy":
@@ -272,7 +195,6 @@ def check_kpi_fields(parsed: dict, row: dict, target_layer: str) -> dict:
     elif target_layer == "o1_nrm":
         return _check_kpi_o1_nrm(parsed, row, flat)
     else:
-        # Unknown layer — fall back to direct matching
         return _check_kpi_direct(parsed, row, flat)
 
 
@@ -295,7 +217,6 @@ LIFECYCLE_LAYERS = {
     "tmf921_lifecycle_monitor", "tmf921_lifecycle_report",
 }
 
-# Expanded lifecycle key matching — more flexible than v1
 LIFECYCLE_KEYS = {
     "tmf921_lifecycle_activate":   ["intentpatch", "intentactivation"],
     "tmf921_lifecycle_modify":     ["intentpatch", "intentupdate", "intentmodification"],
@@ -313,12 +234,10 @@ def check_structure(parsed: dict, target_layer: str) -> bool:
     """Check if the JSON has the expected root keys for the target standard."""
     if target_layer.startswith("adversarial"):
         return parsed.get("status") in ADVERSARIAL_STATUSES
-    
     if target_layer in LIFECYCLE_LAYERS:
         flat_keys = {k.lower() for k in parsed.keys()}
         expected = LIFECYCLE_KEYS.get(target_layer, [])
         return any(k in flat_keys for k in expected)
-    
     expected = LAYER_ROOT_KEYS.get(target_layer, [])
     if not expected:
         return True
@@ -328,38 +247,30 @@ def check_structure(parsed: dict, target_layer: str) -> bool:
 
 # ── Ground-truth baseline ────────────────────────────────────────────
 def compute_gt_baseline(ds):
-    """
-    Run the KPI checker against ground truth outputs to establish metric ceiling.
-    This tells us the maximum score our metric CAN give, even for perfect outputs.
-    """
+    """Run the KPI checker against ground truth to establish metric ceiling."""
     gt_results = defaultdict(lambda: defaultdict(list))
-    
     for row in ds:
         layer = row["target_layer"]
         if layer.startswith("adversarial") or layer in LIFECYCLE_LAYERS:
             continue
-        
         gt_text = row["messages"][-1]["content"]
         parsed, valid = try_parse_json(gt_text)
         if not parsed:
             continue
-        
         kpi = check_kpi_fields(parsed, row, layer)
         for k, v in kpi.items():
             gt_results[layer][k].append(v)
-    
-    print("\n  Ground-truth baseline (metric ceiling — should be 100% for all):")
-    print(f"  {'Layer':<20} {'latency':>8} {'reliab':>8} {'dl_tput':>8} {'ul_tput':>8} {'max_ues':>8}")
-    print("  " + "─" * 55)
-    
+
+    log("\n  Ground-truth baseline (metric ceiling — should be 100% for all):")
+    log(f"  {'Layer':<20} {'latency':>8} {'reliab':>8} {'dl_tput':>8} {'ul_tput':>8} {'max_ues':>8}")
+    log("  " + "─" * 55)
     for layer in sorted(gt_results.keys()):
         metrics = gt_results[layer]
         def rate(key):
             vals = metrics.get(key, [])
             return sum(vals) / len(vals) * 100 if vals else 0
-        print(f"  {layer:<20} {rate('has_latency'):>7.1f}% {rate('has_reliability'):>7.1f}% "
-              f"{rate('has_dl_throughput'):>7.1f}% {rate('has_ul_throughput'):>7.1f}% {rate('has_max_ues'):>7.1f}%")
-    
+        log(f"  {layer:<20} {rate('has_latency'):>7.1f}% {rate('has_reliability'):>7.1f}% "
+            f"{rate('has_dl_throughput'):>7.1f}% {rate('has_ul_throughput'):>7.1f}% {rate('has_max_ues'):>7.1f}%")
     return gt_results
 
 
@@ -367,37 +278,36 @@ def compute_gt_baseline(ds):
 def main():
     args = parse_args()
 
-    print("=" * 70)
-    print("TMF921 Intent Translation — Evaluation v2")
-    print("=" * 70)
-    print(f"Base model   : {args.base_model}")
-    print(f"Adapter      : {args.adapter_path}")
-    print(f"Dataset      : {args.dataset} [{args.split}]")
-    print(f"Num samples  : {args.num_samples}")
-    print(f"KPI checking : standard-aware (v2)")
-    print("=" * 70)
+    log("=" * 70)
+    log("TMF921 Intent Translation — Evaluation v2")
+    log("=" * 70)
+    log(f"Base model   : {args.base_model}")
+    log(f"Adapter      : {args.adapter_path}")
+    log(f"Dataset      : {args.dataset} [{args.split}]")
+    log(f"Num samples  : {args.num_samples}")
+    log(f"KPI checking : standard-aware (v2)")
+    log("=" * 70)
 
     # Load dataset
-    print("\nLoading dataset …")
+    log("\nLoading dataset …")
     ds = load_dataset(args.dataset, split=args.split)
-    
+
     # Compute ground-truth baseline on full test set
-    print("\nComputing ground-truth metric baseline …")
+    log("\nComputing ground-truth metric baseline …")
     gt_baseline = compute_gt_baseline(ds)
-    
+
     if args.num_samples > 0:
         ds = ds.select(range(min(args.num_samples, len(ds))))
-    print(f"\n  Evaluating on {len(ds)} samples")
+    log(f"\n  Evaluating on {len(ds)} samples")
 
     # Load model
-    print("\nLoading model …")
+    log("\nLoading model …")
     bnb_config = BitsAndBytesConfig(
         load_in_4bit=True,
         bnb_4bit_quant_type="nf4",
         bnb_4bit_compute_dtype=torch.bfloat16,
         bnb_4bit_use_double_quant=True,
     )
-
     model_kwargs = {
         "quantization_config": bnb_config,
         "device_map": "auto",
@@ -406,32 +316,30 @@ def main():
     if args.flash_attn:
         model_kwargs["attn_implementation"] = "flash_attention_2"
 
-    base_model = AutoModelForCausalLM.from_pretrained(
-        args.base_model, **model_kwargs
-    )
+    base_model = AutoModelForCausalLM.from_pretrained(args.base_model, **model_kwargs)
     model = PeftModel.from_pretrained(base_model, args.adapter_path)
     model.eval()
 
-    tokenizer = AutoTokenizer.from_pretrained(
-        args.base_model, trust_remote_code=True
-    )
+    tokenizer = AutoTokenizer.from_pretrained(args.base_model, trust_remote_code=True)
     if tokenizer.pad_token is None:
         tokenizer.pad_token = tokenizer.eos_token
 
+    log("✅ Model loaded successfully")
+    log(f"\nStarting inference on {len(ds)} samples …")
+    log(f"  (First sample may take 1-2 min for CUDA warmup)\n")
+
     # Evaluate
-    print("\nRunning inference …")
     results = []
     per_layer = defaultdict(lambda: defaultdict(list))
+    t_start = time.time()
 
     for i, row in enumerate(ds):
-        if (i + 1) % 20 == 0 or i == 0:
-            print(f"  [{i+1}/{len(ds)}] …")
+        t0 = time.time()
 
         messages = row["messages"]
         target_layer = row["target_layer"]
         reference_output = messages[-1]["content"]
 
-        # Build prompt (system + user only)
         prompt_messages = [m for m in messages if m["role"] != "assistant"]
         input_text = tokenizer.apply_chat_template(
             prompt_messages, tokenize=False, add_generation_prompt=True
@@ -450,7 +358,6 @@ def main():
         generated_ids = output_ids[0][inputs["input_ids"].shape[1]:]
         generated_text = tokenizer.decode(generated_ids, skip_special_tokens=True)
 
-        # Parse & validate
         parsed, is_valid_json = try_parse_json(generated_text)
         has_correct_structure = check_structure(parsed, target_layer) if parsed else False
 
@@ -472,20 +379,35 @@ def main():
         if args.save_generations:
             result["generated_text"] = generated_text
             result["reference_text"] = reference_output
-        
+
         results.append(result)
 
-        # Accumulate per-layer
         layer_key = target_layer
         per_layer[layer_key]["json_valid"].append(is_valid_json)
         per_layer[layer_key]["structure_correct"].append(has_correct_structure)
         for k, v in kpi_results.items():
             per_layer[layer_key][k].append(v)
 
+        # Progress logging — every sample with ETA
+        elapsed = time.time() - t_start
+        sample_time = time.time() - t0
+        avg_time = elapsed / (i + 1)
+        remaining = avg_time * (len(ds) - i - 1)
+        eta_h, eta_m = divmod(int(remaining), 3600)
+        eta_m = eta_m // 60
+
+        json_ok = "✓" if is_valid_json else "✗"
+        struct_ok = "✓" if has_correct_structure else "✗"
+        log(f"  [{i+1:>4}/{len(ds)}] {target_layer:<25} JSON:{json_ok} Struct:{struct_ok} "
+            f"| {sample_time:.1f}s | ETA: {eta_h}h{eta_m:02d}m")
+
     # ── Aggregate metrics ────────────────────────────────────────────
-    print("\n" + "=" * 70)
-    print("RESULTS (v2 — standard-aware KPI matching)")
-    print("=" * 70)
+    total_time = time.time() - t_start
+    log(f"\n  Total inference time: {total_time/3600:.1f}h ({total_time/len(ds):.1f}s/sample)")
+
+    log("\n" + "=" * 70)
+    log("RESULTS (v2 — standard-aware KPI matching)")
+    log("=" * 70)
 
     total_valid = sum(1 for r in results if r["json_valid"])
     total_struct = sum(1 for r in results if r["structure_correct"])
@@ -506,14 +428,12 @@ def main():
         all_kpi = [all(r.get(f, False) for f in kpi_fields) for r in kpi_samples]
         overall["all_kpis_correct_rate"] = sum(all_kpi) / len(all_kpi)
 
-    # Adversarial
     adv_results = [r for r in results if r["target_layer"].startswith("adversarial")]
     if adv_results:
         adv_correct = sum(1 for r in adv_results if r["json_valid"] and r["structure_correct"])
         overall["adversarial_accuracy"] = adv_correct / len(adv_results)
         overall["adversarial_samples"] = len(adv_results)
 
-    # Per-layer breakdown
     layer_summary = {}
     for layer, metrics in sorted(per_layer.items()):
         layer_n = len(metrics["json_valid"])
@@ -526,34 +446,31 @@ def main():
             if k in metrics and metrics[k]:
                 layer_summary[layer][k] = sum(metrics[k]) / len(metrics[k])
 
-    # Print overall
-    print(f"\n{'Metric':<35} {'Value':>10}")
-    print("─" * 47)
+    log(f"\n{'Metric':<35} {'Value':>10}")
+    log("─" * 47)
     for k, v in overall.items():
         if isinstance(v, float):
-            print(f"  {k:<33} {v:>9.1%}")
+            log(f"  {k:<33} {v:>9.1%}")
         else:
-            print(f"  {k:<33} {v:>9}")
+            log(f"  {k:<33} {v:>9}")
 
-    # Print per-layer with all KPI columns
-    print(f"\n{'Layer':<25} {'N':>4} {'JSON':>6} {'Struct':>7} {'Lat':>6} {'Rel':>6} {'DL':>6} {'UL':>6} {'UEs':>6} {'All':>6}")
-    print("─" * 85)
+    log(f"\n{'Layer':<25} {'N':>4} {'JSON':>6} {'Struct':>7} {'Lat':>6} {'Rel':>6} {'DL':>6} {'UL':>6} {'UEs':>6} {'All':>6}")
+    log("─" * 85)
     for layer, m in layer_summary.items():
         def fmt(key):
             return f"{m[key]*100:.0f}%" if key in m else "—"
-        print(f"  {layer:<23} {m['n']:>4} {m['json_valid']*100:>5.0f}% {m['structure_correct']*100:>6.0f}% "
-              f"{fmt('has_latency'):>6} {fmt('has_reliability'):>6} {fmt('has_dl_throughput'):>6} "
-              f"{fmt('has_ul_throughput'):>6} {fmt('has_max_ues'):>6}  ", end="")
-        # All KPIs correct for this layer
+        line = (f"  {layer:<23} {m['n']:>4} {m['json_valid']*100:>5.0f}% {m['structure_correct']*100:>6.0f}% "
+                f"{fmt('has_latency'):>6} {fmt('has_reliability'):>6} {fmt('has_dl_throughput'):>6} "
+                f"{fmt('has_ul_throughput'):>6} {fmt('has_max_ues'):>6}  ")
         layer_results = [r for r in results if r["target_layer"] == layer]
         layer_kpi = [r for r in layer_results if any(k in r for k in kpi_fields)]
         if layer_kpi:
             all_correct = sum(1 for r in layer_kpi if all(r.get(f, False) for f in kpi_fields))
-            print(f"{all_correct/len(layer_kpi)*100:>4.0f}%")
+            line += f"{all_correct/len(layer_kpi)*100:>4.0f}%"
         else:
-            print(f"{'—':>5}")
+            line += f"{'—':>5}"
+        log(line)
 
-    # Save
     output = {
         "config": vars(args),
         "overall": overall,
@@ -562,7 +479,7 @@ def main():
     }
     with open(args.output_file, "w") as f:
         json.dump(output, f, indent=2, default=str)
-    print(f"\n✅ Results saved to {args.output_file}")
+    log(f"\n✅ Results saved to {args.output_file}")
 
 
 if __name__ == "__main__":