scripts/gen_fig_sft_training_dynamics.py

#!/usr/bin/env python3
"""Generate publication-quality CodePin SFT training figures from archived logs."""

from __future__ import annotations

import argparse
import csv
import json
import math
import re
from pathlib import Path

import matplotlib.pyplot as plt
import numpy as np
from matplotlib.ticker import FuncFormatter, MaxNLocator


ANSI_RE = re.compile(r"\x1b\[[0-9;]*[A-Za-z]")
STEP_BLOCK_RE = re.compile(r"Step\s+(\d+):\s*\n(.*?\{.*?\})", re.DOTALL)
PAIR_RE = re.compile(r"'([^']+)':\s*'?([-+0-9.eE]+)'?")

BLUE = "#0072B2"
SKY = "#56B4E9"
GREEN = "#009E73"
ORANGE = "#E69F00"
VERMILLION = "#D55E00"
PINK = "#CC79A7"
GRAY = "#7A7A7A"
LIGHT_GRAY = "#D6D9DC"
INK = "#24292F"


def parse_log(path: Path) -> dict[int, dict[str, float]]:
    text = ANSI_RE.sub("", path.read_text(encoding="utf-8", errors="replace"))
    records: dict[int, dict[str, float]] = {}
    for _, block in STEP_BLOCK_RE.findall(text):
        values = {key: float(value) for key, value in PAIR_RE.findall(block)}
        if "train/global_step" in values:
            records[int(values["train/global_step"])] = values
    return records


def rolling(values: np.ndarray, window: int, reducer=np.median) -> np.ndarray:
    output = np.empty_like(values, dtype=float)
    radius = window // 2
    for index in range(len(values)):
        lo = max(0, index - radius)
        hi = min(len(values), index + radius + 1)
        output[index] = reducer(values[lo:hi])
    return output


def ema(values: np.ndarray, alpha: float = 0.08) -> np.ndarray:
    output = np.empty_like(values, dtype=float)
    output[0] = values[0]
    for index in range(1, len(values)):
        output[index] = alpha * values[index] + (1.0 - alpha) * output[index - 1]
    return output


def scheduled_lr(steps: np.ndarray, peak: float = 5e-5, warmup: int = 71, total: int = 710) -> np.ndarray:
    result = np.zeros_like(steps, dtype=float)
    for index, step in enumerate(steps):
        if step <= warmup:
            result[index] = peak * step / warmup
        else:
            progress = min(1.0, (step - warmup) / (total - warmup))
            result[index] = peak * 0.5 * (1.0 + math.cos(math.pi * progress))
    return result


def configure_style() -> None:
    plt.rcParams.update(
        {
            "font.family": "sans-serif",
            "font.sans-serif": ["Inter", "Arial", "DejaVu Sans"],
            "font.size": 8.8,
            "axes.titlesize": 10,
            "axes.titleweight": "bold",
            "axes.labelsize": 8.5,
            "legend.fontsize": 7.4,
            "legend.frameon": False,
            "figure.dpi": 180,
            "savefig.dpi": 300,
            "savefig.bbox": "tight",
            "axes.spines.top": False,
            "axes.spines.right": False,
            "axes.edgecolor": "#555555",
            "axes.linewidth": 0.7,
            "axes.grid": True,
            "grid.alpha": 0.18,
            "grid.linestyle": "-",
            "grid.linewidth": 0.55,
            "lines.linewidth": 1.6,
            "xtick.labelsize": 7.8,
            "ytick.labelsize": 7.8,
            "pdf.fonttype": 42,
            "ps.fonttype": 42,
        }
    )


def panel_label(ax: plt.Axes, label: str) -> None:
    ax.text(
        0.015,
        0.975,
        label,
        transform=ax.transAxes,
        fontweight="bold",
        fontsize=9.5,
        va="top",
        ha="left",
        bbox={"facecolor": "white", "edgecolor": "none", "alpha": 0.78, "pad": 1.2},
        zorder=10,
    )


def save_metrics_csv(path: Path, steps: np.ndarray, arrays: dict[str, np.ndarray]) -> None:
    fieldnames = ["step", *arrays.keys()]
    with path.open("w", encoding="utf-8", newline="") as handle:
        writer = csv.DictWriter(handle, fieldnames=fieldnames)
        writer.writeheader()
        for index, step in enumerate(steps):
            row = {"step": int(step)}
            for key, values in arrays.items():
                value = values[index]
                row[key] = str(value) if isinstance(value, str) else float(value)
            writer.writerow(row)


def stats(values: np.ndarray) -> dict[str, float]:
    return {
        "min": float(np.min(values)),
        "median": float(np.median(values)),
        "p95": float(np.percentile(values, 95)),
        "max": float(np.max(values)),
    }


def main() -> None:
    parser = argparse.ArgumentParser()
    parser.add_argument("--run-dir", type=Path, required=True)
    parser.add_argument("--output-dir", type=Path, default=Path("figures"))
    args = parser.parse_args()
    run_dir = args.run_dir.resolve()
    output_dir = args.output_dir.resolve()
    output_dir.mkdir(parents=True, exist_ok=True)

    initial = parse_log(run_dir / "logs/main.log")
    successful_resume = parse_log(run_dir / "logs/main_resume3.log")
    records = {step: values for step, values in initial.items() if step <= 400}
    records.update({step: values for step, values in successful_resume.items() if step >= 401})
    expected = set(range(1, 711))
    if set(records) != expected:
        missing = sorted(expected - set(records))
        extra = sorted(set(records) - expected)
        raise RuntimeError(f"Expected exactly steps 1..710; missing={missing}, extra={extra}")

    steps = np.arange(1, 711)

    def series(key: str) -> np.ndarray:
        return np.asarray([records[int(step)][key] for step in steps], dtype=float)

    loss = series("train/loss")
    grad_norm = series("train/grad_norm")
    padded_length = series("train/batch_padded_seq_len")
    actual_tokens = series("train/actual_num_tokens")
    throughput = series("train/tokens_per_second_per_gpu")
    step_time = series("timing/step")
    forward_backward_time = series("timing/forward_backward")
    optimizer_time = series("timing/optim_step")
    data_time = series("timing/data_loading")
    cumulative_tokens = np.cumsum(actual_tokens)
    padding_efficiency = actual_tokens / (8.0 * padded_length)
    learning_rate = scheduled_lr(steps)

    arrays = {
        "loss": loss,
        "grad_norm": grad_norm,
        "padded_sequence_length": padded_length,
        "actual_tokens": actual_tokens,
        "padding_efficiency": padding_efficiency,
        "tokens_per_second_per_gpu": throughput,
        "step_time_seconds": step_time,
        "forward_backward_seconds": forward_backward_time,
        "optimizer_step_seconds": optimizer_time,
        "data_loading_seconds": data_time,
        "cumulative_actual_tokens": cumulative_tokens,
        "reconstructed_learning_rate": learning_rate,
    }
    save_metrics_csv(output_dir / "sft_training_metrics.csv", steps, arrays)

    long_mask = padded_length >= 7500
    step_507_index = 506
    step_640_index = 639
    summary = {
        "status": "PASS",
        "trajectory_construction": {
            "description": "one continuous sequence of unique successful optimizer steps",
            "unique_steps": 710,
            "duplicate_failed_attempts_excluded": True,
        },
        "optimization": {
            "loss": stats(loss),
            "loss_first_50_median": float(np.median(loss[:50])),
            "loss_last_50_median": float(np.median(loss[-50:])),
            "loss_final": float(loss[-1]),
            "final_eval_loss": 0.2157,
            "grad_norm": stats(grad_norm),
            "grad_norm_last_50_median": float(np.median(grad_norm[-50:])),
        },
        "data_and_context": {
            "total_actual_tokens": int(cumulative_tokens[-1]),
            "padded_sequence_length": stats(padded_length),
            "batches_at_least_7500_tokens": int(long_mask.sum()),
            "max_length_step": int(steps[np.argmax(padded_length)]),
            "padding_efficiency": stats(padding_efficiency),
        },
        "systems": {
            "throughput_tokens_per_second_per_gpu": stats(throughput),
            "step_time_seconds": stats(step_time),
            "optimizer_time_seconds": stats(optimizer_time),
            "sequence_length_vs_step_time_pearson_r": float(np.corrcoef(padded_length, step_time)[0, 1]),
            "sequence_length_vs_throughput_pearson_r": float(np.corrcoef(padded_length, throughput)[0, 1]),
        },
        "critical_batches": {
            "step_507": {key: float(values[step_507_index]) for key, values in {
                "loss": loss,
                "grad_norm": grad_norm,
                "padded_sequence_length": padded_length,
                "actual_tokens": actual_tokens,
                "tokens_per_second_per_gpu": throughput,
                "step_time_seconds": step_time,
            }.items()},
            "step_640_max_length": {key: float(values[step_640_index]) for key, values in {
                "loss": loss,
                "grad_norm": grad_norm,
                "padded_sequence_length": padded_length,
                "tokens_per_second_per_gpu": throughput,
                "step_time_seconds": step_time,
            }.items()},
        },
        "limitations": [
            "No continuous validation series was logged because eval_interval=0; only final eval_loss=0.2157 is available.",
            "No per-step GPU memory/utilization telemetry was recorded, so memory curves are not inferred.",
            "Learning rate is reconstructed from the declared 71-step warmup and 710-step cosine schedule.",
        ],
    }
    (output_dir / "sft_training_summary.json").write_text(
        json.dumps(summary, indent=2) + "\n", encoding="utf-8"
    )

    configure_style()
    fig, axes = plt.subplots(2, 3, figsize=(10.5, 6.25), constrained_layout=False)
    fig.subplots_adjust(left=0.075, right=0.96, bottom=0.09, top=0.82, wspace=0.36, hspace=0.42)
    axes = axes.ravel()

    ax = axes[0]
    ax.plot(steps, loss, color=SKY, alpha=0.28, linewidth=0.7, label="per-step")
    ax.plot(steps, ema(loss), color=BLUE, linewidth=1.9, label="EMA (α=0.08)")
    ax.axhline(0.2157, color=VERMILLION, linestyle=(0, (4, 2)), linewidth=1.1, label="final eval = 0.2157")
    ax.scatter([710], [loss[-1]], color=BLUE, edgecolor="white", linewidth=0.6, s=28, zorder=5)
    ax.annotate("0.1577", (710, loss[-1]), xytext=(-7, 7), textcoords="offset points", ha="right", fontsize=7, color=BLUE)
    ax.set_title("Optimization objective")
    ax.set_ylabel("Token-level SFT loss")
    ax.set_ylim(0, max(0.62, np.percentile(loss, 99) * 1.08))
    ax.legend(loc="upper right", ncol=1)
    panel_label(ax, "a")

    ax = axes[1]
    ax.plot(steps, grad_norm, color=ORANGE, alpha=0.25, linewidth=0.7, label="per-step")
    ax.plot(steps, rolling(grad_norm, 25), color=VERMILLION, linewidth=1.8, label="rolling median (25)")
    peak_index = int(np.argmax(grad_norm))
    ax.scatter(steps[peak_index], grad_norm[peak_index], color=VERMILLION, s=22, zorder=5)
    ax.annotate(
        f"peak {grad_norm[peak_index]:.1f}",
        (steps[peak_index], grad_norm[peak_index]),
        xytext=(14, -2),
        textcoords="offset points",
        fontsize=7,
        color=VERMILLION,
    )
    ax.set_yscale("log")
    ax.set_title("Gradient stability")
    ax.set_ylabel("Global gradient norm (log)")
    ax.legend(loc="upper right")
    panel_label(ax, "b")

    ax = axes[2]
    ax.axhspan(7500, 8192, color=VERMILLION, alpha=0.08, linewidth=0)
    ax.plot(steps, padded_length, color=BLUE, alpha=0.62, linewidth=0.85)
    ax.scatter(steps[long_mask], padded_length[long_mask], color=VERMILLION, s=15, zorder=4, label="≥7,500 tokens")
    ax.axhline(8192, color=INK, linestyle=(0, (2, 2)), linewidth=0.8, alpha=0.7, label="8,192 limit")
    ax.scatter([507], [padded_length[step_507_index]], marker="*", color=ORANGE, edgecolor=INK, linewidth=0.35, s=58, zorder=6)
    ax.annotate(
        "long batch\n8,106 tokens",
        (507, padded_length[step_507_index]),
        xytext=(-54, -31),
        textcoords="offset points",
        arrowprops={"arrowstyle": "-", "color": GRAY, "linewidth": 0.7},
        fontsize=7,
        color=INK,
    )
    ax.set_title("Long-context exposure")
    ax.set_ylabel("Padded sequence length")
    ax.set_ylim(3000, 8400)
    ax.yaxis.set_major_locator(MaxNLocator(5))
    ax.legend(loc="lower right")
    panel_label(ax, "c")

    ax = axes[3]
    ax.plot(steps, throughput, color=SKY, alpha=0.30, linewidth=0.7, label="per-step")
    ax.plot(steps, rolling(throughput, 25), color=BLUE, linewidth=1.8, label="rolling median (25)")
    throughput_median = float(np.median(throughput))
    ax.axhline(throughput_median, color=INK, linestyle=(0, (2, 2)), linewidth=0.9)
    ax.text(700, throughput_median + 5, f"median {throughput_median:.1f}", fontsize=7, ha="right", color=INK)
    ax.set_title("Training throughput")
    ax.set_ylabel("Tokens / s / GPU")
    ax.legend(loc="lower left")
    panel_label(ax, "d")

    ax = axes[4]
    ax.plot(steps, step_time, color=LIGHT_GRAY, alpha=0.75, linewidth=0.7, label="step time")
    ax.plot(steps, rolling(step_time, 25), color=INK, linewidth=1.8, label="step rolling median")
    ax.scatter([507], [step_time[step_507_index]], color=VERMILLION, marker="*", s=50, zorder=5)
    ax.annotate("53.5 s", (507, step_time[step_507_index]), xytext=(7, -2), textcoords="offset points", fontsize=7, color=VERMILLION)
    ax2 = ax.twinx()
    ax2.plot(steps, rolling(optimizer_time, 25), color=GREEN, linewidth=1.25, linestyle=(0, (4, 2)), label="optimizer rolling median")
    ax2.set_ylabel("Optimizer step (s)", color=GREEN)
    ax2.tick_params(axis="y", colors=GREEN, labelsize=7.5)
    ax2.spines["right"].set_visible(True)
    ax2.spines["right"].set_color(GREEN)
    lines, labels = ax.get_legend_handles_labels()
    lines2, labels2 = ax2.get_legend_handles_labels()
    ax.legend(lines + lines2, labels + labels2, loc="upper left")
    ax.set_title("Step-time decomposition")
    ax.set_ylabel("End-to-end step time (s)")
    panel_label(ax, "e")

    ax = axes[5]
    ax.plot(steps, padding_efficiency, color=ORANGE, alpha=0.25, linewidth=0.7, label="per-step efficiency")
    ax.plot(steps, rolling(padding_efficiency, 25), color=VERMILLION, linewidth=1.8, label="rolling median (25)")
    ax.set_ylim(0.45, 0.9)
    ax.set_ylabel("Non-padding token ratio")
    ax2 = ax.twinx()
    ax2.plot(steps, learning_rate * 1e5, color=PINK, linestyle=(0, (4, 2)), linewidth=1.25, label="cosine LR")
    ax2.set_ylabel("Learning rate (×10⁻⁵)", color=PINK)
    ax2.tick_params(axis="y", colors=PINK, labelsize=7.5)
    ax2.spines["right"].set_visible(True)
    ax2.spines["right"].set_color(PINK)
    lines, labels = ax.get_legend_handles_labels()
    lines2, labels2 = ax2.get_legend_handles_labels()
    ax.legend(lines + lines2, labels + labels2, loc="lower right")
    ax.set_title(f"Packing efficiency and LR · {cumulative_tokens[-1] / 1e6:.2f}M tokens")
    panel_label(ax, "f")

    for ax in axes:
        ax.set_xlim(1, 710)
        ax.set_xlabel("Optimizer step")
        ax.xaxis.set_major_locator(MaxNLocator(6, integer=True))

    fig.suptitle(
        "CodePin-SFT · Qwen3.5-0.8B Full-Parameter Training Dynamics",
        fontsize=12.5,
        fontweight="bold",
        y=0.965,
    )
    fig.text(
        0.5,
        0.915,
        "4× V100 32GB · FSDP FP16 · global batch 8 · max context 8,192 · 710 steps",
        ha="center",
        va="top",
        fontsize=8.5,
        color=GRAY,
    )
    fig.savefig(output_dir / "fig_sft_training_dynamics.pdf")
    fig.savefig(output_dir / "fig_sft_training_dynamics.png", dpi=300)
    plt.close(fig)

    # Systems figure: expose the length-dependent cost across the continuous run.
    fig, axes = plt.subplots(1, 2, figsize=(7.4, 3.05), constrained_layout=True)
    for ax, y, ylabel, title in [
        (axes[0], step_time, "Step time (s)", "Sequence length drives wall time"),
        (axes[1], throughput, "Tokens / s / GPU", "Per-GPU throughput under variable packing"),
    ]:
        regular = ~long_mask
        ax.scatter(padded_length[regular], y[regular], s=11, color=SKY, alpha=0.45, edgecolors="none", label="all steps")
        ax.scatter(padded_length[long_mask], y[long_mask], s=18, color=ORANGE, alpha=0.78, edgecolors="none", label="≥7,500 tokens")
        slope, intercept = np.polyfit(padded_length, y, 1)
        xline = np.linspace(float(padded_length.min()), float(padded_length.max()), 100)
        ax.plot(xline, slope * xline + intercept, color=BLUE, linewidth=1.7, label="linear fit")
        ax.scatter(
            [padded_length[step_507_index]],
            [y[step_507_index]],
            marker="*",
            s=65,
            color=VERMILLION,
            edgecolor=INK,
            linewidth=0.35,
            zorder=6,
            label="step 507",
        )
        ax.axvspan(7500, 8192, color=VERMILLION, alpha=0.06, linewidth=0)
        ax.set_xlabel("Padded sequence length")
        ax.set_ylabel(ylabel)
        ax.set_title(title)
        ax.xaxis.set_major_formatter(FuncFormatter(lambda value, _: f"{value / 1000:.0f}k"))
        ax.legend(loc="best")
    panel_label(axes[0], "a")
    panel_label(axes[1], "b")
    fig.suptitle("Length-Dependent Training Behavior on 4× V100", fontsize=11.5, fontweight="bold")
    fig.savefig(output_dir / "fig_sft_length_efficiency.pdf")
    fig.savefig(output_dir / "fig_sft_length_efficiency.png", dpi=300)
    plt.close(fig)

    print(json.dumps({
        "outputs": [
            "fig_sft_training_dynamics.pdf",
            "fig_sft_training_dynamics.png",
            "fig_sft_length_efficiency.pdf",
            "fig_sft_length_efficiency.png",
            "sft_training_metrics.csv",
            "sft_training_summary.json",
        ],
        "summary": summary,
    }, indent=2))


if __name__ == "__main__":
    main()