feat: add sync trace

Makefile

@@ -12,7 +12,13 @@ BUILDKIT_FLAVOR := arm-rockchip830-linux-uclibcgnueabihf
 BUILDKIT_PATH ?= /opt/jetkvm-native-buildkit
 SKIP_NATIVE_IF_EXISTS ?= 0
 SKIP_UI_BUILD ?= 0
+ENABLE_SYNC_TRACE ?= 0
+
 GO_BUILD_ARGS := -tags netgo,timetzdata,nomsgpack
+ifeq ($(ENABLE_SYNC_TRACE), 1)
+	GO_BUILD_ARGS := $(GO_BUILD_ARGS),synctrace
+endif
+
 GO_RELEASE_BUILD_ARGS := -trimpath $(GO_BUILD_ARGS)
 GO_LDFLAGS := \
   -s -w \

internal/sync/log.go

@@ -0,0 +1,149 @@
+//go:build synctrace
+
+package sync
+
+import (
+	"fmt"
+	"reflect"
+	"runtime"
+	"sync"
+	"time"
+
+	"github.com/jetkvm/kvm/internal/logging"
+	"github.com/rs/zerolog"
+)
+
+var defaultLogger = logging.GetSubsystemLogger("synctrace")
+
+func logTrace(msg string) {
+	if defaultLogger.GetLevel() > zerolog.TraceLevel {
+		return
+	}
+
+	logTrack(3).Trace().Msg(msg)
+}
+
+func logTrack(callerSkip int) *zerolog.Logger {
+	l := *defaultLogger
+	if l.GetLevel() > zerolog.TraceLevel {
+		return &l
+	}
+
+	pc, file, no, ok := runtime.Caller(callerSkip)
+	if ok {
+		l = l.With().
+			Str("file", file).
+			Int("line", no).
+			Logger()
+
+		details := runtime.FuncForPC(pc)
+		if details != nil {
+			l = l.With().
+				Str("func", details.Name()).
+				Logger()
+		}
+	}
+
+	return &l
+}
+
+func logLockTrack(i string) *zerolog.Logger {
+	l := logTrack(4).
+		With().
+		Str("index", i).
+		Logger()
+	return &l
+}
+
+var (
+	indexMu sync.Mutex
+
+	lockCount   map[string]int       = make(map[string]int)
+	unlockCount map[string]int       = make(map[string]int)
+	lastLock    map[string]time.Time = make(map[string]time.Time)
+)
+
+type trackable interface {
+	sync.Locker
+}
+
+func getIndex(t trackable) string {
+	ptr := reflect.ValueOf(t).Pointer()
+	return fmt.Sprintf("%x", ptr)
+}
+
+func increaseLockCount(i string) {
+	indexMu.Lock()
+	defer indexMu.Unlock()
+
+	if _, ok := lockCount[i]; !ok {
+		lockCount[i] = 0
+	}
+	lockCount[i]++
+
+	if _, ok := lastLock[i]; !ok {
+		lastLock[i] = time.Now()
+	}
+}
+
+func increaseUnlockCount(i string) {
+	indexMu.Lock()
+	defer indexMu.Unlock()
+
+	if _, ok := unlockCount[i]; !ok {
+		unlockCount[i] = 0
+	}
+	unlockCount[i]++
+}
+
+func logLock(t trackable) {
+	i := getIndex(t)
+	increaseLockCount(i)
+	logLockTrack(i).Trace().Msg("locking mutex")
+}
+
+func logUnlock(t trackable) {
+	i := getIndex(t)
+	increaseUnlockCount(i)
+	logLockTrack(i).Trace().Msg("unlocking mutex")
+}
+
+func logTryLock(t trackable) {
+	i := getIndex(t)
+	logLockTrack(i).Trace().Msg("trying to lock mutex")
+}
+
+func logTryLockResult(t trackable, l bool) {
+	if !l {
+		return
+	}
+	i := getIndex(t)
+	increaseLockCount(i)
+	logLockTrack(i).Trace().Msg("locked mutex")
+}
+
+func logRLock(t trackable) {
+	i := getIndex(t)
+	increaseLockCount(i)
+	logLockTrack(i).Trace().Msg("locking mutex for reading")
+}
+
+func logRUnlock(t trackable) {
+	i := getIndex(t)
+	increaseUnlockCount(i)
+	logLockTrack(i).Trace().Msg("unlocking mutex for reading")
+}
+
+func logTryRLock(t trackable) {
+	i := getIndex(t)
+	logLockTrack(i).Trace().Msg("trying to lock mutex for reading")
+}
+
+func logTryRLockResult(t trackable, l bool) {
+	if !l {
+		return
+	}
+	i := getIndex(t)
+	increaseLockCount(i)
+	logLockTrack(i).Trace().Msg("locked mutex for reading")
+}

internal/sync/mutex.go

@@ -0,0 +1,69 @@
+//go:build synctrace
+
+package sync
+
+import (
+	gosync "sync"
+)
+
+// Mutex is a wrapper around the sync.Mutex
+type Mutex struct {
+	mu gosync.Mutex
+}
+
+// Lock locks the mutex
+func (m *Mutex) Lock() {
+	logLock(m)
+	m.mu.Lock()
+}
+
+// Unlock unlocks the mutex
+func (m *Mutex) Unlock() {
+	logUnlock(m)
+	m.mu.Unlock()
+}
+
+// TryLock tries to lock the mutex
+func (m *Mutex) TryLock() bool {
+	logTryLock(m)
+	l := m.mu.TryLock()
+	logTryLockResult(m, l)
+	return l
+}
+
+// RWMutex is a wrapper around the sync.RWMutex
+type RWMutex struct {
+	mu gosync.RWMutex
+}
+
+// Lock locks the mutex
+func (m *RWMutex) Lock() {
+	logLock(m)
+	m.mu.Lock()
+}
+
+// Unlock unlocks the mutex
+func (m *RWMutex) Unlock() {
+	logUnlock(m)
+	m.mu.Unlock()
+}
+
+// RLock locks the mutex for reading
+func (m *RWMutex) RLock() {
+	logRLock(m)
+	m.mu.RLock()
+}
+
+// RUnlock unlocks the mutex for reading
+func (m *RWMutex) RUnlock() {
+	logRUnlock(m)
+	m.mu.RUnlock()
+}
+
+// TryRLock tries to lock the mutex for reading
+func (m *RWMutex) TryRLock() bool {
+	logTryRLock(m)
+	l := m.mu.TryRLock()
+	logTryRLockResult(m, l)
+	return l
+}

internal/sync/once.go

@@ -0,0 +1,18 @@
+//go:build synctrace
+
+package sync
+
+import (
+	gosync "sync"
+)
+
+// Once is a wrapper around the sync.Once
+type Once struct {
+	mu gosync.Once
+}
+
+// Do calls the function f if and only if Do has not been called before for this instance of Once.
+func (o *Once) Do(f func()) {
+	logTrace("Doing once")
+	o.mu.Do(f)
+}

internal/sync/release.go

@@ -0,0 +1,92 @@
+//go:build !synctrace
+
+package sync
+
+import (
+	gosync "sync"
+)
+
+// Mutex is a wrapper around the sync.Mutex
+type Mutex struct {
+	mu gosync.Mutex
+}
+
+// Lock locks the mutex
+func (m *Mutex) Lock() {
+	m.mu.Lock()
+}
+
+// Unlock unlocks the mutex
+func (m *Mutex) Unlock() {
+	m.mu.Unlock()
+}
+
+// TryLock tries to lock the mutex
+func (m *Mutex) TryLock() bool {
+	return m.mu.TryLock()
+}
+
+// RWMutex is a wrapper around the sync.RWMutex
+type RWMutex struct {
+	mu gosync.RWMutex
+}
+
+// Lock locks the mutex
+func (m *RWMutex) Lock() {
+	m.mu.Lock()
+}
+
+// Unlock unlocks the mutex
+func (m *RWMutex) Unlock() {
+	m.mu.Unlock()
+}
+
+// RLock locks the mutex for reading
+func (m *RWMutex) RLock() {
+	m.mu.RLock()
+}
+
+// RUnlock unlocks the mutex for reading
+func (m *RWMutex) RUnlock() {
+	m.mu.RUnlock()
+}
+
+// TryRLock tries to lock the mutex for reading
+func (m *RWMutex) TryRLock() bool {
+	return m.mu.TryRLock()
+}
+
+// TryLock tries to lock the mutex
+func (m *RWMutex) TryLock() bool {
+	return m.mu.TryLock()
+}
+
+// WaitGroup is a wrapper around the sync.WaitGroup
+type WaitGroup struct {
+	wg gosync.WaitGroup
+}
+
+// Add adds a function to the wait group
+func (w *WaitGroup) Add(delta int) {
+	w.wg.Add(delta)
+}
+
+// Done decrements the wait group counter
+func (w *WaitGroup) Done() {
+	w.wg.Done()
+}
+
+// Wait waits for the wait group to finish
+func (w *WaitGroup) Wait() {
+	w.wg.Wait()
+}
+
+// Once is a wrapper around the sync.Once
+type Once struct {
+	mu gosync.Once
+}
+
+// Do calls the function f if and only if Do has not been called before for this instance of Once.
+func (o *Once) Do(f func()) {
+	o.mu.Do(f)
+}

internal/sync/waitgroup.go

@@ -0,0 +1,30 @@
+//go:build synctrace
+
+package sync
+
+import (
+	gosync "sync"
+)
+
+// WaitGroup is a wrapper around the sync.WaitGroup
+type WaitGroup struct {
+	wg gosync.WaitGroup
+}
+
+// Add adds a function to the wait group
+func (w *WaitGroup) Add(delta int) {
+	logTrace("Adding to wait group")
+	w.wg.Add(delta)
+}
+
+// Done decrements the wait group counter
+func (w *WaitGroup) Done() {
+	logTrace("Done with wait group")
+	w.wg.Done()
+}
+
+// Wait waits for the wait group to finish
+func (w *WaitGroup) Wait() {
+	logTrace("Waiting for wait group")
+	w.wg.Wait()
+}

scripts/dev_deploy.sh

@@ -17,6 +17,7 @@ show_help() {
     echo "      --skip-ui-build        Skip frontend/UI build"
     echo "      --skip-native-build    Skip native build"
     echo "      --disable-docker       Disable docker build"
+    echo "      --enable-sync-trace    Enable sync trace (do not use in release builds)"
     echo "  -i, --install              Build for release and install the app"
     echo "      --help                 Display this help message"
     echo
@@ -32,6 +33,7 @@ REMOTE_PATH="/userdata/jetkvm/bin"
 SKIP_UI_BUILD=false
 SKIP_UI_BUILD_RELEASE=0
 SKIP_NATIVE_BUILD=0
+ENABLE_SYNC_TRACE=0
 RESET_USB_HID_DEVICE=false
 LOG_TRACE_SCOPES="${LOG_TRACE_SCOPES:-jetkvm,cloud,websocket,native,jsonrpc}"
 RUN_GO_TESTS=false
@@ -64,6 +66,11 @@ while [[ $# -gt 0 ]]; do
             RESET_USB_HID_DEVICE=true
             shift
             ;;
+        --enable-sync-trace)
+            ENABLE_SYNC_TRACE=1
+            LOG_TRACE_SCOPES="${LOG_TRACE_SCOPES},synctrace"
+            shift
+            ;;
         --disable-docker)
             BUILD_IN_DOCKER=false
             shift
@@ -180,7 +187,10 @@ fi
 if [ "$INSTALL_APP" = true ]
 then
 	msg_info "▶ Building release binary"
-	do_make build_release SKIP_NATIVE_IF_EXISTS=${SKIP_NATIVE_BUILD} SKIP_UI_BUILD=${SKIP_UI_BUILD_RELEASE}
+	do_make build_release \
+    SKIP_NATIVE_IF_EXISTS=${SKIP_NATIVE_BUILD} \
+    SKIP_UI_BUILD=${SKIP_UI_BUILD_RELEASE} \
+    ENABLE_SYNC_TRACE=${ENABLE_SYNC_TRACE}
 	
 	# Copy the binary to the remote host as if we were the OTA updater.
 	ssh "${REMOTE_USER}@${REMOTE_HOST}" "cat > /userdata/jetkvm/jetkvm_app.update" < bin/jetkvm_app
@@ -189,7 +199,10 @@ then
 	ssh "${REMOTE_USER}@${REMOTE_HOST}" "reboot"
 else
 	msg_info "▶ Building development binary"
-	do_make build_dev SKIP_NATIVE_IF_EXISTS=${SKIP_NATIVE_BUILD} SKIP_UI_BUILD=${SKIP_UI_BUILD_RELEASE}
+	do_make build_dev \
+    SKIP_NATIVE_IF_EXISTS=${SKIP_NATIVE_BUILD} \
+    SKIP_UI_BUILD=${SKIP_UI_BUILD_RELEASE} \
+    ENABLE_SYNC_TRACE=${ENABLE_SYNC_TRACE}
 	
 	# Kill any existing instances of the application
 	ssh "${REMOTE_USER}@${REMOTE_HOST}" "killall jetkvm_app_debug || true"