diff --git a/Makefile b/Makefile index c3554879..e519a75a 100644 --- a/Makefile +++ b/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 \ diff --git a/internal/sync/log.go b/internal/sync/log.go new file mode 100644 index 00000000..36d0b29c --- /dev/null +++ b/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") +} diff --git a/internal/sync/mutex.go b/internal/sync/mutex.go new file mode 100644 index 00000000..a269bdaf --- /dev/null +++ b/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 +} diff --git a/internal/sync/once.go b/internal/sync/once.go new file mode 100644 index 00000000..e2d90aff --- /dev/null +++ b/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) +} diff --git a/internal/sync/release.go b/internal/sync/release.go new file mode 100644 index 00000000..daec330e --- /dev/null +++ b/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) +} diff --git a/internal/sync/waitgroup.go b/internal/sync/waitgroup.go new file mode 100644 index 00000000..8d022e29 --- /dev/null +++ b/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() +} diff --git a/scripts/dev_deploy.sh b/scripts/dev_deploy.sh index 1ff9296b..d99f6974 100755 --- a/scripts/dev_deploy.sh +++ b/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"