Understanding Traces

Understanding Traces

Learn what ChronoTrace captures, how traces are structured, and how to interpret the data to effectively debug your Laravel application.

---

🎯 What is a Trace?

A trace is a complete snapshot of a single HTTP request execution in your Laravel application. It captures:

• Request details (URL, method, headers, payload)
• Response information (status, headers, body)
• Execution timeline with precise timestamps
• All events that occurred during processing
• Performance metrics (duration, memory usage)
• Error context if the request failed

Think of it as a "flight recorder" for your Laravel requests.

---

📊 Trace Structure

High-Level Structure

{
  "trace_id": "chronotrace_20240806_143015_abc123",
  "request_info": { /* Request details */ },
  "response_info": { /* Response details */ },
  "performance": { /* Timing and memory */ },
  "events": {
    "database": [ /* DB queries */ ],
    "cache": [ /* Cache operations */ ],
    "http": [ /* External API calls */ ],
    "jobs": [ /* Queue jobs */ ],
    "custom": [ /* Application events */ ]
  },
  "metadata": { /* Trace metadata */ }
}

Detailed Breakdown

Request Information

{
  "request_info": {
    "method": "POST",
    "url": "https://example.com/api/users",
    "headers": {
      "Content-Type": "application/json",
      "Authorization": "[REDACTED]",
      "User-Agent": "Mozilla/5.0..."
    },
    "body": {
      "name": "John Doe",
      "email": "[REDACTED]",
      "password": "[REDACTED]"
    },
    "ip_address": "192.168.1.100",
    "user_id": 123,
    "session_id": "sess_abc123"
  }
}

Performance Metrics

{
  "performance": {
    "total_duration_ms": 245,
    "memory_peak_mb": 12.5,
    "memory_start_mb": 8.2,
    "cpu_time_ms": 180,
    "started_at": "2024-08-06T14:30:15.123Z",
    "ended_at": "2024-08-06T14:30:15.368Z"
  }
}

Event Timeline

{
  "events": {
    "database": [
      {
        "timestamp": "2024-08-06T14:30:15.125Z",
        "offset_ms": 2,
        "sql": "SELECT * FROM users WHERE email = ?",
        "bindings": ["[REDACTED]"],
        "duration_ms": 5,
        "connection": "mysql",
        "rows_affected": 1
      }
    ],
    "cache": [
      {
        "timestamp": "2024-08-06T14:30:15.135Z",
        "offset_ms": 12,
        "operation": "get",
        "key": "user:123:profile",
        "result": "hit",
        "store": "redis",
        "ttl_seconds": 3600
      }
    ]
  }
}

---

🕒 Timeline and Timing

Understanding Timestamps

ChronoTrace uses multiple timing references to help you understand execution flow:

Request Start: 2024-08-06T14:30:15.123Z (0ms)
├── [+2ms]   Database Query: SELECT users
├── [+12ms]  Cache GET: user:123:profile  
├── [+45ms]  HTTP POST: external-api.com
├── [+125ms] Database INSERT: user_activities
├── [+180ms] Cache SET: user:123:last_activity
└── [+245ms] Request End: Response sent

Key Timing Concepts

• Absolute Timestamp: Exact time when event occurred
• Relative Offset: Milliseconds since request start
• Event Duration: How long the specific operation took
• Total Duration: Complete request processing time

Example Timeline Analysis

# Replay trace with timing focus
php artisan chronotrace:replay abc123 --show-timeline

┌─ REQUEST TIMELINE ──────────────────────────────────────────┐
│ Total Duration: 245ms                                       │
│                                                             │
│ 0ms     ████ Request Start                                  │
│ 2ms     ████ DB Query (5ms)                                │
│ 12ms    ████ Cache Hit (1ms)                               │
│ 45ms    ████████████████ HTTP Call (80ms)                  │
│ 125ms   ████ DB Insert (3ms)                               │
│ 180ms   ████ Cache Set (2ms)                               │
│ 245ms   ████ Response Sent                                  │
│                                                             │
│ 🔍 Analysis:                                               │
│   • HTTP call accounts for 33% of total time               │
│   • Database operations: 8ms total (3% of time)            │
│   • Cache operations: 3ms total (1% of time)               │
│   • Opportunity: Optimize external API call                │
└─────────────────────────────────────────────────────────────┘

---

🗃️ Event Types

Database Events

Captures all database interactions:

{
  "type": "database",
  "timestamp": "2024-08-06T14:30:15.125Z",
  "sql": "SELECT id, name, email FROM users WHERE active = ? AND created_at > ?",
  "bindings": [true, "2024-01-01 00:00:00"],
  "duration_ms": 15,
  "connection": "mysql",
  "rows_returned": 150,
  "query_type": "select",
  "table": "users"
}

What to look for:

• Slow queries (>100ms)
• N+1 query patterns
• Large result sets
• Missing indexes (high duration + many rows)

Cache Events

Tracks cache operations and efficiency:

{
  "type": "cache",
  "operation": "get",
  "key": "products:featured:2024-08-06",
  "result": "miss",
  "store": "redis",
  "duration_ms": 2,
  "subsequent_action": "database_fallback"
}

What to look for:

• High cache miss rates
• Expensive cache misses followed by DB queries
• Cache stampeding patterns
• Inefficient cache keys

HTTP Events

Monitors external API calls:

{
  "type": "http",
  "method": "POST",
  "url": "https://api.stripe.com/v1/charges",
  "request_headers": {
    "Authorization": "[REDACTED]",
    "Content-Type": "application/x-www-form-urlencoded"
  },
  "request_body": "amount=2999&currency=usd&source=tok_[REDACTED]",
  "response_status": 200,
  "response_headers": {
    "Content-Type": "application/json"
  },
  "response_body": "{\"id\": \"ch_[REDACTED]\", \"status\": \"succeeded\"}",
  "duration_ms": 1250,
  "connection_time_ms": 45,
  "dns_time_ms": 12
}

What to look for:

• Slow external APIs
• Failed API calls
• Timeout patterns
• High connection overhead

Queue Events

Tracks job dispatching and processing:

{
  "type": "job",
  "action": "dispatched",
  "job_class": "App\\Jobs\\SendWelcomeEmail",
  "queue": "emails",
  "delay_seconds": 0,
  "payload": {
    "user_id": 123,
    "template": "welcome"
  },
  "job_id": "job_abc123"
}

What to look for:

• Jobs failing to dispatch
• Queue backlogs
• Job processing delays
• Heavy job payloads

---

🔍 Analyzing Trace Data

Performance Analysis

Identifying Bottlenecks

1. Look at total duration first

   # Find slow requests
   php artisan chronotrace:list --min-duration=1000

2. Analyze the timeline

   # Focus on timing
   php artisan chronotrace:replay abc123 --timeline

3. Identify the biggest time consumers

   • Database queries >100ms
   • HTTP calls >500ms
   • Large memory allocations

Memory Analysis

{
  "memory_analysis": {
    "peak_mb": 45.2,
    "growth_points": [
      {
        "timestamp": "2024-08-06T14:30:15.145Z",
        "memory_mb": 25.1,
        "event": "Large collection loaded",
        "trigger": "User::with('posts', 'comments')->get()"
      }
    ],
    "recommendations": [
      "Use pagination for large collections",
      "Implement lazy loading",
      "Consider select() to limit columns"
    ]
  }
}

Error Analysis

When traces capture errors, they include:

{
  "error_info": {
    "type": "Illuminate\\Database\\QueryException",
    "message": "SQLSTATE[23000]: Integrity constraint violation",
    "file": "/app/Models/User.php",
    "line": 45,
    "stack_trace": "...",
    "context": {
      "sql": "INSERT INTO users (email) VALUES (?)",
      "bindings": ["duplicate@example.com"]
    }
  }
}

Error analysis workflow:

1. Identify the error point in the timeline
2. Examine events leading up to the error
3. Check for data validation issues
4. Look for race conditions or conflicts

---

📈 Trace Patterns

Common Patterns to Recognize

N+1 Query Pattern

[+0ms]   SELECT * FROM posts WHERE user_id = 123
[+5ms]   SELECT * FROM users WHERE id = 456    ← N+1 starts
[+8ms]   SELECT * FROM users WHERE id = 789    ← N+1 continues
[+11ms]  SELECT * FROM users WHERE id = 012    ← N+1 continues

Solution: Use eager loading

$posts = Post::with('user')->where('user_id', 123)->get();

Cache Stampede Pattern

[+0ms]   Cache MISS: expensive_calculation
[+1ms]   Cache MISS: expensive_calculation    ← Multiple misses
[+2ms]   Cache MISS: expensive_calculation    ← Concurrent requests
[+3ms]   Database query: expensive_calculation (1500ms)
[+1503ms] Cache SET: expensive_calculation

Solution: Use cache locks

Cache::lock('expensive_calculation')->get(function () {
    return Cache::remember('expensive_calculation', 3600, function () {
        return $this->performExpensiveCalculation();
    });
});

API Timeout Cascade

[+0ms]   HTTP POST: api.payment.com (timeout after 30s)
[+30000ms] HTTP POST: api.payment.com (retry #1, timeout)
[+60000ms] HTTP POST: api.payment.com (retry #2, timeout)
[+90000ms] ERROR: Payment processing failed

Solution: Implement circuit breaker and better timeout handling

---

🎯 Best Practices for Trace Analysis

1. Start with the Big Picture

Always begin by looking at:

• Total request duration
• HTTP status code
• Memory usage
• Error presence

2. Follow the Timeline

Examine events chronologically:

• What triggered the slow operation?
• Are there patterns in the timing?
• Where did things go wrong?

3. Focus on the Biggest Issues First

Prioritize optimization by impact:

• Operations taking >10% of total time
• Operations with error rates >1%
• Memory spikes >50% increase

4. Compare Similar Requests

Look at multiple traces for the same endpoint:

# Compare performance across similar requests
php artisan chronotrace:list --route="api/users" --limit=10

5. Use Filtering Effectively

Focus on specific aspects:

# Only database events
php artisan chronotrace:replay abc123 --filter=database

# Only slow events
php artisan chronotrace:replay abc123 --min-duration=100

# Only errors
php artisan chronotrace:list --status=error

---

🔧 Trace Metadata

Understanding Metadata

Each trace includes helpful metadata:

{
  "metadata": {
    "chronotrace_version": "1.0.0",
    "laravel_version": "11.x",
    "php_version": "8.3.0",
    "environment": "production",
    "server_info": {
      "hostname": "web-server-01",
      "ip": "10.0.1.100"
    },
    "capture_settings": {
      "mode": "record_on_error",
      "events_captured": ["database", "http", "jobs"],
      "pii_scrubbed": true
    }
  }
}

This helps with:

• Environment correlation - Compare dev vs production
• Version tracking - Identify when issues started
• Configuration validation - Verify settings are correct

---

📚 Related Documentation

• Basic Usage - Learn how to work with traces
• Event Capturing - Configure what events to capture
• Event Filtering - Focus on specific event types
• Performance Analysis - Advanced analysis techniques

---

Understanding traces is key to effective debugging! Take time to explore the structure and you'll quickly become proficient at identifying and solving performance issues.