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 start query`
Network	Network I/O and latency	`@profile start 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, save, list, compare, and delete named memory snapshots.

Take a snapshot (auto-generated name):

@memory snapshot

Output:

Snapshot saved as '20240115_103500'
  Total: 256.50 MB (1,234,567 blocks)

Save with a custom name:

@memory snapshot save before_event

Output:

Snapshot saved as 'before_event'
  Total: 256.50 MB (1,234,567 blocks)

List saved snapshots:

@memory snapshot list

Output:

=== Saved Snapshots (3) ===
  before_event         2024-01-15 10:30:00   256.50 MB
  after_event          2024-01-15 10:35:00   268.80 MB
  20240115_104000      2024-01-15 10:40:00   244.20 MB

Compare a named snapshot to current state:

@memory snapshot compare before_event

Output:

=== Comparison: 'before_event' vs Current ===
Before (before_event): 256.50 MB
Current:               268.80 MB
Change:                +12.30 MB

New allocations: 42
  +5,242,880 bytes at maid_stdlib.components.health:45
  +2,145,678 bytes at maid_classic_rpg.systems.combat:123
  +1,024,000 bytes at maid_engine.core.world:89
  ...

Grown allocations: 15
  +1,048,576 bytes at maid_engine.storage.document_store:67
  ...

Delete a snapshot:

@memory snapshot delete before_event

Output:

Snapshot 'before_event' deleted.

@memory gc¶

Force garbage collection and display before/after diagnostics including objects collected, uncollectable objects, per-generation stats, and RSS memory impact.

@memory gc

Output:

=== Garbage Collection ===
Objects collected: 1,234
Uncollectable:     0

Per-generation counts (before -> after):
  Gen 0: 456 -> 12
  Gen 1: 78 -> 23
  Gen 2: 234 -> 234

Per-generation collection stats:
  Gen 0: collections 1500 -> 1501, collected 45678 -> 46912, uncollectable 0 -> 0
  Gen 1: collections 120 -> 120, collected 5678 -> 5678, uncollectable 0 -> 0
  Gen 2: collections 15 -> 16, collected 1234 -> 2468, uncollectable 0 -> 0

Process RSS: 256.50 MB -> 244.20 MB (freed 12.30 MB)

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¶

Show a detailed per-tick breakdown including total duration, delta, entity/room counts, events processed, and per-system timings with percentage of tick time.

@timing detail 345678

Output:

=== Tick #345678 Detail [SLOW] ===
Timestamp:    10:32:15.123
Total:        45.60 ms
Delta:        250.00 ms
Entities:     1,234
Rooms:        456
Events:       23

System time:  44.80 ms
Overhead:     0.80 ms

Per-system breakdown:
  CombatSystem                       38.20 ms ( 83.8%)
  AISystem                            4.20 ms (  9.2%)
  MovementSystem                      1.50 ms (  3.3%)
  EffectsSystem                       0.90 ms (  2.0%)

When called without a tick number, shows the most recent tick:

@timing detail

@timing history¶

Show recent tick timing history (for graphing).

@timing history

Output:

Tick History (last 20 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 a query profiling session, then use the @profile query subcommands to inspect results.

Start Query Profiling¶

@profile start query

View Query Stats¶

@profile query stats

Output:

=== Query Statistics ===
Total queries: 12,345
Avg duration: 0.10 ms
Min duration: 0.01 ms
Max duration: 15.30 ms
P99 duration: 1.25 ms
Queries/sec: 41.2
Slow queries: 8 (threshold: 10ms)

By operation:
  find: 5,678
  get: 4,321
  update: 1,234
  insert: 1,112

By collection:
  entities: 6,789
  rooms: 3,456
  documents: 2,100

Slow Queries¶

@profile query slow 10

Output:

=== Slowest 10 Queries ===
  1.    15.30ms  find({"type": "player", "online": true}) [players]
     from: maid_engine/storage/document_store.py:123
  2.    12.10ms  query(AIComponent, PositionComponent) [entities]
     from: ...maid_classic_rpg/systems/npc/ai.py:89
  3.     8.70ms  get_entities_in_room(room_id, recursive=True)
     from: ...maid_engine/core/world.py:456
  ...

Query Patterns¶

Detect repeated queries and N+1 query patterns.

@profile query patterns

Output:

=== Query Patterns ===
WARNING: 2 potential N+1 pattern(s) detected!

  world.get_entity(entity_id) [N+1!]
    count=456 avg=0.05ms total=22.80ms
    collections: entities
  inventory.get_items(player_id) [N+1!]
    count=123 avg=0.12ms total=14.76ms
    collections: items, inventories
  find({"zone": zone_id})
    count=89 avg=0.15ms total=13.35ms
    collections: rooms

Network Profiling¶

Track network I/O and latency. Start a network profiling session, then use the @profile network subcommands to inspect results.

Start Network Profiling¶

@profile start network

View Network Stats¶

@profile network stats

Output:

=== Network Statistics ===
Total connections: 60
Active connections: 42
Bytes in: 1.2 MB
Bytes out: 5.6 MB
Total: 6.8 MB
Messages in: 23,456
Messages out: 22,222
Avg msg size in: 54 bytes
Avg msg size out: 258 bytes
Max message size: 4.0 KB

By protocol:
  telnet: 42
  websocket: 15
  admin: 3

Per-Connection Stats¶

@profile network connections

Output:

=== Active Connections (42) ===
  a1b2c3d4 [telnet] 192.168.1.10:54321
    duration=8100.0s in=234.0 KB out=1.2 MB throughput=178.5 B/s
  e5f6a7b8 [telnet] 192.168.1.11:54322
    duration=5400.0s in=156.0 KB out=890.0 KB throughput=198.2 B/s
  c9d0e1f2 [websocket] 192.168.1.12:54323
    duration=2700.0s in=89.0 KB out=456.0 KB throughput=206.8 B/s
  ...

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 (comma-separated)
@profile start all 300                # Profile for 300 seconds
@profile start tick 60                # Profile ticks for 60 seconds

Session Status¶

@profile status

Output:

Profiling active: memory|tick|query|network
Session ID: a1b2c3d4
Elapsed: 300.0s
Remaining: 600.0s

If no session is active but a previous session completed:

No profiling session.
Last session: 300.00s (memory|tick|query|network)

Stopping a Session¶

@profile stop

Clearing Data¶

Clear profiling data for the current session — either all collectors or a specific type.

@profile clear             # Clear all profiling data
@profile clear memory      # Clear only memory data
@profile clear tick        # Clear only tick data
@profile clear query       # Clear only query data
@profile clear network     # Clear only network data

Output:

Cleared profiling data: memory, tick, query, network

Report Generation¶

Generate Report¶

@profile report [format]

Formats: - text - Human-readable text (default) - json - JSON format for programmatic use - html - HTML report saved to a file (cannot be displayed in-game)

Examples:

@profile report                # Text report to chat
@profile report json           # JSON output to chat
@profile report html           # HTML report saved to temp file

Export Report¶

Export profiling results to a file in the specified format.

@profile export <path> [--format text|json|html]

Examples:

@profile export profile_2024-01-15.json --format json
@profile export profile_report.html --format html
@profile export profile_report.txt --format text
@profile export profile_report.txt

Output:

Report exported to: profile_2024-01-15.json (45.2 KB, json)

Notes: - The --format flag is optional; defaults to text. - Requires a completed profiling session (run @profile stop first). - The file is written relative to the server's working directory.

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¶

# Run a profiling session (default: memory,tick for 60 seconds)
uv run maid dev profile

# Profile specific types for a duration
uv run maid dev profile --types memory,tick,query --duration 120

# Save report to a file
uv run maid dev profile --types all --duration 60 --output report.html

# Output as JSON to stdout
uv run maid dev profile --types memory --duration 30 --json

# Take a memory snapshot
uv run maid dev memory-snapshot --output snapshot.json --top 20 --depth 10

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 on the internal observability port (default 9090):

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

Key metrics: - maid_tick_duration_seconds - Tick timing histogram - maid_memory_usage_bytes - Memory usage gauge - maid_entities_total - Entity count - maid_db_query_duration_seconds - Database query timing histogram - maid_connections_total - 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 600
# Wait for normal activity...
@profile stop
@profile report

# Compare after changes
@profile start all 600
# Wait...
@profile stop
@profile report

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¶

Export Report¶

Sample Text Report¶

CLI Tools¶

Profile from Command Line¶

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¶