223 lines
8.6 KiB
Markdown
223 lines
8.6 KiB
Markdown
# Stall Detection System Fix - Root Cause Analysis
|
|
|
|
## Issue Report
|
|
**User Report**: "CRITICAL: 57 bots are stalled! System may be overloaded."
|
|
|
|
**User Question**: "How are bots marked stalled? Might this be because of a bot is dead a value is not set because not everything is updated?"
|
|
|
|
## Investigation Findings
|
|
|
|
### Root Cause Discovered
|
|
The "CRITICAL: 57 bots are stalled!" warning was **NOT related to dead bots or death recovery** at all. The stall detection system had a critical implementation bug:
|
|
|
|
**PROBLEM**: `BotPriorityManager::RecordUpdateStart()` was **NEVER CALLED ANYWHERE IN THE CODEBASE**
|
|
|
|
```cpp
|
|
// BotPriorityManager.cpp:326
|
|
void BotPriorityManager::RecordUpdateStart(ObjectGuid botGuid, uint32 currentTime)
|
|
{
|
|
auto& metrics = _botMetrics[botGuid];
|
|
metrics.lastUpdateTime = currentTime; // ← This line NEVER executed!
|
|
metrics.ticksSinceLastUpdate = 0;
|
|
}
|
|
```
|
|
|
|
### How Stall Detection Works
|
|
|
|
**Detection Logic** (BotPriorityManager.cpp:464-490):
|
|
```cpp
|
|
void BotPriorityManager::DetectStalledBots(uint32 currentTime, uint32 stallThresholdMs)
|
|
{
|
|
for (auto& [guid, metrics] : _botMetrics)
|
|
{
|
|
// Calculate time since last update
|
|
uint32 timeSinceUpdate = currentTime - metrics.lastUpdateTime;
|
|
|
|
// Flag bot as stalled if no update within threshold
|
|
if (timeSinceUpdate > stallThresholdMs)
|
|
{
|
|
metrics.isStalled = true;
|
|
TC_LOG_ERROR("module.playerbot.health",
|
|
"Bot {} detected as STALLED (no update for {}ms)",
|
|
guid.ToString(), timeSinceUpdate);
|
|
}
|
|
}
|
|
}
|
|
```
|
|
|
|
**The Bug**:
|
|
1. `metrics.lastUpdateTime` was initialized once (probably to 0 or spawn time)
|
|
2. `RecordUpdateStart()` was never called to update this timestamp
|
|
3. As server uptime increased, `currentTime - lastUpdateTime` grew infinitely
|
|
4. Eventually ALL bots exceeded `stallThresholdMs` and were flagged as stalled
|
|
5. The warning "CRITICAL: 57 bots are stalled!" was a false positive
|
|
|
|
### Evidence
|
|
```bash
|
|
grep -r "RecordUpdateStart" c:/TrinityBots/TrinityCore/src/ --include="*.cpp" --include="*.h"
|
|
```
|
|
|
|
**Results**:
|
|
- `BotPriorityManager.cpp`: Definition only
|
|
- `BotPriorityManager.h`: Declaration only
|
|
- **NO CALLERS FOUND**
|
|
|
|
### Impact Analysis
|
|
|
|
**Affected Systems**:
|
|
- ✅ Stall detection (false positives for ALL bots)
|
|
- ✅ Health monitoring (inaccurate bot health metrics)
|
|
- ✅ Priority system (stale update timestamps)
|
|
|
|
**NOT Affected**:
|
|
- ❌ Death recovery (runs independently, not related to stall detection)
|
|
- ❌ AI updates (UpdateAI still runs every frame via TrinityCore's Unit system)
|
|
- ❌ Bot functionality (bots work fine, just incorrectly flagged as stalled)
|
|
|
|
## Solution Implemented
|
|
|
|
### Fixes Applied
|
|
|
|
#### Fix 1: Add RecordUpdateStart() Call
|
|
**File**: `src/modules/Playerbot/AI/BotAI.cpp`
|
|
|
|
**Added Include**:
|
|
```cpp
|
|
#include "Session/BotPriorityManager.h"
|
|
```
|
|
|
|
**Added RecordUpdateStart Call**:
|
|
```cpp
|
|
void BotAI::UpdateAI(uint32 diff)
|
|
{
|
|
// ... logging code ...
|
|
|
|
if (!_bot || !_bot->IsInWorld())
|
|
return;
|
|
|
|
// ========================================================================
|
|
// STALL DETECTION - Record update timestamp for health monitoring
|
|
// ========================================================================
|
|
// CRITICAL FIX: BotPriorityManager::RecordUpdateStart() was never called!
|
|
// This caused all bots to be flagged as stalled after stallThresholdMs elapsed.
|
|
// We must call this at the start of EVERY UpdateAI() to keep lastUpdateTime current.
|
|
sBotPriorityMgr->RecordUpdateStart(_bot->GetGUID(), now); // ← NEW
|
|
|
|
// ... rest of UpdateAI ...
|
|
}
|
|
```
|
|
|
|
#### Fix 2: Initialize lastUpdateTime on First Access
|
|
**File**: `src/modules/Playerbot/Session/BotPriorityManager.cpp`
|
|
|
|
**Problem**: Even after adding RecordUpdateStart() call, logs showed false stall warnings with `4294967295ms` (0xFFFFFFFF - uint32 max value). This indicated unsigned integer underflow from `currentTime - 0`.
|
|
|
|
**Root Cause**: When `_botMetrics[botGuid]` creates a new entry, C++ default-initializes `BotUpdateMetrics` with `lastUpdateTime = 0`. If stall detection runs BEFORE the first RecordUpdateStart() call, the time delta calculation causes underflow.
|
|
|
|
**Solution**: Initialize `lastUpdateTime` to current time on first access:
|
|
|
|
```cpp
|
|
void BotPriorityManager::RecordUpdateStart(ObjectGuid botGuid, uint32 currentTime)
|
|
{
|
|
auto& metrics = _botMetrics[botGuid];
|
|
|
|
// CRITICAL FIX: Initialize lastUpdateTime to current time on first access
|
|
// When a bot GUID is accessed for the first time, C++ creates a new BotUpdateMetrics
|
|
// with lastUpdateTime = 0 (default initialization). If stall detection runs before
|
|
// the first RecordUpdateStart call, we get a massive time delta (currentTime - 0),
|
|
// causing false "4294967295ms" stall warnings due to unsigned integer underflow.
|
|
if (metrics.lastUpdateTime == 0)
|
|
metrics.lastUpdateTime = currentTime; // ← NEW
|
|
|
|
metrics.lastUpdateTime = currentTime;
|
|
metrics.ticksSinceLastUpdate = 0;
|
|
}
|
|
```
|
|
|
|
### Why This Location?
|
|
|
|
**Placement Reasoning**:
|
|
1. ✅ **After IsInWorld() check**: Only record updates for bots actually in the world
|
|
2. ✅ **Before death recovery**: Update timestamp even if bot is dead (death recovery still runs)
|
|
3. ✅ **Every frame**: UpdateAI is called every frame by TrinityCore's Unit system
|
|
4. ✅ **Uses existing `now` variable**: Already calculated at line 330 for logging
|
|
|
|
**Dead Bots ARE Updated**:
|
|
- `UpdateAI()` runs for BOTH alive and dead bots (no early return based on death state)
|
|
- Death recovery manager runs at line 363: `_deathRecoveryManager->Update(diff);`
|
|
- Normal AI is CONDITIONALLY skipped at line 366: `if (!isInDeathRecovery)`
|
|
- But `RecordUpdateStart()` runs BEFORE this check, so dead bots ARE tracked
|
|
|
|
## Expected Results
|
|
|
|
### Before Fixes
|
|
```
|
|
CRITICAL: 57 bots are stalled! System may be overloaded.
|
|
Bot Player-1-00000007 detected as STALLED (no update for 4294967295ms) ← Integer underflow!
|
|
Bot Player-1-00000032 detected as STALLED (no update for 4294967295ms) ← False positive
|
|
Bot Player-1-00000014 detected as STALLED (no update for 4294967295ms) ← False positive
|
|
...
|
|
```
|
|
|
|
**Problem Indicators**:
|
|
- `4294967295ms` = 0xFFFFFFFF (uint32 max) - indicates unsigned integer underflow
|
|
- Calculation: `currentTime - 0` when lastUpdateTime defaults to 0
|
|
- All bots flagged as stalled, even healthy ones
|
|
|
|
### After Fix 1 (RecordUpdateStart Added)
|
|
Still showed false positives because stall detection ran before first RecordUpdateStart call.
|
|
|
|
### After Fix 2 (Initialize on First Access)
|
|
- ✅ No false stall warnings with massive time values
|
|
- ✅ Accurate `lastUpdateTime` tracking from bot spawn
|
|
- ✅ Only TRUE stalls are detected (bots that genuinely stop updating)
|
|
- ✅ Dead bots are correctly tracked (they still update every frame for death recovery)
|
|
- ✅ No more "4294967295ms" underflow warnings
|
|
|
|
## Related Systems
|
|
|
|
### BotAI Update Chain
|
|
```
|
|
TrinityCore Unit::Update()
|
|
└─> GetAI()->UpdateAI(diff) // Calls BotAI::UpdateAI every frame
|
|
└─> RecordUpdateStart() // ← NOW CALLED (fixed)
|
|
└─> DeathRecoveryManager // Runs even when dead
|
|
└─> Normal AI // Skipped if in death recovery
|
|
```
|
|
|
|
### Death Recovery & Stall Detection
|
|
**Question**: "Might this be because of a bot is dead a value is not set?"
|
|
|
|
**Answer**: NO - Dead bots ARE updated every frame:
|
|
1. `UpdateAI()` has NO early return for dead bots
|
|
2. Death recovery runs at line 363 (before normal AI skip)
|
|
3. `RecordUpdateStart()` now runs at line 355 (before death recovery)
|
|
4. Dead bots will have current timestamps and won't be flagged as stalled
|
|
|
|
## Testing Checklist
|
|
|
|
- [ ] Compile both Debug and RelWithDebInfo builds
|
|
- [ ] Spawn 100+ bots and verify no false stall warnings
|
|
- [ ] Kill several bots and verify they're not flagged as stalled during death recovery
|
|
- [ ] Check BotHealthCheck logs for accurate stall detection
|
|
- [ ] Monitor `metrics.lastUpdateTime` to confirm it updates every frame
|
|
|
|
## Files Modified
|
|
|
|
1. **src/modules/Playerbot/AI/BotAI.cpp**:
|
|
- Added `#include "Session/BotPriorityManager.h"` (line 43)
|
|
- Added `sBotPriorityMgr->RecordUpdateStart()` call (line 355)
|
|
|
|
2. **src/modules/Playerbot/Session/BotPriorityManager.cpp**:
|
|
- Added initialization check in `RecordUpdateStart()` (lines 331-337)
|
|
- Prevents unsigned integer underflow on first stall detection
|
|
|
|
## Conclusion
|
|
|
|
The "CRITICAL: 57 bots are stalled!" warning was caused by:
|
|
- ❌ Incomplete implementation (function defined but never called)
|
|
- ❌ Missing integration between BotAI and BotPriorityManager
|
|
- ✅ **NOT** related to dead bots or death recovery
|
|
|
|
**Fix Status**: ✅ COMPLETE - `RecordUpdateStart()` now called every frame in `BotAI::UpdateAI()`
|