Lock Debugging and Deadlock Detection

🔒 Lock debugging infrastructure with backtrace capture and interactive monitoring More...

Files
file	lock.c
	🔒 Lock debugging and deadlock detection with call stack backtraces and lock ordering validation

Detailed Description

🔒 Lock debugging infrastructure with backtrace capture and interactive monitoring

Lock Debugging and Deadlock Detection

Comprehensive lock debugging system for detecting deadlocks, lock contention, and lock ordering violations.

Overview

ascii-chat provides a complete lock debugging infrastructure that tracks all mutex and rwlock acquisitions with full backtrace capture. The system is only enabled in debug builds (when NDEBUG is not defined) and has zero overhead in release builds.

Implementation: lib/debug/lock.c, lib/debug/lock.h

Key Features:

• ✅ Lock acquisition tracking with backtraces (IMPLEMENTED)
• ✅ Lock hold time measurement and warnings (IMPLEMENTED)
• ✅ Interactive debug thread with keyboard monitoring (IMPLEMENTED)
• ✅ Lock usage statistics by code location (IMPLEMENTED)
• ✅ Orphaned release detection (double-unlock detection) (IMPLEMENTED)
• ✅ Thread-safe using uthash with rwlock protection (IMPLEMENTED)
• ❌ Automatic deadlock cycle detection (NOT YET IMPLEMENTED)
• ❌ Lock ordering validation (NOT YET IMPLEMENTED)

Architecture

Threading Model:

ascii-chat uses a per-client threading model where each client gets dedicated threads:

• 2 threads per client: 1 video render (60 FPS) + 1 audio render (172 FPS)
• Linear scaling: No shared bottlenecks, scales to 9+ clients
• Lock debugging thread: Additional monitoring thread when debugging enabled

Critical Lock Ordering Rules:

Always acquire locks in this exact order to prevent deadlocks:

1. Global RWLock (g_client_manager_rwlock in src/server/client_manager.c)
2. Per-Client Mutex (client->client_state_mutex in src/server/client.h)
3. Specialized Mutexes (g_stats_mutex in src/server/stats.c, etc.)

Usage

Enable Lock Debugging

Build with Debug Mode (lock debugging is automatic):

cmake -B build -DCMAKE_BUILD_TYPE=Debug
cmake --build build

Initialize in Code:

#include "debug/lock.h"
 
int main() {
    // Initialize lock debugging system
    lock_debug_init();
 
    // Start interactive debug thread (press '?' to print lock state)
    lock_debug_start_thread();
 
    // ... your application code ...
 
    // Cleanup before exit
    lock_debug_cleanup();
    lock_debug_cleanup_thread();
    return 0;
}

Instrument Your Locks

Replace lock calls with debug versions:

// Regular locks (no debugging)
mutex_lock(&my_mutex);
rwlock_rdlock(&my_rwlock);
rwlock_wrlock(&my_rwlock);
 
// Debug locks (with tracking) - only in debug builds
#ifndef NDEBUG
    debug_mutex_lock(&my_mutex, __FILE__, __LINE__, __func__);
    debug_rwlock_rdlock(&my_rwlock, __FILE__, __LINE__, __func__);
    debug_rwlock_wrlock(&my_rwlock, __FILE__, __LINE__, __func__);
#else
    mutex_lock(&my_mutex);
    rwlock_rdlock(&my_rwlock);
    rwlock_wrlock(&my_rwlock);
#endif

Or use convenience macros:

DEBUG_MUTEX_LOCK(&my_mutex);      // Automatically includes file/line/func
DEBUG_MUTEX_UNLOCK(&my_mutex);
DEBUG_RWLOCK_RDLOCK(&my_rwlock);
DEBUG_RWLOCK_WRLOCK(&my_rwlock);

Implemented Features

Lock Acquisition Tracking

Every tracked lock records:

• Lock address and type (mutex, rwlock read/write)
• Thread ID that acquired the lock
• Acquisition timestamp (CLOCK_MONOTONIC)
• Source file, line number, function name
• Full backtrace (up to 32 frames with symbol resolution)

Data Structure (lib/debug/lock.h:95):

struct lock_record {
    void *lock_address;
    lock_type_t lock_type;              // MUTEX, RWLOCK_READ, RWLOCK_WRITE
    uint64_t thread_id;
    struct timespec acquisition_time;
    const char *file_name;
    int line_number;
    const char *function_name;
    void *backtrace_buffer[32];         // Raw backtrace addresses
    int backtrace_size;
    char **backtrace_symbols;           // Symbolized backtrace
};

Lock Hold Time Warnings

Automatic warnings for long-held locks:

The debug thread automatically checks all held locks every 100ms and warns if any lock is held longer than 500ms (configurable via LOCK_HOLD_TIME_WARNING_MS).

Example warning (lib/debug/lock.c:404):

[WARN] Lock held for 1.234s (threshold: 500ms) - MUTEX at 0x7f8a4c001000
  Acquired: src/server/render.c:123 in render_video_thread()
  Thread ID: 140234567890123
  Backtrace from lock acquisition:
    #0: debug_mutex_lock at lib/debug/lock.c:1043
    #1: render_video_thread at src/server/render.c:123
    #2: asciichat_thread_wrapper at lib/platform/posix/thread.c:45

Interactive Debug Thread

Press '?' to print current lock state:

The debug thread (lib/debug/lock.c:484) monitors keyboard input and prints comprehensive lock information when you press '?':

=== LOCK DEBUG STATE ===
Historical Statistics:
  Total locks acquired: 1234567
  Total locks released: 1234560
  Currently held: 7
 
=== Currently Active Locks ===
Lock #1: MUTEX at 0x7f8a4c001000
  Thread ID: 140234567890123
  Acquired: src/server/client_manager.c:234 in client_add()
  Held for: 0.045 seconds
  Call stack (10 frames):
    #0: debug_mutex_lock at lib/debug/lock.c:1043
    #1: client_add at src/server/client_manager.c:234
    ...
 
=== Lock Usage Statistics by Code Location ===
Usage #1: RWLOCK_READ at src/server/client_manager.c:456 in client_find()
  Total acquisitions: 50000
  Total hold time: 5.123 ms
  Average hold time: 0.102 ms
  Max hold time: 2.345 ms
  Min hold time: 0.001 ms
 
=== Orphaned Releases ===
  No orphaned releases found.
=== End Lock Debug State ===

Orphaned Release Detection

Detects double-unlocks and mismatched lock/unlock:

If you call unlock on a lock that was never tracked (either because it wasn't acquired with debug functions, or it was already released), the system records an "orphaned release" with full backtrace.

Example (lib/debug/lock.c:969):

// This will create an orphaned release record:
mutex_lock(&my_mutex);          // Not tracked
debug_mutex_unlock(&my_mutex);  // Tracked unlock - no matching acquire!
 
// Warning:
[ERROR] MUTEX UNTRACKED RELEASED: 0x7f8a4c001000 at client.c:456
[ERROR] *** WARNING: MUTEX lock was acquired and tracked but record was lost! ***

Usage Statistics

Per-location statistics (lib/debug/lock.h:125):

Tracks aggregate stats for each unique file:line:function that acquires locks:

• Total acquisitions
• Total hold time (cumulative)
• Average/min/max hold time
• First and last acquisition timestamps

Implementation Details

Data Structures

Hash Tables (using uthash):

• g_lock_debug_manager.lock_records - Currently held locks
• g_lock_debug_manager.usage_stats - Statistics by code location
• g_lock_debug_manager.orphaned_releases - Double-unlock detections

Thread Safety:

• Each hash table protected by its own rwlock
• Atomic counters for statistics (total_locks_acquired, etc.)
• Careful locking order to prevent deadlocks in the debugger itself

Key Generation (lib/debug/lock.h:204):

// Combines lock address, type, and thread ID using FNV-1a hash
uint32_t lock_record_key(void *lock_address, lock_type_t lock_type) {
    struct {
        uintptr_t addr;
        lock_type_t lock_type;
        uint64_t thread_id;
    } key_data = {
        .addr = (uintptr_t)lock_address,
        .lock_type = lock_type,
        .thread_id = asciichat_thread_current_id()
    };
    return fnv1a_hash_bytes(&key_data, sizeof(key_data));
}

Recursion Prevention

Smart filtering (lib/debug/lock.c:775):

The system filters out its own internal lock operations to prevent infinite recursion:

• All log_*() functions
• All platform_*() functions
• All lock_debug*() functions
• Symbol resolution code
• During system initialization/shutdown

API Reference

Initialization

int lock_debug_init(void);              // Initialize system
int lock_debug_start_thread(void);      // Start debug thread
void lock_debug_cleanup(void);          // Cleanup resources
void lock_debug_cleanup_thread(void);   // Join debug thread

Lock Tracking

// Mutex tracking
int debug_mutex_lock(mutex_t *mutex, const char *file, int line, const char *func);
int debug_mutex_unlock(mutex_t *mutex, const char *file, int line, const char *func);
 
// RWLock read tracking
int debug_rwlock_rdlock(rwlock_t *rwlock, const char *file, int line, const char *func);
int debug_rwlock_rdunlock(rwlock_t *rwlock, const char *file, int line, const char *func);
 
// RWLock write tracking
int debug_rwlock_wrlock(rwlock_t *rwlock, const char *file, int line, const char *func);
int debug_rwlock_wrunlock(rwlock_t *rwlock, const char *file, int line, const char *func);

Statistics

void lock_debug_get_stats(uint64_t *total_acquired,
                          uint64_t *total_released,
                          uint32_t *currently_held);
bool lock_debug_is_initialized(void);
void lock_debug_print_state(void);
void lock_debug_trigger_print(void);  // Trigger print from another thread

Complete Example

#include "debug/lock.h"
#include "platform/abstraction.h"
 
mutex_t g_client_mutex;
 
void process_client(void) {
    // In debug builds, this captures full backtrace
    DEBUG_MUTEX_LOCK(&g_client_mutex);
 
    // Critical section
    // ...
 
    DEBUG_MUTEX_UNLOCK(&g_client_mutex);
}
 
int main() {
    // Initialize platform
    platform_init();
 
    // Initialize lock debugging
    lock_debug_init();
    lock_debug_start_thread();
 
    // Initialize mutex
    mutex_init(&g_client_mutex);
 
    // Your application code
    process_client();
 
    // During execution, press '?' to see all held locks
 
    // Cleanup
    mutex_destroy(&g_client_mutex);
    lock_debug_cleanup();
    lock_debug_cleanup_thread();
    platform_cleanup();
 
    return 0;
}

Best Practices

DO:

• Always acquire locks in the documented order (Global → Client → Specialized)
• Use DEBUG_MUTEX_LOCK/DEBUG_RWLOCK_* macros for automatic file/line capture
• Enable lock debugging during development to catch issues early
• Press '?' during execution to see current lock state
• Review lock usage statistics to find contention hotspots
• Keep lock hold times under 100ms (video is 60 FPS = 16.67ms/frame)

DON'T:

• Don't mix debug and non-debug lock functions (creates orphaned releases)
• Don't hold locks during slow operations (I/O, sleep, etc.)
• Don't ignore "lock held too long" warnings
• Don't disable lock debugging when tracking down deadlocks
• Don't forget to call lock_debug_cleanup() before exit

Future Enhancements

Not Yet Implemented:

• Automatic deadlock cycle detection via lock dependency graph
• Lock ordering validation (automatically detect order violations)
• Graphical visualization of lock dependency graphs
• Export lock statistics to JSON/CSV for analysis
• Per-thread lock stack tracking

References

Source Files:

• Implementation: lib/debug/lock.c (1394 lines)
• Header: lib/debug/lock.h
• Platform abstraction: lib/platform/abstraction.h
• Backtrace support: lib/platform/system.h (platform_backtrace, platform_backtrace_symbols)
• Hash tables: deps/ascii-chat-deps/uthash/src/uthash.h (included via platform/abstraction.h)

Key Functions:

• Lock tracking: lib/debug/lock.c:1043 (debug_mutex_lock)
• Hold time warnings: lib/debug/lock.c:404 (check_long_held_locks)
• Debug thread: lib/debug/lock.c:484 (debug_thread_func)
• State printing: lib/debug/lock.c:1175 (lock_debug_print_state)
• Orphan detection: lib/debug/lock.c:969 (debug_process_untracked_unlock)

See also

lib/debug/lock.h

lib/debug/lock.c

platform/abstraction.h

platform/posix/mutex.c

platform/posix/rwlock.c