analyze_locks.go

package main

import (
	"bufio"
	"fmt"
	"os"
	"strings"
)

type lockInfo struct {
	lockType string
	cluster  string
	name     string
	id       string
}

func main() {
	logfile := "out2.txt"
	if len(os.Args) > 1 {
		logfile = os.Args[1]
	}

	f, err := os.Open(logfile)
	if err != nil {
		fmt.Fprintf(os.Stderr, "Error: Log file '%s' not found\n", logfile)
		os.Exit(1)
	}
	defer f.Close()

	starts := make(map[string]*lockInfo)
	acquires := make(map[string]*lockInfo)
	releases := make(map[string]struct{})

	scanner := bufio.NewScanner(f)
	for scanner.Scan() {
		line := scanner.Text()

		// Find LOGMU position
		idx := strings.Index(line, "LOGMU ")
		if idx == -1 {
			continue
		}
		rest := line[idx+6:] // skip "LOGMU "

		// Determine operation and lock type
		var op, lockType string
		if strings.HasPrefix(rest, "RLOCK ") {
			lockType = "RLOCK"
			rest = rest[6:]
		} else if strings.HasPrefix(rest, "LOCK ") {
			lockType = "LOCK"
			rest = rest[5:]
		} else {
			continue
		}

		if strings.HasPrefix(rest, "START ") {
			op = "START"
			rest = rest[6:]
		} else if strings.HasPrefix(rest, "ACQUIRED ") {
			op = "ACQUIRED"
			rest = rest[9:]
		} else if strings.HasPrefix(rest, "RELEASED ") {
			op = "RELEASED"
			rest = rest[9:]
		} else {
			continue
		}

		// Parse: (cluster) [name] id
		// rest is now: "(cluster) name id" or "(cluster) id"
		if len(rest) < 3 || rest[0] != '(' {
			continue
		}
		closeP := strings.Index(rest, ")")
		if closeP == -1 {
			continue
		}
		cluster := rest[1:closeP]
		rest = strings.TrimLeft(rest[closeP+1:], " ")

		// Split remaining by space
		parts := strings.Fields(rest)
		var name, id string
		if len(parts) == 2 {
			name = parts[0]
			id = parts[1]
		} else if len(parts) == 1 {
			name = "(unnamed)"
			id = parts[0]
		} else {
			continue
		}

		key := lockType + "|" + cluster + "|" + id

		switch op {
		case "START":
			starts[key] = &lockInfo{lockType, cluster, name, id}
		case "ACQUIRED":
			acquires[key] = &lockInfo{lockType, cluster, name, id}
		case "RELEASED":
			releases[key] = struct{}{}
		}
	}

	if err := scanner.Err(); err != nil {
		fmt.Fprintf(os.Stderr, "Error reading file: %v\n", err)
		os.Exit(1)
	}

	// Output
	fmt.Println("===============================================")
	fmt.Println("  LOCK CONTENTION ANALYSIS")
	fmt.Println("===============================================")
	fmt.Println()
	fmt.Println("=== STUCK: Started but never acquired (waiting for lock) ===")

	stuckCount := 0
	for key, info := range starts {
		if _, acquired := acquires[key]; !acquired {
			fmt.Printf("  %-5s | %-4s | %-25s | ID: %s\n", info.lockType, info.cluster, info.name, info.id)
			stuckCount++
		}
	}
	if stuckCount == 0 {
		fmt.Println("  (none)")
	}

	fmt.Println()
	fmt.Println("=== HELD: Acquired but never released (holding lock) ===")

	heldCount := 0
	for key, info := range acquires {
		if _, released := releases[key]; !released {
			fmt.Printf("  %-5s | %-4s | %-25s | ID: %s\n", info.lockType, info.cluster, info.name, info.id)
			heldCount++
		}
	}
	if heldCount == 0 {
		fmt.Println("  (none)")
	}

	fmt.Println()
	fmt.Println("=== SUMMARY ===")
	fmt.Printf("  Stuck waiting: %d\n", stuckCount)
	fmt.Printf("  Held:          %d\n", heldCount)
	fmt.Println()
}

analyze_locks.sh

#!/bin/bash
# Analyze lock contention from log file
# Usage: ./analyze_locks.sh [logfile]

LOGFILE="${1:-out2.txt}"

if [[ ! -f "$LOGFILE" ]]; then
    echo "Error: Log file '$LOGFILE' not found"
    exit 1
fi

awk '
/LOGMU (R?LOCK) START/ {
    if (match($0, /LOGMU (R?LOCK) START \(([^)]+)\) ([^ ]+) ([0-9]+)$/, arr)) {
        key = arr[1] "|" arr[2] "|" arr[4]
        starts[key]++
        lock_type[key] = arr[1]
        cluster[key] = arr[2]
        lock_name[key] = arr[3]
        lock_id[key] = arr[4]
    } else if (match($0, /LOGMU (R?LOCK) START \(([^)]+)\) ([0-9]+)$/, arr)) {
        key = arr[1] "|" arr[2] "|" arr[3]
        starts[key]++
        lock_type[key] = arr[1]
        cluster[key] = arr[2]
        lock_name[key] = "(unnamed)"
        lock_id[key] = arr[3]
    }
}
/LOGMU (R?LOCK) ACQUIRED/ {
    if (match($0, /LOGMU (R?LOCK) ACQUIRED \(([^)]+)\) ([^ ]+) ([0-9]+)$/, arr)) {
        key = arr[1] "|" arr[2] "|" arr[4]
        acquires[key]++
        acq_name[key] = arr[3]
        acq_type[key] = arr[1]
        acq_cluster[key] = arr[2]
        acq_id[key] = arr[4]
    } else if (match($0, /LOGMU (R?LOCK) ACQUIRED \(([^)]+)\) ([0-9]+)$/, arr)) {
        key = arr[1] "|" arr[2] "|" arr[3]
        acquires[key]++
    }
}
/LOGMU (R?LOCK) RELEASED/ {
    if (match($0, /LOGMU (R?LOCK) RELEASED \(([^)]+)\) ([^ ]+) ([0-9]+)$/, arr)) {
        key = arr[1] "|" arr[2] "|" arr[4]
        releases[key]++
    }
}
END {
    print "==============================================="
    print "  LOCK CONTENTION ANALYSIS"
    print "==============================================="
    print ""
    print "=== STUCK: Started but never acquired (waiting for lock) ==="
    stuck_count = 0
    for (key in starts) {
        s = starts[key]
        a = (key in acquires) ? acquires[key] : 0
        if (s > a) {
            printf "  %-5s | %-4s | %-25s | ID: %s\n", lock_type[key], cluster[key], lock_name[key], lock_id[key]
            stuck_count++
        }
    }
    if (stuck_count == 0) print "  (none)"
    print ""
    print "=== HELD: Acquired but never released (holding lock) ==="
    held_count = 0
    for (key in acquires) {
        a = acquires[key]
        r = (key in releases) ? releases[key] : 0
        if (a > r && length(acq_name[key]) > 0) {
            printf "  %-5s | %-4s | %-25s | ID: %s\n", acq_type[key], acq_cluster[key], acq_name[key], acq_id[key]
            held_count++
        }
    }
    if (held_count == 0) print "  (none - or unnamed locks being held)"
    print ""
    print "=== SUMMARY ==="
    printf "  Stuck waiting: %d\n", stuck_count
    printf "  Held (named):  %d\n", held_count
    print ""
}' "$LOGFILE"

logged_mutex.go

// Package loggedmu provides mutex wrappers with configurable logging and optional stack traces.
package loggedmu

import (
	"fmt"
	"math/rand/v2"
	"runtime"
	"strings"
	"sync"
)

// LogFunc is the signature for custom logging functions.
type LogFunc func(format string, args ...any)

var defaultLogFunc LogFunc = func(format string, args ...any) {
	fmt.Printf(format+"\n", args...)
}

// Mutex is a logged wrapper around sync.RWMutex.
type Mutex struct {
	name           string
	mu             sync.RWMutex
	logFunc        LogFunc
	backtraceDepth int // 0 = disabled
}

// Option configures a Mutex.
type Option func(*Mutex)

// WithName sets an identifier for this mutex instance.
func WithName(name string) Option {
	return func(m *Mutex) {
		m.name = name
	}
}

// WithLogFunc sets a custom logging function.
func WithLogFunc(fn LogFunc) Option {
	return func(m *Mutex) {
		m.logFunc = fn
	}
}

// WithBacktrace enables stack trace logging with the specified depth.
func WithBacktrace(depth int) Option {
	return func(m *Mutex) {
		m.backtraceDepth = depth
	}
}

// New creates a new logged Mutex.
func New(opts ...Option) *Mutex {
	m := &Mutex{
		logFunc: defaultLogFunc,
	}
	for _, opt := range opts {
		opt(m)
	}
	return m
}

func (m *Mutex) getCallerChain(skip, depth int) string {
	if depth <= 0 {
		return ""
	}
	pcs := make([]uintptr, depth)
	n := runtime.Callers(skip, pcs)
	if n == 0 {
		return ""
	}
	frames := runtime.CallersFrames(pcs[:n])

	var parts []string
	for {
		frame, more := frames.Next()
		name := frame.Function
		if idx := strings.LastIndex(name, "."); idx != -1 {
			name = name[idx+1:]
		}
		parts = append(parts, fmt.Sprintf("%s:%d", name, frame.Line))
		if !more || len(parts) >= depth {
			break
		}
	}
	return strings.Join(parts, " <- ")
}

func (m *Mutex) log(format string, args ...any) {
	if m.logFunc != nil {
		m.logFunc(format, args...)
	}
}

func (m *Mutex) formatPrefix(op string, id int) string {
	if m.name != "" {
		return fmt.Sprintf("LOGMU %s (%s) %d", op, m.name, id)
	}
	return fmt.Sprintf("LOGMU %s %d", op, id)
}

func (m *Mutex) formatWithTrace(prefix string) string {
	if m.backtraceDepth > 0 {
		trace := m.getCallerChain(4, m.backtraceDepth)
		if trace != "" {
			return fmt.Sprintf("%s [%s]", prefix, trace)
		}
	}
	return prefix
}

// Lock acquires the write lock.
func (m *Mutex) Lock() {
	id := rand.IntN(9999999)
	prefix := m.formatPrefix("LOCK", id)
	m.log("%s START", m.formatWithTrace(prefix))
	m.mu.Lock()
	m.log("%s ACQUIRED", m.formatWithTrace(prefix))
}

// Unlock releases the write lock.
func (m *Mutex) Unlock() {
	m.mu.Unlock()
}

// LockWithUnlock acquires the write lock and returns an unlock function.
func (m *Mutex) LockWithUnlock() func() {
	id := rand.IntN(9999999)
	prefix := m.formatPrefix("LOCK", id)
	trace := m.formatWithTrace(prefix)
	m.log("%s START", trace)
	m.mu.Lock()
	m.log("%s ACQUIRED", trace)
	return func() {
		m.log("%s RELEASED", trace)
		m.mu.Unlock()
	}
}

// RLock acquires the read lock.
func (m *Mutex) RLock() {
	id := rand.IntN(9999999)
	prefix := m.formatPrefix("RLOCK", id)
	m.log("%s START", m.formatWithTrace(prefix))
	m.mu.RLock()
	m.log("%s ACQUIRED", m.formatWithTrace(prefix))
}

// RUnlock releases the read lock.
func (m *Mutex) RUnlock() {
	m.mu.RUnlock()
}

// RLockWithUnlock acquires the read lock and returns an unlock function.
func (m *Mutex) RLockWithUnlock() func() {
	id := rand.IntN(9999999)
	prefix := m.formatPrefix("RLOCK", id)
	trace := m.formatWithTrace(prefix)
	m.log("%s START", trace)
	m.mu.RLock()
	m.log("%s ACQUIRED", trace)
	return func() {
		m.log("%s RELEASED", trace)
		m.mu.RUnlock()
	}
}

// SetBacktraceDepth changes the backtrace depth at runtime.
func (m *Mutex) SetBacktraceDepth(depth int) {
	m.backtraceDepth = depth
}

// SetLogFunc changes the logging function at runtime.
func (m *Mutex) SetLogFunc(fn LogFunc) {
	m.logFunc = fn
}