4. The Three Pillars in AI Context

Capsule description

You already know what observability is, why it's different from monitoring, and why AI systems need a different approach. Now it's time to open up the three pillars — logs, metrics, traces — and see what's inside when the system you observe makes calls to LLMs, runs RAG pipelines, and generates non-deterministic outputs.

The three pillars aren't a new invention. They've been in the infrastructure and backend world for years. But when you apply them to AI systems, the content of each pillar changes radically. A log is no longer just "request received, status 200." Now it needs to capture the prompt, the tokens consumed, the model used, the temperature, and the cost. A metric is no longer just average latency. You need TTFT (time to first token), tokens per request, cost per endpoint. A trace is no longer "HTTP → database → response." It's "HTTP → validation → embedding → vector search → prompt construction → LLM call → output validation → response."

But the most important insight of this capsule isn't the individual pillars — it's how they correlate. A metric alert tells you latency went up. A trace shows you which step of the pipeline is slow. A log reveals that the prompt included a 15,000-token context because retrieval didn't filter well. The three pillars, used together, give you a complete narrative. Used separately, they give you fragments without context.

Logs in AI: More Than Application Events

The traditional log vs the AI log

In a classic REST API, a typical log captures infrastructure events:

2026-03-08 14:23:01 INFO  Request received: GET /api/users/42
2026-03-08 14:23:01 INFO  Database query executed in 12ms
2026-03-08 14:23:01 INFO  Response sent: 200 OK (15ms)

Useful for basic debugging. But if your endpoint calls an LLM, that log tells you nothing about what really happened. What prompt was sent? How many tokens did it consume? What model was used? How much did it cost? Was the output correct?

An AI-aware log needs to capture data that doesn't exist in traditional software:

Data                    Why?
──────────────────────────────────────────────────────────────────
prompt_content          To reproduce and debug outputs
completion_content      To verify quality after the fact
model                   Different models = different behavior
temperature             Affects output determinism
prompt_tokens           Cost and size of the input
completion_tokens       Cost of the generated output
total_tokens            Total cost of the request
latency_ms              Performance of the LLM call
cost_usd                Direct financial impact
system_prompt_version   To track changes in behavior
rag_context_chunks      How many documents were included in the context

Structured logging for AI with structlog

The difference between a print() and a structured log is the difference between being able to search for information and having to read lines manually. Structured logs are JSON: every field is searchable, filterable, and aggregatable.

import structlog
import time
from openai import OpenAI
from dotenv import load_dotenv

load_dotenv()

structlog.configure(
    processors=[
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.add_log_level,
        structlog.processors.StackInfoRenderer(),
        structlog.processors.JSONRenderer(),
    ],
    wrapper_class=structlog.BoundLogger,
    context_class=dict,
    logger_factory=structlog.PrintLoggerFactory(),
)

logger = structlog.get_logger()
client = OpenAI()

COST_PER_1K = {
    "gpt-4o": {"prompt": 0.0025, "completion": 0.01},
    "gpt-4o-mini": {"prompt": 0.00015, "completion": 0.0006},
}


def calculate_cost(model: str, prompt_tokens: int, completion_tokens: int) -> float:
    rates = COST_PER_1K.get(model, {"prompt": 0.0, "completion": 0.0})
    return (prompt_tokens / 1000 * rates["prompt"]) + (
        completion_tokens / 1000 * rates["completion"]
    )


def call_llm_with_logging(
    prompt: str,
    model: str = "gpt-4o-mini",
    temperature: float = 0.7,
    system_prompt: str = "You are a helpful assistant.",
    system_prompt_version: str = "v1.0",
    endpoint: str = "/unknown",
    user_id: str = "anonymous",
) -> str:
    log = logger.bind(
        endpoint=endpoint,
        user_id=user_id,
        model=model,
        temperature=temperature,
        system_prompt_version=system_prompt_version,
    )

    log.info("llm_request_started", prompt_length=len(prompt))

    start = time.time()
    try:
        response = client.chat.completions.create(
            model=model,
            temperature=temperature,
            messages=[
                {"role": "system", "content": system_prompt},
                {"role": "user", "content": prompt},
            ],
            max_tokens=500,
        )
        latency_ms = (time.time() - start) * 1000
        usage = response.usage
        output = response.choices[0].message.content
        cost = calculate_cost(model, usage.prompt_tokens, usage.completion_tokens)

        log.info(
            "llm_request_completed",
            prompt_tokens=usage.prompt_tokens,
            completion_tokens=usage.completion_tokens,
            total_tokens=usage.total_tokens,
            latency_ms=round(latency_ms, 2),
            cost_usd=round(cost, 6),
            output_length=len(output),
            finish_reason=response.choices[0].finish_reason,
        )

        return output

    except Exception as e:
        latency_ms = (time.time() - start) * 1000
        log.error(
            "llm_request_failed",
            error_type=type(e).__name__,
            error_message=str(e),
            latency_ms=round(latency_ms, 2),
        )
        raise


result = call_llm_with_logging(
    prompt="What is observability in AI systems?",
    model="gpt-4o-mini",
    endpoint="/api/chat",
    user_id="user_12345",
    system_prompt_version="v2.1",
)
print(f"\nOutput: {result[:100]}...")

Expected output (JSON formatted for readability):

{
  "event": "llm_request_started",
  "timestamp": "2026-03-08T14:23:01.234Z",
  "level": "info",
  "endpoint": "/api/chat",
  "user_id": "user_12345",
  "model": "gpt-4o-mini",
  "temperature": 0.7,
  "system_prompt_version": "v2.1",
  "prompt_length": 42
}
{
  "event": "llm_request_completed",
  "timestamp": "2026-03-08T14:23:02.567Z",
  "level": "info",
  "endpoint": "/api/chat",
  "user_id": "user_12345",
  "model": "gpt-4o-mini",
  "prompt_tokens": 28,
  "completion_tokens": 87,
  "total_tokens": 115,
  "latency_ms": 1332.45,
  "cost_usd": 0.000056,
  "output_length": 312,
  "finish_reason": "stop"
}

Notice what you can do with logs like these:

• 🔍 Search all requests from a user: user_id = "user_12345"
• 💰 Sum cost per endpoint: SELECT SUM(cost_usd) WHERE endpoint = "/api/chat"
• ⚡ Filter slow requests: latency_ms > 3000
• 📊 Group by model: GROUP BY model
• 🚨 Alert on errors: event = "llm_request_failed"

With a print("Request completed"), none of this is possible.

What NOT to log

Be careful with privacy and volume:

• ❌ Don't log full prompts in production by default. If your prompts contain users' personal data, complying with GDPR/CCPA requires anonymization or consent.
• ❌ Don't always log full completions. A 4,000-token output per request generates massive logs. Log a hash or the first N characters.
• ✅ Do always log metadata: tokens, cost, latency, model, endpoint, user_id (anonymized if necessary).
• ✅ Log prompts/completions in development environments and specific debug sessions.

import hashlib


def safe_log_content(content: str, max_preview: int = 100) -> dict:
    """Logs content metadata without exposing the full text."""
    return {
        "length": len(content),
        "preview": content[:max_preview] + "..." if len(content) > max_preview else content,
        "hash": hashlib.sha256(content.encode()).hexdigest()[:16],
    }

Metrics in AI: Numbers That Change Decisions

Traditional metrics vs AI metrics

The infrastructure metrics you already know are still necessary:

Traditional metric           What it tells you
──────────────────────────────────────────────────
request_count                Traffic volume
error_rate                   Percentage of failures
latency_p50 / p99            General performance
uptime                       Availability

But in AI you need an additional layer of metrics that don't exist in conventional software:

AI-specific metric            What it tells you
──────────────────────────────────────────────────────────────────────
ttft_ms                       Time to first token — perception of speed
tti_ms                        Time to last token (TTI) — total duration
tokens_per_request            Cost in tokens (prompt + completion)
cost_per_request_usd          Financial impact of each request
cost_per_user_day_usd         How much it costs to serve each user
tokens_per_endpoint           Which endpoints consume the most tokens
hallucination_rate            Percentage of outputs with fabricated information
quality_score                 Assessment of the output's relevance/usefulness
model_switch_count            How many times the model was switched (if there's fallback)
rag_chunks_per_request        Amount of context included in each prompt
cache_hit_rate                Percentage of responses served from cache

TTFT vs TTI vs End-to-End

These three types of latency measure different things:

                   ┌─── TTFT ───┐
                   │             │
Request ──────────► First token ─────────────► Last token ────────► Response
                                  │                          │
                                  └──── Streaming time ──────┘
                   │                                               │
                   └──────────────── End-to-end ───────────────────┘

• TTFT (Time To First Token): How long the model takes to start generating. It affects the user's perception — if TTFT is high, the user feels like "nothing is happening."
• TTI (Time To last token / Inference): How long it takes to generate the whole output. It depends on the number of tokens generated.
• End-to-end: From when the request reaches your server until the response goes out. It includes validation, embedding, RAG, LLM, post-processing.

Collecting AI metrics with simple counters

Before you get to Prometheus (module 4), you can start with in-memory counters that give you immediate visibility:

import time
from dataclasses import dataclass, field
from collections import defaultdict


@dataclass
class AIMetricsCollector:
    """Simple AI metrics collector.

    In production you'd use Prometheus/OpenTelemetry.
    This collector demonstrates which metrics to capture.
    """

    total_requests: int = 0
    total_errors: int = 0
    total_tokens: int = 0
    total_cost_usd: float = 0.0
    latencies_ms: list = field(default_factory=list)
    ttft_ms_list: list = field(default_factory=list)
    tokens_by_endpoint: dict = field(default_factory=lambda: defaultdict(int))
    cost_by_endpoint: dict = field(default_factory=lambda: defaultdict(float))
    cost_by_user: dict = field(default_factory=lambda: defaultdict(float))
    errors_by_type: dict = field(default_factory=lambda: defaultdict(int))

    def record_request(
        self,
        endpoint: str,
        user_id: str,
        model: str,
        prompt_tokens: int,
        completion_tokens: int,
        latency_ms: float,
        cost_usd: float,
        ttft_ms: float | None = None,
    ):
        self.total_requests += 1
        self.total_tokens += prompt_tokens + completion_tokens
        self.total_cost_usd += cost_usd
        self.latencies_ms.append(latency_ms)
        self.tokens_by_endpoint[endpoint] += prompt_tokens + completion_tokens
        self.cost_by_endpoint[endpoint] += cost_usd
        self.cost_by_user[user_id] += cost_usd

        if ttft_ms is not None:
            self.ttft_ms_list.append(ttft_ms)

    def record_error(self, error_type: str):
        self.total_errors += 1
        self.errors_by_type[error_type] += 1

    def get_summary(self) -> dict:
        sorted_latencies = sorted(self.latencies_ms)
        p50_idx = len(sorted_latencies) // 2
        p99_idx = int(len(sorted_latencies) * 0.99)

        return {
            "total_requests": self.total_requests,
            "total_errors": self.total_errors,
            "error_rate": (
                round(self.total_errors / self.total_requests * 100, 2)
                if self.total_requests > 0
                else 0
            ),
            "total_tokens": self.total_tokens,
            "avg_tokens_per_request": (
                round(self.total_tokens / self.total_requests)
                if self.total_requests > 0
                else 0
            ),
            "total_cost_usd": round(self.total_cost_usd, 4),
            "avg_cost_per_request_usd": (
                round(self.total_cost_usd / self.total_requests, 6)
                if self.total_requests > 0
                else 0
            ),
            "latency_p50_ms": (
                round(sorted_latencies[p50_idx], 2) if sorted_latencies else 0
            ),
            "latency_p99_ms": (
                round(sorted_latencies[p99_idx], 2) if sorted_latencies else 0
            ),
            "top_endpoints_by_cost": dict(
                sorted(
                    self.cost_by_endpoint.items(), key=lambda x: x[1], reverse=True
                )[:5]
            ),
            "top_users_by_cost": dict(
                sorted(self.cost_by_user.items(), key=lambda x: x[1], reverse=True)[
                    :5
                ]
            ),
        }


metrics = AIMetricsCollector()

metrics.record_request(
    endpoint="/api/chat",
    user_id="user_001",
    model="gpt-4o-mini",
    prompt_tokens=150,
    completion_tokens=200,
    latency_ms=1200.5,
    cost_usd=0.000142,
    ttft_ms=340.0,
)
metrics.record_request(
    endpoint="/api/summarize",
    user_id="user_001",
    model="gpt-4o",
    prompt_tokens=4000,
    completion_tokens=500,
    latency_ms=3400.2,
    cost_usd=0.015,
    ttft_ms=890.0,
)
metrics.record_request(
    endpoint="/api/chat",
    user_id="user_002",
    model="gpt-4o-mini",
    prompt_tokens=80,
    completion_tokens=120,
    latency_ms=900.1,
    cost_usd=0.000084,
    ttft_ms=280.0,
)
metrics.record_error("RateLimitError")

summary = metrics.get_summary()
print("=" * 60)
print("AI METRICS SUMMARY")
print("=" * 60)
for key, value in summary.items():
    print(f"  {key}: {value}")

Expected output:

============================================================
AI METRICS SUMMARY
============================================================
  total_requests: 3
  total_errors: 1
  error_rate: 33.33
  total_tokens: 5050
  avg_tokens_per_request: 1683
  total_cost_usd: 0.0152
  avg_cost_per_request_usd: 0.005075
  latency_p50_ms: 1200.5
  latency_p99_ms: 3400.2
  top_endpoints_by_cost: {'/api/summarize': 0.015, '/api/chat': 0.000226}
  top_users_by_cost: {'user_001': 0.015142, 'user_002': 8.4e-05}

With just three requests you can already see that /api/summarize costs 66x more than /api/chat, and that user_001 generates 99% of the spend. Without metrics, that information is invisible.

Traces in AI: The Complete Story of a Request

The traditional trace vs the AI trace

A trace in a classic REST backend is simple:

[Trace: abc-123]
  └── HTTP GET /api/users/42 .................. 15ms
       └── Database query (SELECT * FROM users) .. 12ms

Two spans. Direct. If the request is slow, the bottleneck is in the database.

A trace in an AI system is fundamentally more complex:

[Trace: xyz-789]
  └── HTTP POST /api/chat ............................ 4,200ms
       ├── Input validation ........................... 5ms
       ├── Embedding call (text-embedding-3-small) .... 120ms
       │    └── tokens: 45, cost: $0.000002
       ├── Vector search (Pinecone) ................... 230ms
       │    └── results: 8 chunks, relevance: [0.92, 0.89, 0.87, ...]
       ├── Context construction ....................... 15ms
       │    └── selected: 4 chunks, total_tokens: 3,200
       ├── Prompt assembly ............................ 2ms
       │    └── system_prompt_v2.1 + context + user_query
       ├── LLM call (gpt-4o) ......................... 3,750ms
       │    ├── prompt_tokens: 3,400
       │    ├── completion_tokens: 280
       │    ├── cost: $0.0113
       │    ├── ttft: 650ms
       │    └── finish_reason: stop
       └── Output validation .......................... 78ms
            └── hallucination_check: pass, format_check: pass

Now the trace tells you a story. The total latency is 4,200ms, but 89% of the time is in the LLM call. The embedding was fast. The vector search returned 8 chunks but you only used 4. The final prompt had 3,400 tokens. The output passed validation. Each span has AI-specific attributes.

Implementation: manual trace with structured logging

Before using OpenTelemetry (module 3), you can build simple traces with logging. This demonstrates the concept and already gives you value:

import time
import uuid
import structlog
from dataclasses import dataclass

structlog.configure(
    processors=[
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.add_log_level,
        structlog.processors.JSONRenderer(),
    ],
    wrapper_class=structlog.BoundLogger,
    context_class=dict,
    logger_factory=structlog.PrintLoggerFactory(),
)


@dataclass
class SpanResult:
    name: str
    duration_ms: float
    attributes: dict


class SimpleTracer:
    """Manual tracer to demonstrate the concept before OTel."""

    def __init__(self):
        self.trace_id = str(uuid.uuid4())[:8]
        self.spans: list[SpanResult] = []
        self.logger = structlog.get_logger().bind(trace_id=self.trace_id)

    def span(self, name: str):
        return SpanContext(self, name)

    def summary(self) -> dict:
        total_ms = sum(s.duration_ms for s in self.spans)
        return {
            "trace_id": self.trace_id,
            "total_duration_ms": round(total_ms, 2),
            "span_count": len(self.spans),
            "spans": [
                {
                    "name": s.name,
                    "duration_ms": round(s.duration_ms, 2),
                    "pct_of_total": round(s.duration_ms / total_ms * 100, 1)
                    if total_ms > 0
                    else 0,
                    **s.attributes,
                }
                for s in self.spans
            ],
        }


class SpanContext:
    def __init__(self, tracer: SimpleTracer, name: str):
        self.tracer = tracer
        self.name = name
        self.attributes: dict = {}
        self.start_time = 0.0

    def __enter__(self):
        self.start_time = time.time()
        self.tracer.logger.info(f"span_start", span=self.name)
        return self

    def __exit__(self, exc_type, exc_val, exc_tb):
        duration_ms = (time.time() - self.start_time) * 1000
        self.tracer.spans.append(
            SpanResult(
                name=self.name,
                duration_ms=duration_ms,
                attributes=self.attributes,
            )
        )
        self.tracer.logger.info(
            "span_end",
            span=self.name,
            duration_ms=round(duration_ms, 2),
            **self.attributes,
        )
        return False

    def set(self, key: str, value) -> "SpanContext":
        self.attributes[key] = value
        return self


def simulate_rag_pipeline(query: str) -> dict:
    """Simulates a complete RAG pipeline with manual tracing."""
    tracer = SimpleTracer()

    with tracer.span("input_validation") as span:
        time.sleep(0.005)
        is_valid = len(query) > 0 and len(query) < 10000
        span.set("query_length", len(query))
        span.set("is_valid", is_valid)

    with tracer.span("embedding") as span:
        time.sleep(0.12)
        span.set("model", "text-embedding-3-small")
        span.set("input_tokens", 45)
        span.set("dimensions", 1536)

    with tracer.span("vector_search") as span:
        time.sleep(0.23)
        span.set("index", "knowledge_base")
        span.set("top_k", 8)
        span.set("results_returned", 8)
        span.set("min_relevance_score", 0.82)

    with tracer.span("context_construction") as span:
        time.sleep(0.015)
        span.set("chunks_selected", 4)
        span.set("chunks_discarded", 4)
        span.set("context_tokens", 3200)
        span.set("selection_strategy", "relevance_threshold_0.85")

    with tracer.span("prompt_assembly") as span:
        time.sleep(0.002)
        span.set("system_prompt_version", "v2.1")
        span.set("total_prompt_tokens", 3400)
        span.set("includes_rag_context", True)

    with tracer.span("llm_call") as span:
        time.sleep(0.8)
        span.set("model", "gpt-4o")
        span.set("temperature", 0.3)
        span.set("prompt_tokens", 3400)
        span.set("completion_tokens", 280)
        span.set("cost_usd", 0.0113)
        span.set("ttft_ms", 650)
        span.set("finish_reason", "stop")

    with tracer.span("output_validation") as span:
        time.sleep(0.08)
        span.set("hallucination_check", "pass")
        span.set("format_check", "pass")
        span.set("confidence_score", 0.91)

    return tracer.summary()


result = simulate_rag_pipeline("What is the return policy?")

print("\n" + "=" * 60)
print("TRACE SUMMARY")
print("=" * 60)
print(f"Trace ID: {result['trace_id']}")
print(f"Total: {result['total_duration_ms']}ms ({result['span_count']} spans)")
print("-" * 60)
for span in result["spans"]:
    name = span.pop("name")
    duration = span.pop("duration_ms")
    pct = span.pop("pct_of_total")
    bar = "█" * int(pct / 2)
    print(f"  {name:.<30} {duration:>8.1f}ms ({pct:>5.1f}%) {bar}")
    for k, v in span.items():
        print(f"    {k}: {v}")

Expected output:

============================================================
TRACE SUMMARY
============================================================
Trace ID: a3f2c1d8
Total: 1252.34ms (7 spans)
------------------------------------------------------------
  input_validation............      5.1ms ( 0.4%)
    query_length: 26
    is_valid: True
  embedding...................    120.3ms ( 9.6%) ████
    model: text-embedding-3-small
    input_tokens: 45
    dimensions: 1536
  vector_search...............    230.5ms (18.4%) █████████
    index: knowledge_base
    top_k: 8
    results_returned: 8
    min_relevance_score: 0.82
  context_construction........     15.2ms ( 1.2%)
    chunks_selected: 4
    chunks_discarded: 4
    context_tokens: 3200
    selection_strategy: relevance_threshold_0.85
  prompt_assembly.............      2.1ms ( 0.2%)
    system_prompt_version: v2.1
    total_prompt_tokens: 3400
    includes_rag_context: True
  llm_call....................    800.8ms (64.0%) ████████████████████████████████
    model: gpt-4o
    temperature: 0.3
    prompt_tokens: 3400
    completion_tokens: 280
    cost_usd: 0.0113
    ttft_ms: 650
    finish_reason: stop
  output_validation...........     80.3ms ( 6.4%) ███
    hallucination_check: pass
    format_check: pass
    confidence_score: 0.91

Now you can see that 64% of the time is spent in the LLM call. If you want to optimize latency, there's your bottleneck. The vector search takes 18% — also significant. And output_validation is 6.4% that's worth every millisecond because it catches hallucinations before they reach the user.

The Three Pillars Correlated: The Key Insight

They aren't three tools — they're three perspectives

The most common mistake when learning observability is treating the three pillars as independent tools: "I have my logs over here, my metrics over there, and if one day I need traces, I'll figure it out." That's like having a sales department, a marketing department, and a product department that never talk to each other.

The three pillars are three perspectives of the same event:

A SINGLE REQUEST generates:
├── LOG:    {"event": "llm_request_completed", "tokens": 3680, "cost": 0.0113, ...}
├── METRIC: request_latency_ms = 4200, tokens_total = 3680, cost_usd = 0.0113
└── TRACE:  [validation → embedding → search → context → llm → validation] = 4200ms

The log gives you the detail (what exactly happened in this request). The metric gives you the trend (how this request compares to others). The trace gives you the flow (which steps ran and how long each took).

The investigation cycle: metric → trace → log

In production, the typical investigation of an incident follows this flow:

1. METRIC ALERT
   "latency_p99 went from 2s to 8s in the last 15 minutes"
   → You know WHAT is happening, but not WHY.

2. TRACE INVESTIGATION
   You filter traces where latency > 5000ms.
   You discover the "vector_search" span went from 200ms to 3,500ms.
   → You know WHERE the problem is, but not the CAUSE.

3. DETAIL IN LOGS
   You filter logs from the "vector_search" span for those slow traces.
   You discover top_k changed from 8 to 50 (someone modified the config).
   → You know WHY it happened. You can fix it.

Without correlation between the three, each pillar gives you an incomplete piece:

• Metrics only: "Something is slow." → What? Where? Why?
• Logs only: "This request did X." → Is it an isolated case or a pattern?
• Traces only: "This request went through these steps." → How many requests are like this?

Practical correlation example

import time
import uuid
import structlog
from collections import defaultdict

structlog.configure(
    processors=[
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.add_log_level,
        structlog.processors.JSONRenderer(),
    ],
    wrapper_class=structlog.BoundLogger,
    context_class=dict,
    logger_factory=structlog.PrintLoggerFactory(),
)


class CorrelatedObservability:
    """Demonstrates how the three pillars connect through shared IDs."""

    def __init__(self):
        self.logger = structlog.get_logger()
        self.metrics = defaultdict(list)

    def handle_request(self, query: str, user_id: str, endpoint: str):
        trace_id = str(uuid.uuid4())[:12]
        log = self.logger.bind(
            trace_id=trace_id, user_id=user_id, endpoint=endpoint
        )

        request_start = time.time()
        spans = []

        # Span 1: Embedding
        t0 = time.time()
        time.sleep(0.1)
        embed_ms = (time.time() - t0) * 1000
        spans.append(("embedding", embed_ms))
        log.info("span_completed", span="embedding", duration_ms=round(embed_ms, 1))

        # Span 2: Vector search
        t0 = time.time()
        time.sleep(0.2)
        search_ms = (time.time() - t0) * 1000
        chunks_found = 6
        spans.append(("vector_search", search_ms))
        log.info(
            "span_completed",
            span="vector_search",
            duration_ms=round(search_ms, 1),
            chunks_found=chunks_found,
        )

        # Span 3: LLM call
        t0 = time.time()
        time.sleep(0.5)
        llm_ms = (time.time() - t0) * 1000
        prompt_tokens = 2800
        completion_tokens = 200
        cost = 0.0085
        spans.append(("llm_call", llm_ms))
        log.info(
            "span_completed",
            span="llm_call",
            duration_ms=round(llm_ms, 1),
            prompt_tokens=prompt_tokens,
            completion_tokens=completion_tokens,
            cost_usd=cost,
        )

        total_ms = (time.time() - request_start) * 1000

        # PILLAR 1: Full request log
        log.info(
            "request_completed",
            total_ms=round(total_ms, 1),
            total_tokens=prompt_tokens + completion_tokens,
            cost_usd=cost,
        )

        # PILLAR 2: Aggregated metrics
        self.metrics["latency_ms"].append(total_ms)
        self.metrics["cost_usd"].append(cost)
        self.metrics["tokens"].append(prompt_tokens + completion_tokens)

        # PILLAR 3: Trace (spans)
        # In real OTel, spans are exported automatically.
        # Here we print them as a summary.
        log.info(
            "trace_summary",
            spans=[
                {"name": name, "ms": round(ms, 1)} for name, ms in spans
            ],
            bottleneck=max(spans, key=lambda x: x[1])[0],
        )

        return trace_id

    def get_metrics_snapshot(self) -> dict:
        latencies = sorted(self.metrics["latency_ms"])
        costs = self.metrics["cost_usd"]
        return {
            "request_count": len(latencies),
            "latency_p50_ms": round(latencies[len(latencies) // 2], 1)
            if latencies
            else 0,
            "latency_p99_ms": round(latencies[int(len(latencies) * 0.99)], 1)
            if latencies
            else 0,
            "total_cost_usd": round(sum(costs), 4),
            "avg_cost_per_request": round(sum(costs) / len(costs), 6)
            if costs
            else 0,
        }


obs = CorrelatedObservability()

print("--- Simulating 3 requests ---\n")
for i in range(3):
    trace_id = obs.handle_request(
        query=f"Question #{i+1}",
        user_id=f"user_{i % 2 + 1:03d}",
        endpoint="/api/chat",
    )
    print()

print("=" * 60)
print("METRICS SNAPSHOT (what you see in a dashboard)")
print("=" * 60)
snapshot = obs.get_metrics_snapshot()
for k, v in snapshot.items():
    print(f"  {k}: {v}")

Notice how the trace_id appears in every log. That's the correlation: when a metric alerts you to a problem, you look up the trace_ids of the affected requests, and with those IDs you can find each individual log. Without that connecting thread, each pillar lives in isolation.

Comparison: Pillars in Traditional Software vs AI

The AI column doesn't replace the traditional one — it extends it. You still need HTTP logs, infrastructure metrics, and network traces. But without the AI-specific layer, your observability has a hole exactly where you need it most.

Connection with the Project

How the pillars feed your Observability Assessment

The module's project (capsule 08) is an Observability Assessment. For each pillar, you evaluate your system:

PILLAR: LOGS
  Do I capture prompts sent?                     □ Yes  □ No
  Do I capture tokens per request?               □ Yes  □ No
  Are my logs structured (JSON)?                  □ Yes  □ No
  Can I filter logs by model/endpoint/user?       □ Yes  □ No

PILLAR: METRICS
  Do I measure TTFT and TTI separately?          □ Yes  □ No
  Do I calculate cost per request in USD?         □ Yes  □ No
  Do I have output quality metrics?               □ Yes  □ No
  Do I know which endpoint is most costly?        □ Yes  □ No

PILLAR: TRACES
  Can I see the complete flow of a request?       □ Yes  □ No
  Does each step have its own latency?            □ Yes  □ No
  Can I identify the bottleneck of a request?     □ Yes  □ No
  Do I have a trace_id to correlate pillars?      □ Yes  □ No

If most of your answers are "No," you know exactly where your gaps are. Modules 2-3 give you the tools to turn those "No"s into "Yes"es.

Troubleshooting

Problem: "My logs are too large because of the prompts"

Symptom: Log volume multiplied after logging prompts and completions.

Solution: Don't log full content in production by default. Log metadata (tokens, cost, latency) always, and content only in debug mode or for controlled sampling (for example, 1 in every 100 requests). Use the safe_log_content pattern from this capsule.

Problem: "I don't know how to calculate cost in USD"

Symptom: You have tokens but not money. The dashboard shows "3,400 prompt tokens" but not what it means in USD.

Solution: Keep an updated cost table per model (like COST_PER_1K in this capsule's code). Calculate cost at the moment of the log and record cost_usd as a field. Providers publish their prices — the conversion is simple arithmetic.

Problem: "My traces don't show the LLM call as a separate span"

Symptom: The trace shows the whole request as a single block. You can't see which step took the most time.

Solution: Each significant operation (embedding, vector search, LLM call, validation) should be a separate span. If you use a library that does everything "inside a function," you need to instrument that function internally. OpenTelemetry (module 3) makes this easier.

Problem: "I can't correlate a log with a trace"

Symptom: You have logs and you have traces, but when a metric alerts you to a problem, you can't go from the dashboard to the specific log.

Solution: Make sure every log includes the trace_id. Structlog with a bound logger (as in the examples) makes this automatic. The trace_id is the thread that connects metrics → traces → logs.

Problem: "The three pillars seem redundant"

Symptom: You feel like you're recording the same information three times.

Solution: It's not redundancy — they're different perspectives. The log has the detail of an individual request. The metric is an aggregated number of thousands of requests. The trace is the temporal flow of one request. Without any of the three, you're missing a dimension of analysis. Think of it as latitude, longitude, and altitude: the three numbers describe a point, but none is redundant.

Exercises

Exercise 1: Identify the AI-specific fields

Given this log from an AI system, identify which fields are AI-specific (wouldn't exist in a conventional REST backend):

{
  "timestamp": "2026-03-08T14:23:02.567Z",
  "level": "info",
  "event": "request_completed",
  "method": "POST",
  "path": "/api/chat",
  "status_code": 200,
  "model": "gpt-4o-mini",
  "prompt_tokens": 1250,
  "completion_tokens": 340,
  "temperature": 0.7,
  "latency_ms": 2100,
  "cost_usd": 0.000391,
  "user_id": "usr_abc",
  "system_prompt_version": "v3.2",
  "rag_chunks_included": 4,
  "finish_reason": "stop"
}

Exercise 2: Design metrics for a chatbot

You have a chatbot that answers questions about product documentation. Define at least 8 metrics you should capture, categorized by pillar. For each metric, indicate: name, type (counter, gauge, histogram), and why it matters.

LATENCY METRICS
────────────────────
1. chatbot_ttft_ms (histogram)
   Time to first token. Affects perception of speed.
   Labels: model, endpoint

2. chatbot_e2e_latency_ms (histogram)
   Total request latency including RAG.
   Labels: model, endpoint, has_rag_context

3. chatbot_embedding_latency_ms (histogram)
   Latency of the embedding step for search.
   Labels: embedding_model

COST METRICS
─────────────────
4. chatbot_tokens_total (counter)
   Total tokens consumed (prompt + completion).
   Labels: model, token_type (prompt/completion), endpoint

5. chatbot_cost_usd_total (counter)
   Accumulated cost in USD.
   Labels: model, endpoint

6. chatbot_rag_chunks_per_request (histogram)
   Context chunks included per request.
   Indicates retrieval efficiency.

QUALITY METRICS
───────────────────
7. chatbot_responses_total (counter)
   Total responses generated.
   Labels: finish_reason (stop/length/error), model

8. chatbot_hallucination_detected_total (counter)
   Responses where a hallucination was detected.
   Labels: detection_method, severity

ERROR METRICS
─────────────────
9. chatbot_errors_total (counter)
   Total errors by type.
   Labels: error_type (rate_limit/timeout/invalid_output/model_error)

10. chatbot_retries_total (counter)
    Retries needed.
    Labels: retry_reason, model

Exercise 3: Draw your system's trace

Take the AI system you work with (or one you know) and draw the complete trace of a request. For each span, indicate:

• Name of the step
• Estimated duration
• AI-relevant attributes you'd capture

[Trace: request to a RAG chatbot with tool calls]

  └── POST /api/chat ................................. ~5,500ms total
       ├── auth_validation ........................... ~10ms
       │    └── user_id, auth_method
       │
       ├── input_moderation .......................... ~200ms
       │    └── model: gpt-4o-mini, flagged: false, categories: []
       │
       ├── query_embedding ........................... ~80ms
       │    └── model: text-embedding-3-small, tokens: 32, dimensions: 1536
       │
       ├── vector_search ............................. ~150ms
       │    └── index: product_docs, top_k: 10, results: 10, min_score: 0.78
       │
       ├── context_ranking ........................... ~300ms
       │    └── model: gpt-4o-mini, chunks_in: 10, chunks_out: 4
       │    └── tokens_used: 800, strategy: llm_reranking
       │
       ├── prompt_assembly ........................... ~5ms
       │    └── system_v: 3.1, context_tokens: 2400, total_tokens: 2600
       │
       ├── llm_call_main ............................. ~3,200ms
       │    └── model: gpt-4o, temp: 0.3, prompt_tk: 2600, completion_tk: 180
       │    └── cost: $0.0083, ttft: 580ms, finish: tool_calls
       │
       ├── tool_execution ............................ ~800ms
       │    └── tool: get_pricing, args: {product: "pro"}, result_tokens: 45
       │
       ├── llm_call_final ............................ ~650ms
       │    └── model: gpt-4o, prompt_tk: 2825, completion_tk: 120
       │    └── cost: $0.0083, finish: stop
       │
       └── output_validation ......................... ~50ms
            └── format_ok: true, hallucination_check: pass

Exercise 4: Implement multi-model cost calculation

Extend the calculate_cost function to support at least 5 different models (including Anthropic models and embedding models). Add support for a cache discount (some providers charge less if the prompt is in cache).

from dataclasses import dataclass


@dataclass
class ModelPricing:
    prompt_per_1k: float
    completion_per_1k: float
    cached_prompt_per_1k: float | None = None


PRICING_TABLE: dict[str, ModelPricing] = {
    "gpt-4o": ModelPricing(
        prompt_per_1k=0.0025,
        completion_per_1k=0.01,
        cached_prompt_per_1k=0.00125,
    ),
    "gpt-4o-mini": ModelPricing(
        prompt_per_1k=0.00015,
        completion_per_1k=0.0006,
        cached_prompt_per_1k=0.000075,
    ),
    "claude-sonnet-4-20250514": ModelPricing(
        prompt_per_1k=0.003,
        completion_per_1k=0.015,
        cached_prompt_per_1k=0.0003,
    ),
    "claude-3-5-haiku-20241022": ModelPricing(
        prompt_per_1k=0.0008,
        completion_per_1k=0.004,
        cached_prompt_per_1k=0.00008,
    ),
    "text-embedding-3-small": ModelPricing(
        prompt_per_1k=0.00002,
        completion_per_1k=0.0,
    ),
}


def calculate_cost_v2(
    model: str,
    prompt_tokens: int,
    completion_tokens: int,
    cached_prompt_tokens: int = 0,
) -> dict:
    pricing = PRICING_TABLE.get(model)
    if pricing is None:
        return {
            "cost_usd": 0.0,
            "warning": f"Unknown model: {model}. Cost not calculated.",
        }

    non_cached_prompt = prompt_tokens - cached_prompt_tokens
    prompt_cost = non_cached_prompt / 1000 * pricing.prompt_per_1k
    completion_cost = completion_tokens / 1000 * pricing.completion_per_1k

    cache_cost = 0.0
    cache_savings = 0.0
    if cached_prompt_tokens > 0 and pricing.cached_prompt_per_1k is not None:
        cache_cost = cached_prompt_tokens / 1000 * pricing.cached_prompt_per_1k
        full_price = cached_prompt_tokens / 1000 * pricing.prompt_per_1k
        cache_savings = full_price - cache_cost

    total = prompt_cost + completion_cost + cache_cost

    return {
        "cost_usd": round(total, 8),
        "prompt_cost_usd": round(prompt_cost, 8),
        "completion_cost_usd": round(completion_cost, 8),
        "cache_cost_usd": round(cache_cost, 8),
        "cache_savings_usd": round(cache_savings, 8),
        "model": model,
    }


# Test
print(calculate_cost_v2("gpt-4o", 3400, 280))
print(calculate_cost_v2("claude-sonnet-4-20250514", 5000, 400, cached_prompt_tokens=3000))
print(calculate_cost_v2("text-embedding-3-small", 512, 0))

{'cost_usd': 0.0113, 'prompt_cost_usd': 0.0085, 'completion_cost_usd': 0.0028,
 'cache_cost_usd': 0.0, 'cache_savings_usd': 0.0, 'model': 'gpt-4o'}

{'cost_usd': 0.0129, 'prompt_cost_usd': 0.006, 'completion_cost_usd': 0.006,
 'cache_cost_usd': 0.0009, 'cache_savings_usd': 0.0081,
 'model': 'claude-sonnet-4-20250514'}

{'cost_usd': 1.024e-05, 'prompt_cost_usd': 1.024e-05, 'completion_cost_usd': 0.0,
 'cache_cost_usd': 0.0, 'cache_savings_usd': 0.0,
 'model': 'text-embedding-3-small'}

Exercise 5: From alert to root cause

You receive this metrics alert at 3pm:

⚠️ ALERT: latency_p99 > 8000ms (threshold: 5000ms)
   Endpoint: /api/summarize
   Window: last 15 minutes
   Current value: 8,432ms

Describe step by step how you'd use the three pillars to get to the root cause. Indicate what you'd look for in each pillar, what filters you'd apply, and what conclusions you could draw.

Query: latency_p99 for /api/summarize, last 2 hours, broken down by model

Result: latency went from 2,100ms to 8,400ms ~18 minutes ago.
Only affects the gpt-4o model. gpt-4o-mini is still normal.

Additional query: average tokens_per_request for /api/summarize, same window

Result: average tokens went from 1,200 to 6,800 ~18 minutes ago.

Partial conclusion: the problem is that requests are sending many more
tokens to the model. It's not a problem with the model itself (no change in
TTFT normalized by tokens).

Filter: traces where endpoint=/api/summarize AND total_duration > 5000ms
         in the last 20 minutes

Result: 47 traces match.

Inspection of a representative trace:
  - embedding: 80ms (normal)
  - vector_search: 180ms (normal)
  - context_construction: 12ms (normal)
    → BUT: context_tokens = 5,800 (normally ~800)
    → chunks_selected = 12 (normally 3-4)
  - llm_call: 7,800ms
    → prompt_tokens = 6,200 (normally ~1,000)

Partial conclusion: context_construction is selecting too many chunks.
The problem isn't in the LLM or the vector search — it's in the context
selection logic.

Filter: logs where trace_id IN (traces from step 2) AND span="context_construction"

Result: logs show:
  {"event": "context_selection", "strategy": "include_all",
   "config_version": "v4.0", "chunks_in": 12, "chunks_out": 12}

The strategy changed from "relevance_threshold_0.85" to "include_all"!

Additional filter: logs where event="config_change" in the last 2 hours

Result:
  {"event": "config_change", "key": "rag.context_strategy",
   "old_value": "relevance_threshold_0.85", "new_value": "include_all",
   "changed_by": "deploy_pipeline", "timestamp": "2026-03-08T14:42:00Z"}

ROOT CAUSE: A deploy 18 minutes ago changed the context selection
strategy. It now includes ALL chunks from the vector search instead
of filtering by relevance. This multiplied the tokens sent to the LLM,
causing high latency and probably elevated cost.

Exercise 6: Audit a pillar of your own system

Choose one of the three pillars (logs, metrics, or traces) and perform a quick audit of your AI system. Answer:

1. What data do you currently capture in this pillar?
2. What AI-specific data are you missing?
3. What questions can't you answer because of that gap?
4. What would you need to implement to close the gaps?

PILLAR AUDIT: LOGS
═════════════════════════

1. WHAT I CAPTURE TODAY:
   ✅ Timestamp of each request
   ✅ HTTP method and path
   ✅ Response status code
   ✅ Errors with stack trace
   ❌ Not captured in structured format (I use print/basic logging)

2. WHAT I'M MISSING (AI-SPECIFIC):
   ❌ Model used per request
   ❌ Tokens (prompt + completion)
   ❌ Cost in USD
   ❌ Latency of the LLM call (I only have end-to-end)
   ❌ Temperature and other parameters
   ❌ System prompt version
   ❌ Prompt content (not even a hash)
   ❌ RAG chunks included

3. QUESTIONS I CAN'T ANSWER:
   - "How much did yesterday's most expensive request cost?"
   - "Which prompt generated the incorrect response the user reported?"
   - "Did the system prompt change between yesterday and today?"
   - "How many average tokens does /api/chat consume vs /api/summarize?"
   - "Are there requests that fail silently (200 OK but empty output)?"

4. WHAT I NEED TO IMPLEMENT:
   a. Migrate from print()/logging to structlog (1-2 hours)
   b. Add AI fields to every LLM call log (30 min)
   c. Implement calculate_cost to record USD (30 min)
   d. Add safe_log_content for prompts (30 min)
   e. Set up a basic log aggregator (to search/filter)

   PRIORITY: (a) and (b) first — without structured logs with AI fields,
   the rest of the pillars won't work well either.

Summary

• The three pillars of observability (logs, metrics, traces) apply to AI systems, but their content changes radically compared to traditional software.
• Logs in AI need to capture prompt metadata, tokens, cost, model, and parameters — not just HTTP events. Structured logging with structlog gives you searchable and filterable fields.
• Metrics in AI include dimensions that don't exist in a conventional backend: TTFT, TTI, tokens per request, cost in USD, hallucination rate, quality score.
• Traces in AI are more complex: a typical request goes through validation → embedding → vector search → context construction → LLM call → output validation. Each step is a span with AI-relevant attributes.
• The pillars aren't independent — they're three perspectives of the same system. A metric alerts, a trace locates, a log explains. Without correlation (via trace_id), each pillar gives fragments without context.
• The investigation cycle flows: metric alert → trace filter → detail in logs → root cause identified. Practice that flow before you need it at 2am.
• Don't log everything: metadata always, prompt/completion content carefully (privacy, volume). Use sampling and hashing.
• Cost calculation is simple arithmetic but requires an updated pricing table per model. Record cost_usd in every log — it's the metric that most impacts business decisions.

Additional Resources

1. OpenTelemetry — Logs, Metrics, Traces — Official definition of the three pillars as "signals" in OTel
2. OpenTelemetry Semantic Conventions for GenAI — Attribute conventions for LLM spans (model, tokens, etc.)
3. structlog Documentation — Complete reference for the library used in this capsule
4. Google SRE — Monitoring Distributed Systems — The classic chapter on the four golden signals
5. Charity Majors — Observability Engineering, Chapter 3 — Logs, metrics, traces as correlated perspectives
6. OpenAI Pricing — Up-to-date prices for calculating cost_usd
7. Anthropic API Pricing — Claude prices including cache discounts
8. Distributed Tracing in Practice (O'Reilly) — Reference book on distributed tracing