Profiling Tools Tutorial¶

MAID includes comprehensive profiling tools to help identify performance bottlenecks, memory leaks, and slow operations. This guide covers how to use the in-game profiling commands and interpret the results.

Table of Contents¶

Overview
Memory Profiling
Tick Profiling
Query Profiling
Network Profiling
Profile Sessions
Report Generation
CLI Tools
Integration with External Tools

Overview¶

Available Profiling Types¶

Type	Description	Command
Memory	Track memory allocations and usage	`@memory`
Tick	Measure game loop timing	`@timing`
Query	Database/world query performance	`@profile query`
Network	Network I/O and latency	`@profile network`
All	Combined profiling	`@profile start all`

Quick Start¶

# Start a profiling session
@profile start all

# Wait for some activity...

# Stop and view results
@profile stop
@profile report

Memory Profiling¶

Memory profiling helps identify memory leaks and excessive allocations.

@memory¶

View current memory usage.

@memory

Output:

Memory Usage Summary:
  Current:     256.5 MB
  Peak:        312.8 MB
  Available:   1,792 MB

  By Category:
    Entities:   45.2 MB (17.6%)
    Components: 89.3 MB (34.8%)
    World Data: 23.1 MB (9.0%)
    Systems:    12.4 MB (4.8%)
    Buffers:    35.6 MB (13.9%)
    Other:      50.9 MB (19.8%)

@memory top¶

Show top memory allocations.

@memory top 20

Output:

Top 20 Memory Allocations:
  #  Size      Count    Type/Location
  1  45.2 MB   123,456  Entity objects
  2  23.1 MB   89,012   PositionComponent
  3  18.7 MB   45,678   HealthComponent
  4  12.3 MB   12,345   Room data structures
  5  8.9 MB    5,432    Inventory items
  ...

@memory systems¶

Show memory usage by system/module.

@memory systems

Output:

Memory by System/Module:
  Module                              Allocated    Objects
  maid_stdlib.components              89.3 MB      234,567
  maid_classic_rpg.systems.combat     15.2 MB      12,345
  maid_engine.core.world              45.2 MB      123,456
  maid_engine.storage                 23.1 MB      5,678
  ...

@memory compare¶

Compare current memory with a previous snapshot.

@memory compare

Output:

Memory Comparison (vs 10 minutes ago):
  Current:  256.5 MB  (+12.3 MB / +5.0%)

  Changes by Category:
    Entities:      +2.1 MB  (4,567 new objects)
    Components:    +8.9 MB  (12,345 new objects)
    World Data:    +0.3 MB  (stable)
    Buffers:       +1.0 MB  (normal growth)

  Potential Leaks:
    ! CombatSystem._cached_targets: +5.2 MB (not clearing?)
    ! EventBus._handlers: +2.1 MB (handlers accumulating?)

@memory snapshot¶

Take a memory snapshot for later comparison.

@memory snapshot
@memory snapshot save "before_event"
@memory snapshot list
@memory snapshot compare "before_event"

@memory gc¶

Force garbage collection and show results.

@memory gc

Output:

Garbage Collection:
  Before:    256.5 MB
  Collected: 1,234 objects (12.3 MB)
  After:     244.2 MB

  Uncollectable: 0 objects (good!)

Tick Profiling¶

Tick profiling measures game loop performance.

@timing¶

Show tick timing summary.

@timing

Output:

Tick Timing Summary (last 1000 ticks):
  Target Rate:  4.0 ticks/sec (250ms budget)
  Actual Rate:  3.98 ticks/sec

  Timing:
    Average:    2.5 ms
    Median:     2.1 ms
    P95:        5.2 ms
    P99:        12.3 ms
    Max:        45.6 ms

  Budget Status:
    Under budget:  98.5%
    Over budget:   1.5% (15 ticks)

@timing systems¶

Show timing by ECS system.

@timing systems

Output:

System Timing (last 1000 ticks):
  System                  Avg (ms)  Max (ms)  % of Tick
  CombatSystem            0.85      12.3      34.0%
  MovementSystem          0.42      3.2       16.8%
  AISystem                0.38      8.7       15.2%
  InventorySystem         0.21      1.5       8.4%
  EffectsSystem           0.15      2.1       6.0%
  QuestSystem             0.12      1.8       4.8%
  Other                   0.37      5.4       14.8%
  Total                   2.50      45.6      100.0%

@timing slow¶

Show the slowest ticks.

@timing slow 10

Output:

Slowest 10 Ticks:
  #  Tick #    Duration   Timestamp            Cause
  1  345,678   45.6 ms    10:32:15.123         CombatSystem (mass combat)
  2  345,234   32.1 ms    10:31:45.456         AISystem (pathfinding)
  3  344,890   28.7 ms    10:31:12.789         CombatSystem (AoE spell)
  ...

Use @timing detail <tick#> for more info.

@timing detail¶

Get detailed breakdown of a specific tick.

@timing detail 345678

Output:

Tick #345,678 Detail (45.6 ms total):
  Phase          Duration   Details
  Pre-tick       0.2 ms     Input processing
  Systems        44.8 ms    See breakdown below
  Events         0.4 ms     23 events processed
  Post-tick      0.2 ms     State sync

  System Breakdown:
    CombatSystem    38.2 ms   Mass combat: 45 participants
      - Damage calc:  25.1 ms
      - Hit checks:   8.3 ms
      - Effects:      4.8 ms
    AISystem        4.2 ms    Pathfinding for 12 NPCs
    MovementSystem  1.5 ms    Normal
    Other           0.9 ms    Normal

@timing history¶

Show recent tick timing history (for graphing).

@timing history 60

Output:

Tick History (last 60 ticks):
  Tick      Duration  Systems
  345,680   2.1 ms    ####
  345,679   2.3 ms    #####
  345,678   45.6 ms   ##################################################
  345,677   2.0 ms    ####
  ...

Query Profiling¶

Track database and world query performance.

Start Query Profiling¶

@profile start query

View Query Stats¶

@profile query stats

Output:

Query Statistics (session duration: 5 minutes):
  Total Queries:  12,345
  Total Time:     1,234 ms
  Avg per Query:  0.10 ms

  By Type:
    Entity Lookups:     5,678 (46%)   avg 0.05 ms
    Component Queries:  4,321 (35%)   avg 0.12 ms
    Room Queries:       1,234 (10%)   avg 0.15 ms
    Document Store:     1,112 (9%)    avg 0.25 ms

Slow Queries¶

@profile query slow 10

Output:

Slowest 10 Queries:
  #  Duration   Type              Query
  1  15.3 ms    Document Store    find({"type": "player", "online": true})
  2  12.1 ms    Component Query   world.query(AIComponent, PositionComponent)
  3  8.7 ms     Entity Lookup     get_entities_in_room(room_id, recursive=True)
  ...

Query Patterns¶

@profile query patterns

Output:

Query Patterns (potential optimizations):
  ! Repeated query in loop:
    world.get_entity(entity_id) called 456 times in CombatSystem.process()
    Consider: batch query or caching

  ! N+1 query pattern:
    For each player, querying inventory separately
    Consider: eager loading or batch query

  ! Unindexed field:
    Document query on "custom_field" - no index
    Consider: add index or restructure query

Network Profiling¶

Track network I/O and latency.

Start Network Profiling¶

@profile start network

View Network Stats¶

@profile network stats

Output:

Network Statistics (session duration: 5 minutes):
  Connections:
    Telnet:     42 active
    WebSocket:  15 active
    Admin API:  3 active

  Traffic:
    Bytes In:   1.2 MB   (4.0 KB/s avg)
    Bytes Out:  5.6 MB   (18.7 KB/s avg)
    Messages:   45,678   (152/s avg)

  Latency (client RTT):
    Average:    45 ms
    P95:        120 ms
    P99:        250 ms

Per-Connection Stats¶

@profile network connections

Output:

Connection Statistics:
  ID       Type      Duration   In        Out       Latency
  conn_1   Telnet    2h 15m     234 KB    1.2 MB    35 ms
  conn_2   Telnet    1h 30m     156 KB    890 KB    42 ms
  conn_3   WebSocket 45m        89 KB     456 KB    28 ms
  ...

Profile Sessions¶

Starting a Profile Session¶

@profile start <types> [duration]

Types: - memory - Memory tracking - tick - Tick timing - query - Query profiling - network - Network I/O - all - All types

Examples:

@profile start all                    # Start all profiling
@profile start memory tick            # Memory and tick only
@profile start all 5m                 # Profile for 5 minutes
@profile start tick 1000              # Profile for 1000 ticks

Session Status¶

@profile status

Output:

Profiling Session Status:
  Active:     Yes
  Started:    10:30:00 (5 minutes ago)
  Duration:   Until stopped

  Active Profilers:
    [x] Memory    (45 snapshots, 12.3 MB overhead)
    [x] Tick      (1,200 ticks recorded)
    [x] Query     (12,345 queries tracked)
    [x] Network   (active)

  Estimated Overhead: 3.2% CPU, 15.6 MB memory

Stopping a Session¶

@profile stop

Clearing Data¶

@profile clear         # Clear all profiling data
@profile clear memory  # Clear only memory data

Report Generation¶

Generate Report¶

@profile report [format]

Formats: - text - Human-readable text (default) - json - JSON format for programmatic use - html - HTML report with charts

Examples:

@profile report                # Text report to chat
@profile report json           # JSON output
@profile report html > report.html  # Save HTML report

Report Sections¶

@profile report --sections memory,timing

Export Report¶

@profile export <filename>

Examples:

@profile export profile_2024-01-15.json
@profile export profile_report.html

Sample Text Report¶

==========================================
MAID Performance Profile Report
Generated: 2024-01-15 10:35:00
Session Duration: 5 minutes
==========================================

## Memory Summary
Current Usage: 256.5 MB (Peak: 312.8 MB)
Growth Rate: +2.5 MB/min (normal)

Top Allocations:
  1. Entity objects: 45.2 MB
  2. PositionComponent: 23.1 MB
  3. HealthComponent: 18.7 MB

Potential Issues:
  - None detected

## Tick Timing Summary
Average Tick: 2.5 ms (budget: 250 ms)
Over Budget: 1.5% of ticks

Slowest Systems:
  1. CombatSystem: 0.85 ms avg (34%)
  2. MovementSystem: 0.42 ms avg (17%)
  3. AISystem: 0.38 ms avg (15%)

Recommendations:
  - Consider optimizing CombatSystem for mass combat
  - AISystem pathfinding spikes warrant investigation

## Query Summary
Total Queries: 12,345 (avg 0.10 ms)

Slow Queries:
  1. Document query on unindexed field (15.3 ms)

Recommendations:
  - Add index for frequently queried fields
  - Consider batch queries in CombatSystem

==========================================

CLI Tools¶

Profile from Command Line¶

# Start server with profiling enabled
uv run maid server start --profile

# Profile specific types
uv run maid server start --profile=memory,tick

# Generate profile report
uv run maid dev profile report --output report.html

# Analyze existing profile data
uv run maid dev profile analyze profile_data.json

Continuous Profiling¶

# Run server with continuous low-overhead profiling
uv run maid server start --profile-continuous

# Export data periodically
uv run maid dev profile export --continuous --interval 5m

Compare Profiles¶

# Compare two profile snapshots
uv run maid dev profile compare before.json after.json

Integration with External Tools¶

py-spy Integration¶

# Profile the running server with py-spy
py-spy record -o profile.svg --pid $(pgrep -f "maid server")

# Top-like view
py-spy top --pid $(pgrep -f "maid server")

memory_profiler Integration¶

# Add to your code for detailed memory profiling
from memory_profiler import profile

@profile
def my_expensive_function():
    ...

Prometheus Metrics¶

MAID exposes Prometheus metrics at /metrics:

# prometheus.yml
scrape_configs:
  - job_name: 'maid'
    static_configs:
      - targets: ['localhost:8080']

Key metrics: - maid_tick_duration_seconds - Tick timing histogram - maid_memory_bytes - Memory usage gauge - maid_entities_total - Entity count - maid_queries_total - Query count - maid_connections_active - Active connections

Grafana Dashboards¶

Import the MAID Grafana dashboard from docs/grafana/maid-dashboard.json:

Real-time tick timing
Memory usage over time
Query performance
Connection metrics

Best Practices¶

1. Profile in Production-Like Environment¶

Use similar hardware/resources
Test with realistic player counts
Include typical game activities

2. Establish Baselines¶

# Take baseline measurements
@profile start all 10m
# Wait for normal activity...
@profile export baseline.json

# Compare after changes
@profile start all 10m
# Wait...
@profile export after_change.json

# Compare
uv run maid dev profile compare baseline.json after_change.json

3. Profile Before Optimization¶

Always measure before optimizing:

@profile start tick
# Run the slow operation
@timing systems
# Now you know what to optimize

4. Watch for Profiling Overhead¶

Profiling itself has overhead: - Memory profiling: ~5-10% memory overhead - Tick profiling: ~1-2% CPU overhead - Query profiling: ~2-3% query overhead

Use @profile status to monitor overhead.

5. Regular Profiling Schedule¶

Daily: Quick tick timing check
Weekly: Full profile session
Before releases: Comprehensive profiling
After incidents: Targeted investigation

Profiling Tools Tutorial¶

Table of Contents¶

Overview¶

Available Profiling Types¶

Quick Start¶

Memory Profiling¶

@memory¶

@memory top¶

@memory systems¶

@memory compare¶

@memory snapshot¶

@memory gc¶

Tick Profiling¶

@timing¶

@timing systems¶

@timing slow¶

@timing detail¶

@timing history¶

Query Profiling¶

Start Query Profiling¶

View Query Stats¶

Slow Queries¶

Query Patterns¶

Network Profiling¶

Start Network Profiling¶

View Network Stats¶

Per-Connection Stats¶

Profile Sessions¶

Starting a Profile Session¶

Session Status¶

Stopping a Session¶

Clearing Data¶

Report Generation¶

Generate Report¶

Report Sections¶

Export Report¶

Sample Text Report¶

CLI Tools¶

Profile from Command Line¶

Continuous Profiling¶

Compare Profiles¶

Integration with External Tools¶

py-spy Integration¶

memory_profiler Integration¶

Prometheus Metrics¶

Grafana Dashboards¶

Best Practices¶

1. Profile in Production-Like Environment¶

2. Establish Baselines¶

3. Profile Before Optimization¶

4. Watch for Profiling Overhead¶

5. Regular Profiling Schedule¶

See Also¶