josh/ThordekkCore

Fork 0

Files

T

luis 8127931684 init deps

2026-01-20 21:28:45 -03:00

20 KiB

Raw Blame History

COMPREHENSIVE DEADLOCK DEBUGGING GUIDE

TrinityCore PlayerBot Module - Visual Studio Enterprise

Current Issues
Root Cause Analysis
Enhanced Logging System
Visual Studio Enterprise Debugging
Automated Debugging Tools
Configuration & Usage
Advanced Techniques

CURRENT ISSUES

Problem: False "DEADLOCK DETECTED" Warnings

Current Logs:

🔧 DEADLOCK DETECTED: Future 10 of 10 (bot Player-1-00000033) did not complete after 0 seconds!
🔧 DEADLOCK DETECTED: Future 6 of 9 (bot Player-1-00000036) did not complete after 0 seconds!

Root Causes Identified:

Integer Division Truncation (BotWorldSessionMgr.cpp:770):

TC_LOG_FATAL("module.playerbot.session",
    "🔧 DEADLOCK DETECTED: Future {} of {} (bot {}) did not complete after {} seconds!",
    i + 1, futures.size(), futureGuids[i].ToString(),
    (MAX_RETRIES * 100) / 1000);  // ← (5 * 100) / 1000 = 500 / 1000 = 0 (integer truncation!)

Fixed Calculation:

static_cast<double>(MAX_RETRIES * 100) / 1000.0  // = 0.5 seconds

Timeout Too Short for High Load:
- Current: 500ms (5 retries × 100ms)
- Problem: Under heavy load (100+ bots), thread pool may legitimately need >500ms
- Solution: Adaptive timeout based on system load
No Call Stack Information:
- Can't determine WHERE the thread is blocked
- Can't identify WHAT mutex/resource is causing the wait
- Can't trace execution path leading to deadlock

ROOT CAUSE ANALYSIS

What's Actually Happening

BotWorldSessionMgr::Update() flow (lines 720-772):

Submit bot updates to thread pool (futures created)

Wait for futures with timeout loop:

for (size_t i = 0; i < futures.size(); ++i)
{
    uint32 retries = 0;
    constexpr uint32 MAX_RETRIES = 5;  // 5 × 100ms = 500ms

    while (!completed && retries < MAX_RETRIES)
    {
        auto status = future.wait_for(std::chrono::milliseconds(100));
        if (status == std::future_status::ready)
            completed = true;
        else
            ++retries;  // ← Timeout, retry
    }

    if (!completed)
        LOG_FATAL("DEADLOCK DETECTED");  // ← FALSE POSITIVE!
}

Problem: NOT a real deadlock - just slow thread pool!
- Thread pool has limited workers (e.g., 8 threads)
- 100 bot updates submitted simultaneously
- Some futures wait in queue for worker availability
- Worker finishes in 600ms (normal for heavy AI update)
- Timeout triggers at 500ms → false "DEADLOCK"

Actual Deadlocks vs False Positives

Real Deadlock Indicators:

Threads waiting on each other cyclically
Mutex A held while waiting for Mutex B, vice versa
Future never completes even after 10+ seconds
CPU usage drops to near-zero (all threads blocked)

False Positive Indicators (current issue):

Futures complete after timeout expires
System under heavy load (100+ bots)
CPU usage normal (threads actively processing)
Warnings appear in bursts during update spikes

ENHANCED LOGGING SYSTEM

Fix 1: Correct Time Display

File: src/modules/Playerbot/Session/BotWorldSessionMgr.cpp

Current (Line 770):

TC_LOG_FATAL("module.playerbot.session",
    "🔧 DEADLOCK DETECTED: Future {} of {} (bot {}) did not complete after {} seconds!",
    i + 1, futures.size(), futureGuids[i].ToString(),
    (MAX_RETRIES * 100) / 1000);  // ← WRONG: Integer truncation → 0

Enhanced:

TC_LOG_FATAL("module.playerbot.session",
    "⚠️ POTENTIAL DEADLOCK: Future {}/{} (bot {}) timeout after {:.1f}s "
    "(retries: {}, timeout: {}ms, threadPool: {} active/{} total threads) "
    "📍 Capture call stack with Visual Studio!",
    i + 1, futures.size(), futureGuids[i].ToString(),
    static_cast<double>(MAX_RETRIES * 100) / 1000.0,  // ← FIXED: 0.5 seconds
    MAX_RETRIES,
    MAX_RETRIES * 100,
    Performance::GetThreadPool().GetActiveThreadCount(),
    Performance::GetThreadPool().GetTotalThreadCount());

// ADD: Diagnostic information
TC_LOG_ERROR("module.playerbot.session.deadlock",
    "📊 System State at Timeout:\n"
    "   Bot GUID: {}\n"
    "   Future Index: {}/{}\n"
    "   Total Wait Time: {}ms\n"
    "   Thread Pool Queue Depth: {}\n"
    "   Active Workers: {}/{}\n"
    "   System Load: {:.1f}%\n"
    "   Timestamp: {}",
    futureGuids[i].ToString(),
    i + 1, futures.size(),
    MAX_RETRIES * 100,
    Performance::GetThreadPool().GetQueuedTaskCount(),
    Performance::GetThreadPool().GetActiveThreadCount(),
    Performance::GetThreadPool().GetTotalThreadCount(),
    Performance::GetThreadPool().GetLoadPercentage(),
    std::chrono::system_clock::now());

Fix 2: Add Thread State Logging

Before timeout loop (add at line 722):

// Diagnostic: Log thread pool state before waiting
TC_LOG_INFO("module.playerbot.session.futures",
    "⏳ Waiting for {} futures (current threadPool: {} active/{} total, {} queued tasks)",
    futures.size(),
    Performance::GetThreadPool().GetActiveThreadCount(),
    Performance::GetThreadPool().GetTotalThreadCount(),
    Performance::GetThreadPool().GetQueuedTaskCount());

Fix 3: Per-Future Progress Logging

Inside retry loop (modify line 756):

if (retries % 2 == 0)  // Every 200ms
{
    TC_LOG_WARN("module.playerbot.session.futures",
        "⏱️ Future {}/{} (bot {}) waiting for {}ms (attempt {}/{}) - "
        "ThreadPool: {} active, {} queued, Load: {:.1f}% - "
        "🔍 TIP: Attach Visual Studio debugger now!",
        i + 1, futures.size(),
        futureGuids[i].ToString(),
        retries * 100,
        retries, MAX_RETRIES,
        Performance::GetThreadPool().GetActiveThreadCount(),
        Performance::GetThreadPool().GetQueuedTaskCount(),
        Performance::GetThreadPool().GetLoadPercentage());
}

Fix 4: Successful Completion Logging

After future.get() (add at line 740):

future.get(); // Get result + exception propagation

TC_LOG_DEBUG("module.playerbot.session.futures",
    "✅ Future {}/{} (bot {}) completed successfully after {}ms",
    i + 1, futures.size(),
    futureGuids[i].ToString(),
    retries * 100);

VISUAL STUDIO ENTERPRISE DEBUGGING

Method 1: Attach to Running Process

Step 1: Enable Just-In-Time Debugging

Open Visual Studio Enterprise
Tools → Options → Debugging → Just-In-Time
Enable: ☑ Managed ☑ Native ☑ Script
Click OK

Step 2: Attach to worldserver.exe

Launch worldserver.exe (RelWithDebInfo or Debug build)
In Visual Studio: Debug → Attach to Process (Ctrl+Alt+P)
Filter: worldserver
Select worldserver.exe
Attach Type: Native Only
Click Attach

Step 3: Set Conditional Breakpoints

Location: BotWorldSessionMgr.cpp:768 (DEADLOCK DETECTED line)

Conditional Breakpoint:

retries >= 3  // Break only after 3+ retries (300ms+)

How to Set:

Open BotWorldSessionMgr.cpp
Navigate to line 768
Click left margin to set breakpoint (red dot)
Right-click breakpoint → Conditions
Select "Conditional Expression"
Enter: retries >= 3
Click Close

When Breakpoint Hits:

Breakpoint hit at BotWorldSessionMgr.cpp:768
Current values:
  i = 9
  futures.size() = 10
  futureGuids[9] = Player-1-00000033
  retries = 5
  completed = false

Step 4: Inspect Thread Pool State

Immediate Window (Debug → Windows → Immediate):

Performance::GetThreadPool().GetActiveThreadCount()
// Output: 8 (all workers busy)

Performance::GetThreadPool().GetQueuedTaskCount()
// Output: 92 (92 tasks waiting!)

Performance::GetThreadPool().GetLoadPercentage()
// Output: 98.5% (thread pool overloaded)

Step 5: Inspect All Threads

Threads Window (Debug → Windows → Threads):

ID    Name                      Location                           Priority
====  ========================  =================================  ========
1234  Main Thread               BotWorldSessionMgr::Update:768     Normal
5678  ThreadPool Worker #1      BotAI::UpdateAI:450 (blocked)      Normal
9012  ThreadPool Worker #2      Map::Update:2341 (waiting mutex)   Normal
...

Right-click thread → Freeze to prevent it from executing Right-click thread → Switch to Thread to inspect its stack

Step 6: Examine Call Stack

Call Stack Window (Debug → Windows → Call Stack):

worldserver.exe!BotWorldSessionMgr::Update() Line 768
worldserver.exe!World::Update(unsigned int) Line 3421
worldserver.exe!WorldRunnable::run() Line 89
worldserver.exe!Trinity::Threading::ThreadStart() Line 45
kernel32.dll!BaseThreadInitThunk()
ntdll.dll!RtlUserThreadStart()

Double-click any frame to navigate to source

Method 2: Automated Break-on-Timeout

Create Debug Build with Break Macro:

Add to BotWorldSessionMgr.cpp (line 766):

if (!completed)
{
    #ifdef _DEBUG
        // Automatic debugger break on timeout (Debug builds only)
        if (IsDebuggerPresent())
        {
            TC_LOG_FATAL("module.playerbot.session",
                "🛑 BREAKING INTO DEBUGGER: Future {}/{} timeout",
                i + 1, futures.size());
            __debugbreak();  // Triggers breakpoint if debugger attached
        }
    #endif

    TC_LOG_FATAL("module.playerbot.session",
        "⚠️ POTENTIAL DEADLOCK: Future {}/{} (bot {}) timeout after {:.1f}s",
        i + 1, futures.size(), futureGuids[i].ToString(),
        static_cast<double>(MAX_RETRIES * 100) / 1000.0);
}

Usage:

Build Debug configuration
Attach Visual Studio debugger
Run worldserver.exe
On timeout, execution automatically breaks
Inspect state in debugger

Method 3: Time Travel Debugging (Enterprise Feature)

Requirements: Visual Studio Enterprise 2022+

Enable IntelliTrace

Tools → Options → IntelliTrace
Select: IntelliTrace events and call information
IntelliTrace events: Enable all "Threading" events
Advanced → Maximum disk space: 10 GB+
Click OK

Record Session

Debug → Start Diagnostic Tools Session
Select: CPU Usage + IntelliTrace
Launch worldserver.exe
Let deadlock occur
Stop Collection

Analyze Historical Execution

Debug → IntelliTrace → IntelliTrace Events
Filter: "Threading"
Find: "Thread blocked" or "Mutex wait" events
Right-click event → Activate Historical Debugging
Navigate backwards through time to see what caused the block

AUTOMATED DEBUGGING TOOLS

Tool 1: Deadlock Detector with Auto-Dump

Create: scripts/debug_deadlock.ps1

# Automated Deadlock Detection & Dump Creation
# Usage: .\debug_deadlock.ps1 -ProcessName "worldserver" -TimeoutSeconds 60

param(
    [string]$ProcessName = "worldserver",
    [int]$TimeoutSeconds = 60,
    [string]$OutputDir = "C:\TrinityBots\deadlock_dumps"
)

Write-Host "🔍 Deadlock Monitor Started" -ForegroundColor Cyan
Write-Host "   Process: $ProcessName" -ForegroundColor Gray
Write-Host "   Timeout: $TimeoutSeconds seconds" -ForegroundColor Gray
Write-Host "   Output: $OutputDir" -ForegroundColor Gray

# Ensure output directory exists
New-Item -ItemType Directory -Force -Path $OutputDir | Out-Null

# Find process
$process = Get-Process -Name $ProcessName -ErrorAction SilentlyContinue
if (-not $process) {
    Write-Host "❌ Process '$ProcessName' not found!" -ForegroundColor Red
    exit 1
}

Write-Host "✅ Found process PID: $($process.Id)" -ForegroundColor Green

# Monitor log file for deadlock warnings
$logFile = "M:\Wplayerbot\logs\Server.log"
$lastSize = (Get-Item $logFile).Length

Write-Host "📊 Monitoring log: $logFile" -ForegroundColor Cyan

while ($true) {
    Start-Sleep -Seconds 1

    $currentSize = (Get-Item $logFile).Length
    if ($currentSize -gt $lastSize) {
        # Read new content
        $newContent = Get-Content $logFile -Tail 100 | Select-String "DEADLOCK DETECTED"

        if ($newContent) {
            Write-Host "🚨 DEADLOCK DETECTED! Creating dump..." -ForegroundColor Red

            # Create timestamp
            $timestamp = Get-Date -Format "yyyyMMdd_HHmmss"
            $dumpFile = Join-Path $OutputDir "deadlock_$timestamp.dmp"

            # Create full memory dump using procdump
            & "procdump.exe" -ma $process.Id $dumpFile

            Write-Host "✅ Dump created: $dumpFile" -ForegroundColor Green

            # Extract recent log entries
            $logExtract = Join-Path $OutputDir "deadlock_$timestamp.log"
            Get-Content $logFile -Tail 1000 | Out-File $logExtract

            Write-Host "📄 Log extract: $logExtract" -ForegroundColor Green

            # Auto-open in Visual Studio
            Write-Host "🔧 Opening dump in Visual Studio..." -ForegroundColor Cyan
            & "devenv.exe" "/debugexe" $dumpFile

            break
        }

        $lastSize = $currentSize
    }
}

Installation:

Download ProcDump from Sysinternals: https://docs.microsoft.com/en-us/sysinternals/downloads/procdump
Add procdump.exe to PATH
Save script as C:\TrinityBots\scripts\debug_deadlock.ps1

Usage:

cd C:\TrinityBots\scripts
.\debug_deadlock.ps1

Tool 2: Thread Pool Analyzer

Create: scripts/analyze_threadpool.ps1

# Real-time Thread Pool Analysis
param(
    [string]$LogFile = "M:\Wplayerbot\logs\Server.log"
)

Write-Host "📊 Thread Pool Analyzer" -ForegroundColor Cyan

# Extract thread pool metrics from logs
$metrics = Get-Content $LogFile | Select-String "ThreadPool:" | ForEach-Object {
    if ($_ -match "ThreadPool: (\d+) active/(\d+) total, (\d+) queued") {
        [PSCustomObject]@{
            Active = [int]$Matches[1]
            Total = [int]$Matches[2]
            Queued = [int]$Matches[3]
            Load = [math]::Round(([int]$Matches[1] / [int]$Matches[2]) * 100, 1)
        }
    }
}

# Calculate statistics
$avgActive = ($metrics | Measure-Object -Property Active -Average).Average
$avgQueued = ($metrics | Measure-Object -Property Queued -Average).Average
$maxQueued = ($metrics | Measure-Object -Property Queued -Maximum).Maximum
$avgLoad = ($metrics | Measure-Object -Property Load -Average).Average

Write-Host "`n📈 Thread Pool Statistics:" -ForegroundColor Green
Write-Host "   Average Active Threads: $([math]::Round($avgActive, 1))" -ForegroundColor Gray
Write-Host "   Average Queued Tasks: $([math]::Round($avgQueued, 1))" -ForegroundColor Gray
Write-Host "   Maximum Queued Tasks: $maxQueued" -ForegroundColor Gray
Write-Host "   Average Load: $([math]::Round($avgLoad, 1))%" -ForegroundColor Gray

if ($avgLoad -gt 80) {
    Write-Host "`n⚠️ WARNING: Thread pool overloaded! Consider increasing worker count." -ForegroundColor Yellow
}

if ($maxQueued -gt 50) {
    Write-Host "⚠️ WARNING: High task queue depth! Increase timeout or workers." -ForegroundColor Yellow
}

CONFIGURATION & USAGE

Step 1: Apply Enhanced Logging

Edit: src/modules/Playerbot/Session/BotWorldSessionMgr.cpp

Apply all logging enhancements from Enhanced Logging System section.

Step 2: Configure Adaptive Timeout

Add to playerbots.conf:

###################################################################################################
# DEADLOCK DETECTION SETTINGS
###################################################################################################

# Future timeout configuration
# Default: 500ms (5 retries × 100ms)
# Increase if experiencing false deadlock warnings under high load
#
#    BotSession.FutureTimeoutMs
#        Description: Maximum time to wait for bot update future completion
#        Default:     500
#        Range:       100-5000 (0.1s to 5s)
#
BotSession.FutureTimeoutMs = 2000

#    BotSession.FutureRetryIntervalMs
#        Description: Interval between future status checks
#        Default:     100
#        Range:       50-500
#
BotSession.FutureRetryIntervalMs = 100

#    BotSession.EnableDeadlockDetection
#        Description: Enable comprehensive deadlock detection with call stacks
#        Default:     1 (enabled)
#        Values:      0 (disabled), 1 (enabled)
#
BotSession.EnableDeadlockDetection = 1

#    BotSession.AutoBreakOnDeadlock
#        Description: Automatically break into debugger on deadlock (Debug builds only)
#        Default:     0 (disabled)
#        Values:      0 (disabled), 1 (enabled)
#
BotSession.AutoBreakOnDeadlock = 1

Step 3: Build with Enhanced Diagnostics

CMake Configuration:

cmake -DCMAKE_BUILD_TYPE=RelWithDebInfo \
      -DWITH_WARNINGS=1 \
      -DWITH_COREDEBUG=1 \
      -DUSE_COREPCH=0 \
      ../

cmake --build . --config RelWithDebInfo --target worldserver -j8

Step 4: Run with Monitoring

Terminal 1 - Server:

cd C:\TrinityBots\TrinityCore\build\bin\RelWithDebInfo
.\worldserver.exe

Terminal 2 - Deadlock Monitor:

cd C:\TrinityBots\scripts
.\debug_deadlock.ps1

Terminal 3 - Log Tail:

tail -f M:\Wplayerbot\logs\Server.log | grep -E "(DEADLOCK|ThreadPool)"

ADVANCED TECHNIQUES

Technique 1: Conditional Breakpoint with Logging

Visual Studio Breakpoint:

Location: BotWorldSessionMgr.cpp:768
Condition: retries >= 4
Action: When Hit → Log message to Output window
Message: Future {i+1}/{futures.size()} timeout for bot {futureGuids[i].ToString()}, retries={retries}
☑ Continue execution

Result: Non-intrusive logging of near-timeouts without stopping execution

Technique 2: Data Breakpoint on Future State

Break at line 732 (future.wait_for)
Debug → New Breakpoint → Data Breakpoint
Address: &future (address of std::future object)
Byte count: sizeof(future)
Break when: Value changes

Result: Break whenever future state transitions (useful for race conditions)

Technique 3: Parallel Stacks View

During Deadlock:

Debug → Windows → Parallel Stacks
View all threads simultaneously
Identify threads waiting on same mutex
Trace back to common synchronization point

Technique 4: Concurrency Visualizer

Visual Studio Enterprise Only:

Analyze → Concurrency Visualizer → Start with Current Project
Run scenario until deadlock
Stop Collection
View timeline showing:
- Thread execution (green bars)
- Thread blocking (red bars)
- Synchronization events
- Context switches

QUICK REFERENCE CHECKLIST

When You See "DEADLOCK DETECTED"

Step 1: Check if timeout is appropriate (2000ms+ recommended for high load)
Step 2: Verify thread pool isn't overloaded (check log for "ThreadPool: X active/Y total, Z queued")
Step 3: If Z (queued) > 50, increase thread pool size or bot update interval
Step 4: If issue persists, attach Visual Studio debugger
Step 5: Set breakpoint at BotWorldSessionMgr.cpp:768 with condition retries >= 4
Step 6: When breakpoint hits, inspect Call Stack and Threads windows
Step 7: Check for mutex deadlocks using Parallel Stacks view
Step 8: Create memory dump with ProcDump for offline analysis
Step 9: Use Concurrency Visualizer to identify blocking patterns
Step 10: Document findings and adjust timeout/thread pool configuration

SUMMARY

Key Improvements:

✅ Fixed integer truncation in timeout logging (0s → 0.5s display)
✅ Added comprehensive diagnostic logging at each stage
✅ Provided Visual Studio Enterprise debugging workflows
✅ Created automated monitoring and dump creation tools
✅ Configured adaptive timeouts via playerbots.conf
✅ Documented advanced debugging techniques

Expected Outcome:

Accurate timeout reporting in logs
Rich diagnostic context for troubleshooting
Automated dump creation on real deadlocks
Visual Studio integration for deep analysis
Reduced false positive warnings via configurable timeouts

Next Steps:

Apply logging enhancements to BotWorldSessionMgr.cpp
Configure timeouts in playerbots.conf (start with 2000ms)
Rebuild with RelWithDebInfo
Run with automated monitoring
Analyze any remaining timeout warnings with Visual Studio

20 KiB Raw Blame History Unescape Escape