thinking-machines-lab/tinker-cookbook/debug

Tinker Debug

Systematic triage for training and deployment issues. Five triage paths:

1. Performance issues — slow steps, hanging sessions, throughput problems
2. Output correctness issues — mismatches between Tinker sampling and external inference engines
3. Service availability — "is Tinker down?" quick diagnostics
4. Renderer issues — wrong tokens, training quality degradation, prompt mismatches
5. Error message decoder — mapping opaque errors to root causes

Identify which category the user's problem falls into, then follow the appropriate triage.

How the Tinker SDK works (essential context)

Understanding the SDK's threading model is key to diagnosing most issues. The SDK runs a background thread with its own asyncio event loop. All network I/O, heartbeats, and API result polling happen on this thread.

┌─────────────────────┐     ┌──────────────────────────────┐
│     Main Thread      │     │      SDK Background Thread    │
│  (user code)         │     │  (asyncio event loop)         │
│                      │     │                               │
│  fb = tc.fwd_bwd_   │────>│  HTTP POST /forward_backward  │
│       async(data)    │     │  → returns request_id         │
│                      │     │                               │
│  # prepare next      │     │  Long-poll /retrieve_future   │
│  # batch here...     │     │  (HTTP 408 = not ready yet)   │
│                      │     │                               │
│  result = fb.result()│<────│  Result arrives → resolve     │
│  # blocks until done │     │                               │
│                      │     │  Heartbeat every 10s          │
└─────────────────────┘     └──────────────────────────────┘

When you call forward_backward_async(), the SDK:

1. Submits the request coroutine to the background thread
2. Returns a future immediately (main thread continues)
3. Background thread sends HTTP request, starts long-polling for result
4. Calling .result() on the future blocks main thread until the background thread resolves it

Why this matters for debugging: The background thread shares the Python GIL with the main thread. If user code holds the GIL for extended periods (heavy numpy/torch computation, CPU-bound data processing, slow serialization), the background thread cannot:

• Send heartbeats (sessions can expire after missed heartbeats)
• Poll for API results (futures appear to "hang")
• Submit new requests (pipelining breaks)

This means "my training is slow/hanging" is often caused by the user's own code blocking the SDK's background thread via GIL contention — not a network or server issue.

Triage order

Work through these steps in order. Most issues are caught in steps 1-3 and never need deep profiling.

Step 1: Environment check

Bad dependency versions are a silent killer. Check these first because they're fast to verify and cause mysterious slowdowns that look like service issues.

import sys, pydantic, tinker
print(f"Python: {sys.version}")
print(f"pydantic: {pydantic.__version__}")
print(f"tinker SDK: {tinker.__version__}")
try:
    import torch; print(f"torch: {torch.__version__}")
except ImportError: pass
try:
    import numpy; print(f"numpy: {numpy.__version__}")
except ImportError: pass
try:
    import transformers; print(f"transformers: {transformers.__version__}")
except ImportError: pass

Known problem versions:

• pydantic >= 2.13.0b1 (beta): Serialization regression makes model_dump() extremely slow on large payloads (tokens/tensors). Symptom: SDK thread stalls for minutes on forward_backward submission. Fix: pin pydantic<2.13 or use a stable release.
• transformers == 5.3.0: Incorrect tokenizer_class for DeepSeek V2/V3 models (huggingface/transformers#44801, fixed in 5.3.1). Causes tokenizer loading failures. Upgrade or skip this version.
• transformers < 5.0: Bug in Qwen2VLImageProcessor that miscounts image tokens for VL models. Fix: upgrade to >=5.0.
• Always check if the user is on the latest stable tinker SDK. Suggest pip install --upgrade tinker.

If the user has a beta or pre-release of any core dependency, that's the likely culprit. Suggest downgrading before deeper investigation.

Step 2: Async pipelining check

The single most common performance mistake. If the user's code awaits each API call before submitting the next, the GPU sits idle between steps.

Ask the user to share their training loop code, then look for these anti-patterns:

# BAD: sequential — GPU idle while client prepares next call
result = tc.forward_backward(data=batch, loss_fn="cross_entropy")  # blocks
tc.optim_step(adam_params=params)  # blocks
# BAD: async but still sequential
result = await tc.forward_backward_async(data=batch, loss_fn="cross_entropy")
await tc.optim_step_async(adam_params=params)
# GOOD: pipelined — submit both before awaiting
fb_future = tc.forward_backward_async(data=batch, loss_fn="cross_entropy")
optim_future = tc.optim_step_async(adam_params=params)
# ... prepare next batch while GPU works ...
fb_result = fb_future.result()
optim_result = optim_future.result()

If the user is using the cookbook's supervised.train or rl.train, pipelining is handled automatically. If they have a custom script, check their loop carefully. If they're struggling with async patterns, suggest switching to the cookbook's training scripts which handle pipelining, checkpointing, and logging out of the box.

Quick test: If the user reports "first step is slow but later steps are faster," that's often normal warm-up (model loading, JIT compilation). If every step is slow, the issue is likely pipelining or serialization.

Step 3: Quick timing breakdown

Before reaching for heavy profiling tools, get a rough breakdown of where time goes. The cookbook's built-in tracing does this automatically.

If the user is running the cookbook's train scripts, check the log_path output:

# Read timing metrics from a training run
import json
with open("path/to/metrics.jsonl") as f:
    metrics = [json.loads(line) for line in f]
# Look at timing keys for the last few steps
for m in metrics[-3:]:
    timing = {k: v for k, v in m.items() if k.startswith("time/")}
    print(f"step {m.get('progress/batch')}: {timing}")

What to look for:

• time/forward_backward >> time/optim_step — Normal, fwd/bwd is heavier
• time/get_batch is large — Data loading is the bottleneck, not Tinker
• time/total >> sum of individual times — There are gaps between operations (pipelining issue)
• Large time/forward_backward on step 0, then normal — Warm-up, not a bug

If the user has a custom script without cookbook tracing, suggest wrapping key sections:

import time
t0 = time.perf_counter()
fb_future = tc.forward_backward_async(data=batch, loss_fn="cross_entropy")
t_submit = time.perf_counter() - t0
t0 = time.perf_counter()
result = fb_future.result()
t_wait = time.perf_counter() - t0
print(f"submit: {t_submit:.2f}s, wait: {t_wait:.2f}s")

For a more detailed view, pyinstrument with async mode shows exactly where time goes:

pip install pyinstrument
pyinstrument --async-mode=enabled your_script.py

Interpreting results:

• High submit time → Client-side bottleneck (serialization, data prep). Go to Step 4.
• High wait time → Either network or server-side. Go to Step 5.
• Both reasonable but steps are slow → Check for gaps between steps (pipelining). Go back to Step 2.

Step 4: Profile the request lifecycle

The key is to understand where in the request lifecycle time is being spent. Every Tinker API call goes through: submit → serialize → network send → server compute → long-poll → resolve. GIL contention can block steps on the SDK background thread silently.

Option A: Cookbook tracing (if using cookbook train scripts)

The cookbook automatically produces Gantt charts and Perfetto traces:

# View the Gantt chart — shows each operation as a timeline bar
# Open: <log_path>/iteration_000000/timing_gantt.html
# View Perfetto trace (more detail, shows both threads)
python -m tinker_cookbook.utils.trace <log_path>/trace_events.jsonl -o trace.json
# Open https://ui.perfetto.dev/ and load trace.json

In the Gantt chart, look for gaps between bars — these are periods where neither the main thread nor the SDK is doing useful work. Common patterns:

• Long bar for `forward_backward` with gaps before/after → Pipelining issue
• Long bar for `get_batch` → Data loading bottleneck
• Gaps with no bars at all → GIL contention (background thread blocked)

Option B: pyinstrument (for custom scripts)

pip install pyinstrument
pyinstrument --async-mode=enabled your_script.py

The --async-mode=enabled flag is critical — without it, time spent in await all gets attributed to epoll.poll which tells you nothing.

What to look for:

• Time in pydantic serialization (model_dump, __repr__) → Dependency issue (Step 1)
• Time in AwaitableConcurrentFuture.result_async → Waiting for server (network or server-side)
• Time in data preparation, tokenization, numpy/torch ops → GIL contention risk

Option C: Thread stack watchdog (for hung/slow sessions)

When a session is actively slow or hung, use the async task dump + thread stack watchdog to see what both threads are doing in real-time. Read references/async-task-dump.md for ready-to-paste diagnostic code.

Interpreting the output:

• SDK thread has pending _forward_backward_async tasks → Work submitted, waiting for server
• SDK thread has pending _result_async → Normal long-polling behavior
• SDK thread stopped logging entirely → GIL contention — the background thread can't wake up
• Main thread stuck in numpy/torch/data code while SDK thread is stalled → GIL is the bottleneck

Step 5: GIL contention and background thread blocking

This is the most subtle and most common cause of "mysterious" slowdowns. Because the SDK's background thread shares Python's GIL with the main thread, CPU-heavy work in the user's code blocks the SDK from:

• Sending heartbeats → Session may expire (warning: "Session heartbeat failed")
• Polling for results → Futures appear to hang for minutes
• Submitting new requests → Pipelining breaks even when using _async variants

Symptoms of GIL contention:

• Steps are slow but server-side traces show the GPU finished quickly
• Heartbeat warnings in the logs
• Inconsistent step times (varies with data processing load)
• pyinstrument shows most time in epoll.poll (even with async mode) — the event loop couldn't run

Common GIL-heavy operations in training scripts:

• Large numpy array operations (tokenization, data preprocessing)
• Torch tensor operations on CPU (not GPU — GPU ops release the GIL)
• Heavy JSON/pydantic serialization
• File I/O for large datasets
• transformers tokenizer calls on large batches

Fixes:

1. Move heavy work out of the hot loop: Preprocess data before training starts
2. Use the cookbook's training scripts: They pipeline data prep with async API calls
3. Offload to subprocess: For sampling-heavy workloads, the SDK supports subprocess isolation via TINKER_SUBPROCESS_SAMPLING=1, which gives sampling its own event loop in a separate process (no GIL sharing)
4. Break up long CPU operations: Insert await asyncio.sleep(0) or small yields between heavy processing to let the background thread run

Diagnostic: Is GIL the problem?

import threading, time