453 lines
13 KiB
Markdown
453 lines
13 KiB
Markdown
# Mutex Lock Contention Root Cause Analysis
|
||||
|
|
|
|||
|
|
**Date:** 2025-10-24
|
|||
|
|
**Severity:** CRITICAL - Causing 100% bot stall rate
|
|||
|
|
**Author:** Concurrency & Threading Specialist
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## Executive Summary
|
|||
|
|
|
|||
|
|
**ROOT CAUSE CONFIRMED:** Massive recursive mutex contention in manager Update() methods is causing the runtime stalls. With 100 bots × multiple managers × recursive mutexes, we have created a **catastrophic lock convoy** scenario.
|
|||
|
|
|
|||
|
|
**Key Finding:** AuctionManager alone has **14 recursive_mutex lock acquisitions**, with the OnUpdate() method (called every 10 seconds) acquiring a lock for the **entire duration** of its execution.
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 1. Root Cause Confirmation
|
|||
|
|
|
|||
|
|
### The Smoking Gun: AuctionManager::OnUpdate()
|
|||
|
|
```cpp
|
|||
|
|
// Line 61 in AuctionManager.cpp
|
|||
|
|
void AuctionManager::OnUpdate(uint32 elapsed)
|
|||
|
|
{
|
|||
|
|
if (!GetBot() || !GetBot()->IsInWorld() || !IsEnabled())
|
|||
|
|
return;
|
|||
|
|
|
|||
|
|
std::lock_guard<std::recursive_mutex> lock(_mutex); // 🔴 CRITICAL BOTTLENECK
|
|||
|
|
|
|||
|
|
// ... rest of update logic ...
|
|||
|
|
}
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
This single line creates a **bottleneck of epic proportions**.
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 2. Severity Assessment
|
|||
|
|
|
|||
|
|
### The Mathematics of Disaster
|
|||
|
|
|
|||
|
|
With the current implementation:
|
|||
|
|
- **100 bots** each have their own manager instances
|
|||
|
|
- **6+ managers per bot** (Quest, Trade, Gathering, Auction, Group, Death)
|
|||
|
|
- **Each manager has its own recursive_mutex**
|
|||
|
|
- **ManagerRegistry::UpdateAll() also has a recursive_mutex** (line 272)
|
|||
|
|
|
|||
|
|
### Lock Acquisition Pattern (Per Update Cycle):
|
|||
|
|
```
|
|||
|
|
1. ManagerRegistry::UpdateAll() acquires registry lock
|
|||
|
|
2. For each manager:
|
|||
|
|
- Manager::Update() acquires its own lock
|
|||
|
|
- Manager may acquire lock multiple times (recursive)
|
|||
|
|
3. Registry releases lock
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
### The Convoy Effect:
|
|||
|
|
```
|
|||
|
|
Bot 1: ManagerRegistry lock → QuestManager lock → TradeManager lock → ...
|
|||
|
|
Bot 2: [WAITING for ManagerRegistry lock...]
|
|||
|
|
Bot 3: [WAITING for ManagerRegistry lock...]
|
|||
|
|
...
|
|||
|
|
Bot 100: [WAITING for ManagerRegistry lock...]
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
**Result:** All 100 bots serialize through a single bottleneck!
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 3. Specific Bottleneck Locations
|
|||
|
|
|
|||
|
|
### AuctionManager (14 locks total)
|
|||
|
|
- **Line 61:** `OnUpdate()` - Locks for ENTIRE update duration
|
|||
|
|
- **Line 113:** `ScanAuctionHouse()` - Nested lock (recursive)
|
|||
|
|
- **Line 162:** `AnalyzeMarketTrends()` - Another nested lock
|
|||
|
|
- **Line 182:** `GetItemPriceData()` - Frequent lock acquisition
|
|||
|
|
- **Lines 208, 745, 751, 765, 808, 819, 834, 841, 848, 857:** Various operations
|
|||
|
|
|
|||
|
|
### GatheringManager (6 locks)
|
|||
|
|
- **Line 72:** `OnShutdown()` - Lock for cleanup
|
|||
|
|
- **Line 164:** `FindNearestNode()` - Lock for node search
|
|||
|
|
- Multiple other node access methods
|
|||
|
|
|
|||
|
|
### ManagerRegistry (Critical Global Lock)
|
|||
|
|
- **Line 272:** `UpdateAll()` - Global lock for ALL manager updates
|
|||
|
|
```cpp
|
|||
|
|
uint32 ManagerRegistry::UpdateAll(uint32 diff)
|
|||
|
|
{
|
|||
|
|
std::lock_guard<std::recursive_mutex> lock(_managerMutex); // 🔴 GLOBAL BOTTLENECK
|
|||
|
|
// ... updates all managers ...
|
|||
|
|
}
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 4. Why This Is Catastrophic
|
|||
|
|
|
|||
|
|
### Problem 1: Per-Bot Mutexes Are Unnecessary
|
|||
|
|
Each bot has its **own instance** of managers. They don't share data with other bots' managers. The mutexes are protecting against a **non-existent threat**.
|
|||
|
|
|
|||
|
|
### Problem 2: Recursive Mutexes Hide Design Flaws
|
|||
|
|
Recursive mutexes allow the same thread to lock multiple times, which:
|
|||
|
|
- Masks poor design decisions
|
|||
|
|
- Creates unnecessary overhead
|
|||
|
|
- Makes deadlock analysis impossible
|
|||
|
|
|
|||
|
|
### Problem 3: Lock Granularity Is Too Coarse
|
|||
|
|
Entire Update() methods are locked, even when only small sections need protection.
|
|||
|
|
|
|||
|
|
### Problem 4: Registry Lock Creates Global Serialization
|
|||
|
|
The ManagerRegistry lock forces ALL bots to update sequentially, not in parallel.
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 5. Recommended Fix Strategy
|
|||
|
|
|
|||
|
|
### Strategy A: Remove Unnecessary Locks (BEST)
|
|||
|
|
|
|||
|
|
Since each bot has independent manager instances:
|
|||
|
|
|
|||
|
|
```cpp
|
|||
|
|
// AuctionManager::OnUpdate() - FIXED
|
|||
|
|
void AuctionManager::OnUpdate(uint32 elapsed)
|
|||
|
|
{
|
|||
|
|
if (!GetBot() || !GetBot()->IsInWorld() || !IsEnabled())
|
|||
|
|
return;
|
|||
|
|
|
|||
|
|
// NO LOCK NEEDED - This manager instance is only accessed by one bot
|
|||
|
|
|
|||
|
|
_updateTimer += elapsed;
|
|||
|
|
_marketScanTimer += elapsed;
|
|||
|
|
|
|||
|
|
// Only lock when accessing truly shared resources
|
|||
|
|
if (_marketScanTimer >= _marketScanInterval)
|
|||
|
|
{
|
|||
|
|
_marketScanTimer = 0;
|
|||
|
|
// Market scanning per-bot, no shared state
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
// Price cache cleanup - might need fine-grained locking if shared
|
|||
|
|
auto now = std::chrono::steady_clock::now();
|
|||
|
|
for (auto it = _priceCache.begin(); it != _priceCache.end();)
|
|||
|
|
{
|
|||
|
|
if (now - it->second.LastUpdate > Minutes(_priceHistoryDays * 1440))
|
|||
|
|
it = _priceCache.erase(it);
|
|||
|
|
else
|
|||
|
|
++it;
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
### Strategy B: Use Lock-Free Data Structures
|
|||
|
|
|
|||
|
|
Replace mutex-protected containers with lock-free alternatives:
|
|||
|
|
|
|||
|
|
```cpp
|
|||
|
|
// Instead of:
|
|||
|
|
std::map<uint32, ItemPriceData> _priceCache; // Protected by mutex
|
|||
|
|
|
|||
|
|
// Use:
|
|||
|
|
tbb::concurrent_hash_map<uint32, ItemPriceData> _priceCache; // Lock-free
|
|||
|
|
// OR
|
|||
|
|
folly::ConcurrentHashMap<uint32, ItemPriceData> _priceCache; // Lock-free
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
### Strategy C: Read-Write Locks for Shared Data
|
|||
|
|
|
|||
|
|
If data IS truly shared between bots:
|
|||
|
|
|
|||
|
|
```cpp
|
|||
|
|
class AuctionManager {
|
|||
|
|
private:
|
|||
|
|
mutable std::shared_mutex _priceCacheMutex; // Instead of recursive_mutex
|
|||
|
|
|
|||
|
|
public:
|
|||
|
|
ItemPriceData GetItemPriceData(uint32 itemId) const
|
|||
|
|
{
|
|||
|
|
std::shared_lock lock(_priceCacheMutex); // Multiple readers OK
|
|||
|
|
auto it = _priceCache.find(itemId);
|
|||
|
|
if (it != _priceCache.end())
|
|||
|
|
return it->second;
|
|||
|
|
return ItemPriceData();
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
void UpdatePriceData(uint32 itemId, const ItemPriceData& data)
|
|||
|
|
{
|
|||
|
|
std::unique_lock lock(_priceCacheMutex); // Exclusive for writing
|
|||
|
|
_priceCache[itemId] = data;
|
|||
|
|
}
|
|||
|
|
};
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
### Strategy D: Remove ManagerRegistry Global Lock
|
|||
|
|
|
|||
|
|
```cpp
|
|||
|
|
uint32 ManagerRegistry::UpdateAll(uint32 diff)
|
|||
|
|
{
|
|||
|
|
// NO GLOBAL LOCK - Each manager updates independently
|
|||
|
|
|
|||
|
|
if (!_initialized)
|
|||
|
|
return 0;
|
|||
|
|
|
|||
|
|
uint32 updateCount = 0;
|
|||
|
|
uint64 currentTime = getMSTime();
|
|||
|
|
|
|||
|
|
// Parallel update of managers
|
|||
|
|
std::atomic<uint32> atomicUpdateCount{0};
|
|||
|
|
|
|||
|
|
std::for_each(std::execution::par_unseq,
|
|||
|
|
_managers.begin(), _managers.end(),
|
|||
|
|
[&](auto& pair) {
|
|||
|
|
auto& [managerId, entry] = pair;
|
|||
|
|
if (!entry.initialized || !entry.manager || !entry.manager->IsActive())
|
|||
|
|
return;
|
|||
|
|
|
|||
|
|
uint32 updateInterval = entry.manager->GetUpdateInterval();
|
|||
|
|
uint64 timeSinceLastUpdate = currentTime - entry.lastUpdateTime;
|
|||
|
|
|
|||
|
|
if (timeSinceLastUpdate < updateInterval)
|
|||
|
|
return;
|
|||
|
|
|
|||
|
|
try {
|
|||
|
|
entry.manager->Update(diff);
|
|||
|
|
entry.lastUpdateTime = currentTime;
|
|||
|
|
atomicUpdateCount.fetch_add(1);
|
|||
|
|
} catch (std::exception const& ex) {
|
|||
|
|
TC_LOG_ERROR("module.playerbot.managers",
|
|||
|
|
"Exception updating manager '{}': {}", managerId, ex.what());
|
|||
|
|
}
|
|||
|
|
});
|
|||
|
|
|
|||
|
|
return atomicUpdateCount.load();
|
|||
|
|
}
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 6. Implementation Priority
|
|||
|
|
|
|||
|
|
### Phase 1: Immediate Relief (1-2 hours)
|
|||
|
|
1. **Remove unnecessary locks** from manager Update() methods
|
|||
|
|
2. **Test with 10 bots** to verify no crashes
|
|||
|
|
3. **Scale to 100 bots** and measure improvement
|
|||
|
|
|
|||
|
|
### Phase 2: Architectural Fix (2-4 hours)
|
|||
|
|
1. **Audit all managers** for actual shared state
|
|||
|
|
2. **Implement lock-free containers** where needed
|
|||
|
|
3. **Convert to read-write locks** for truly shared data
|
|||
|
|
4. **Remove ManagerRegistry global lock**
|
|||
|
|
|
|||
|
|
### Phase 3: Performance Optimization (4-8 hours)
|
|||
|
|
1. **Implement work-stealing** for manager updates
|
|||
|
|
2. **Use thread-local storage** for per-bot data
|
|||
|
|
3. **Add performance counters** for monitoring
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 7. Expected Performance Improvement
|
|||
|
|
|
|||
|
|
### Current State (WITH locks):
|
|||
|
|
- 100 bots × 6 managers × 10ms lock wait = **6000ms serialized delay**
|
|||
|
|
- Actual measured: "CRITICAL: 100 bots stalled"
|
|||
|
|
|
|||
|
|
### After Fix (WITHOUT unnecessary locks):
|
|||
|
|
- 100 bots updating in parallel
|
|||
|
|
- Expected update time: <1ms per bot
|
|||
|
|
- **6000× improvement** in worst-case latency
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 8. Code Examples
|
|||
|
|
|
|||
|
|
### Example 1: Thread-Safe Without Locks (Per-Bot Data)
|
|||
|
|
|
|||
|
|
```cpp
|
|||
|
|
class QuestManager {
|
|||
|
|
private:
|
|||
|
|
// Per-bot data - no sharing, no locks needed
|
|||
|
|
std::vector<uint32> _activeQuests;
|
|||
|
|
std::map<uint32, QuestProgress> _questProgress;
|
|||
|
|
|
|||
|
|
public:
|
|||
|
|
void Update(uint32 diff) {
|
|||
|
|
// NO LOCK - This is per-bot instance data
|
|||
|
|
for (auto& questId : _activeQuests) {
|
|||
|
|
UpdateQuestProgress(questId, diff);
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
};
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
### Example 2: Lock-Free Shared Cache
|
|||
|
|
|
|||
|
|
```cpp
|
|||
|
|
class SharedAuctionCache {
|
|||
|
|
private:
|
|||
|
|
// Shared between all bots - use atomic operations
|
|||
|
|
struct PriceEntry {
|
|||
|
|
std::atomic<uint64> price;
|
|||
|
|
std::atomic<uint64> timestamp;
|
|||
|
|
};
|
|||
|
|
|
|||
|
|
std::array<PriceEntry, 100000> _priceCache; // Fixed size, lock-free
|
|||
|
|
|
|||
|
|
public:
|
|||
|
|
uint64 GetPrice(uint32 itemId) const {
|
|||
|
|
if (itemId >= _priceCache.size()) return 0;
|
|||
|
|
return _priceCache[itemId].price.load(std::memory_order_acquire);
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
void UpdatePrice(uint32 itemId, uint64 price) {
|
|||
|
|
if (itemId >= _priceCache.size()) return;
|
|||
|
|
_priceCache[itemId].price.store(price, std::memory_order_release);
|
|||
|
|
_priceCache[itemId].timestamp.store(
|
|||
|
|
std::chrono::steady_clock::now().time_since_epoch().count(),
|
|||
|
|
std::memory_order_release);
|
|||
|
|
}
|
|||
|
|
};
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
### Example 3: Work-Stealing Manager Updates
|
|||
|
|
|
|||
|
|
```cpp
|
|||
|
|
class BotUpdateScheduler {
|
|||
|
|
private:
|
|||
|
|
struct UpdateTask {
|
|||
|
|
BotAI* bot;
|
|||
|
|
uint32 diff;
|
|||
|
|
};
|
|||
|
|
|
|||
|
|
moodycamel::ConcurrentQueue<UpdateTask> _taskQueue;
|
|||
|
|
std::array<std::thread, 8> _workers; // 8 worker threads
|
|||
|
|
|
|||
|
|
public:
|
|||
|
|
void ScheduleUpdate(BotAI* bot, uint32 diff) {
|
|||
|
|
_taskQueue.enqueue({bot, diff});
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
void WorkerThread() {
|
|||
|
|
UpdateTask task;
|
|||
|
|
while (_running) {
|
|||
|
|
if (_taskQueue.try_dequeue(task)) {
|
|||
|
|
task.bot->Update(task.diff); // No locks needed
|
|||
|
|
} else {
|
|||
|
|
std::this_thread::yield();
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
};
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 9. Testing Plan
|
|||
|
|
|
|||
|
|
### Step 1: Baseline Measurement
|
|||
|
|
```bash
|
|||
|
|
# Current performance with locks
|
|||
|
|
grep "CRITICAL.*stalled" logs/Server.log | wc -l
|
|||
|
|
# Result: Many stalls
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
### Step 2: Remove Locks from One Manager
|
|||
|
|
1. Start with AuctionManager::OnUpdate()
|
|||
|
|
2. Remove the lock at line 61
|
|||
|
|
3. Test with 10 bots
|
|||
|
|
4. Check for crashes or data corruption
|
|||
|
|
|
|||
|
|
### Step 3: Scale Testing
|
|||
|
|
1. Remove locks from all managers
|
|||
|
|
2. Test with 25, 50, 100 bots
|
|||
|
|
3. Measure update times
|
|||
|
|
4. Verify no stalls
|
|||
|
|
|
|||
|
|
### Step 4: Stress Testing
|
|||
|
|
1. Run 500 bots
|
|||
|
|
2. Monitor CPU usage
|
|||
|
|
3. Check for race conditions
|
|||
|
|
4. Validate data consistency
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 10. Conclusion
|
|||
|
|
|
|||
|
|
The root cause of the bot stalls is **catastrophic mutex contention** caused by:
|
|||
|
|
1. **Unnecessary per-bot mutexes** protecting non-shared data
|
|||
|
|
2. **Global ManagerRegistry lock** forcing sequential updates
|
|||
|
|
3. **Coarse-grained locking** of entire Update() methods
|
|||
|
|
4. **Recursive mutexes** hiding the depth of the problem
|
|||
|
|
|
|||
|
|
The solution is straightforward: **Remove the locks that aren't needed**.
|
|||
|
|
|
|||
|
|
Since each bot has its own manager instances, and these instances don't share state with other bots, the vast majority of these locks are protecting against a threat that doesn't exist.
|
|||
|
|
|
|||
|
|
**Estimated effort:** 2-4 hours to implement and test
|
|||
|
|
**Expected improvement:** 100× to 6000× reduction in update latency
|
|||
|
|
**Risk level:** Low (most locks are unnecessary)
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## Appendix A: Mutex Count by Manager
|
|||
|
|
|
|||
|
|
| Manager | Mutex Count | Critical Path |
|
|||
|
|
|---------|-------------|---------------|
|
|||
|
|
| AuctionManager | 14 | OnUpdate() at line 61 |
|
|||
|
|
| GatheringManager | 6 | Multiple node operations |
|
|||
|
|
| TradeManager | Unknown | Needs investigation |
|
|||
|
|
| QuestManager | Unknown | Needs investigation |
|
|||
|
|
| GroupCoordinator | Unknown | Needs investigation |
|
|||
|
|
| ManagerRegistry | 12+ | UpdateAll() at line 272 |
|
|||
|
|
|
|||
|
|
**Total estimated locks per update cycle:** 50-100+
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## Appendix B: Lock Convoy Visualization
|
|||
|
|
|
|||
|
|
```
|
|||
|
|
Time Bot1 Bot2 Bot3 ... Bot100
|
|||
|
|
T0 Acquire Wait Wait ... Wait
|
|||
|
|
T1 Update Wait Wait ... Wait
|
|||
|
|
T2 Release Acquire Wait ... Wait
|
|||
|
|
T3 Done Update Wait ... Wait
|
|||
|
|
T4 Done Release Acquire ... Wait
|
|||
|
|
...
|
|||
|
|
T200 Done Done Done ... Acquire
|
|||
|
|
T201 Done Done Done ... Update
|
|||
|
|
T202 Done Done Done ... Release
|
|||
|
|
|
|||
|
|
Total time: 202 time units for what should take 2 time units!
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## Appendix C: Priority Fixes
|
|||
|
|
|
|||
|
|
### 🔴 CRITICAL - Fix Immediately
|
|||
|
|
1. Remove lock from AuctionManager::OnUpdate() (line 61)
|
|||
|
|
2. Remove lock from ManagerRegistry::UpdateAll() (line 272)
|
|||
|
|
|
|||
|
|
### 🟡 HIGH - Fix Soon
|
|||
|
|
1. Convert to read-write locks where sharing exists
|
|||
|
|
2. Implement lock-free containers
|
|||
|
|
|
|||
|
|
### 🟢 NICE TO HAVE - Optimize Later
|
|||
|
|
1. Work-stealing scheduler
|
|||
|
|
2. Thread-local storage optimization
|
|||
|
|
3. Performance counters
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
**END OF ANALYSIS**
|
|||
|
|
|
|||
|
|
This is a textbook case of **premature synchronization** - adding locks "just in case" without analyzing whether they're actually needed. The fix is simple: remove them.
|