From 9d4f977026bbb4516f8cc97f715c0dc28bf2a13f Mon Sep 17 00:00:00 2001
From: Ariver <shanghai3168@gmail.com>
Date: Mon, 29 Jun 2026 20:16:29 +0800
Subject: [PATCH] Add performance diagnostics build
---
privatevoice.src/frontend/package.json | 2
privatevoice.src/app.go | 149 ++++++++++++++++++++++++++++++++++---
privatevoice.src/frontend/package-lock.json | 4
privatevoice.src/internal/input/paste_darwin.go | 60 +++++++++++++++
CHANGELOG.md | 15 +++
privatevoice.src/build/darwin/Info.plist | 4
6 files changed, 216 insertions(+), 18 deletions(-)
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 2e52d5b..254d47c 100755
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,5 +1,20 @@
# Changelog
+## v2.1.38 (2026-06-29)
+
+### 性能诊断
+
+- **新增识别流水线性能日志**：为录音尾部等待、停止录音、语音检测、模型识别、文本后处理、历史写入、热键释放等待、粘贴和总耗时加入 `PERF` 分段日志。
+- **新增 macOS 粘贴链路性能日志**：记录辅助权限检查、剪贴板快照、写入剪贴板、剪贴板校验和 Cmd+V 的耗时，用于判断慢感是否来自粘贴安全链路。
+- **保持识别行为不变**：本版本只增加诊断日志，不调整首尾字保护、模型选择、识别参数或 UI 行为。
+
+### 构建
+
+- build: `20260629.2014`
+- 说明: 本版本为性能回退排查诊断候选包，用于真实使用几天后分析慢在识别、尾部等待还是粘贴链路。
+
+---
+
## v2.1.37 (2026-06-29)
### 双构建线
diff --git a/privatevoice.src/app.go b/privatevoice.src/app.go
index 2fe71b1..f9f6cd1 100755
--- a/privatevoice.src/app.go
+++ b/privatevoice.src/app.go
@@ -28,8 +28,8 @@
)
const (
- appVersion = "2.1.37"
- appBuild = "20260629.0059"
+ appVersion = "2.1.38"
+ appBuild = "20260629.2014"
appDisplayVersion = appVersion + " (build " + appBuild + ")"
appName = "PrivateVoice Dictation"
@@ -539,8 +539,11 @@
a.isStoppingRecording = true
a.indicator.SetStatus(overlay.StatusProcessing, "识别中")
go func() {
- samples, hasVoice := a.stopRecorderAfterReleaseTailCapture()
- a.recognizeAndPaste(hasVoice, samples)
+ perfID := newPerfTraceID()
+ pipelineStart := time.Now()
+ logger.Info("PERF pipeline_start id=%d mode=hold", perfID)
+ samples, hasVoice := a.stopRecorderAfterReleaseTailCapture(perfID, pipelineStart)
+ a.recognizeAndPaste(hasVoice, samples, perfID, pipelineStart)
}()
}
@@ -715,8 +718,11 @@
logger.Info("Tap recording stopped")
a.indicator.SetStatus(overlay.StatusProcessing, "识别中")
go func() {
- samples, hasVoice := a.stopRecorderAfterReleaseTailCapture()
- a.recognizeAndPaste(hasVoice, samples)
+ perfID := newPerfTraceID()
+ pipelineStart := time.Now()
+ logger.Info("PERF pipeline_start id=%d mode=tap", perfID)
+ samples, hasVoice := a.stopRecorderAfterReleaseTailCapture(perfID, pipelineStart)
+ a.recognizeAndPaste(hasVoice, samples, perfID, pipelineStart)
}()
}
@@ -768,21 +774,43 @@
// silenceAutoStop performs the actual device stop and ASR after a silence timeout.
// Runs in its own goroutine to avoid deadlocking the audio callback thread.
func (a *App) silenceAutoStop() {
+ perfID := newPerfTraceID()
+ pipelineStart := time.Now()
+ logger.Info("PERF pipeline_start id=%d mode=silence_auto_stop", perfID)
+
+ voiceStart := time.Now()
hasVoice := a.recorder.HasVoiceActivity()
+ voiceElapsed := time.Since(voiceStart)
+
+ stopStart := time.Now()
samples := a.recorder.StopAndGetSamples()
+ stopElapsed := time.Since(stopStart)
+ logger.Info(
+ "PERF audio_stop_done id=%d mode=silence_auto_stop stop_ms=%d voice_check_ms=%d samples=%d audio_ms=%d has_voice=%t since_start_ms=%d",
+ perfID,
+ perfDurationMS(stopElapsed),
+ perfDurationMS(voiceElapsed),
+ len(samples),
+ perfAudioDurationMS(samples),
+ hasVoice,
+ perfSinceMS(pipelineStart),
+ )
logger.Info("Free talk stopped (silence auto-stop)")
a.indicator.SetStatus(overlay.StatusProcessing, "识别中")
- a.recognizeAndPaste(hasVoice, samples)
+ a.recognizeAndPaste(hasVoice, samples, perfID, pipelineStart)
}
-func (a *App) waitForReleaseTailCapture() {
+func (a *App) waitForReleaseTailCapture(perfID int64) {
delay := a.releaseTailCaptureDelay()
if delay <= 0 {
+ logger.Info("PERF release_tail_wait_done id=%d configured_ms=0 elapsed_ms=0", perfID)
return
}
logger.Info("Release tail capture: waiting %dms before stopping audio", delay.Milliseconds())
+ start := time.Now()
time.Sleep(delay)
+ logger.Info("PERF release_tail_wait_done id=%d configured_ms=%d elapsed_ms=%d", perfID, delay.Milliseconds(), perfSinceMS(start))
}
func (a *App) releaseTailCaptureDelay() time.Duration {
@@ -793,21 +821,38 @@
return time.Duration(nanos)
}
-func (a *App) stopRecorderAfterReleaseTailCapture() ([]float32, bool) {
- a.waitForReleaseTailCapture()
+func (a *App) stopRecorderAfterReleaseTailCapture(perfID int64, pipelineStart time.Time) ([]float32, bool) {
+ a.waitForReleaseTailCapture(perfID)
+
+ stopStart := time.Now()
samples := a.recorder.StopAndGetSamples()
+ stopElapsed := time.Since(stopStart)
+
+ voiceStart := time.Now()
hasVoice := a.recorder.HasVoiceActivity()
+ voiceElapsed := time.Since(voiceStart)
a.mu.Lock()
a.isStoppingRecording = false
a.mu.Unlock()
+
+ logger.Info(
+ "PERF audio_stop_done id=%d stop_ms=%d voice_check_ms=%d samples=%d audio_ms=%d has_voice=%t since_start_ms=%d",
+ perfID,
+ perfDurationMS(stopElapsed),
+ perfDurationMS(voiceElapsed),
+ len(samples),
+ perfAudioDurationMS(samples),
+ hasVoice,
+ perfSinceMS(pipelineStart),
+ )
return samples, hasVoice
}
// recognizeAndPaste runs ASR on the recorded samples and pastes the result.
// Shared by both hold and tap modes.
-func (a *App) recognizeAndPaste(hasVoice bool, samples []float32) {
+func (a *App) recognizeAndPaste(hasVoice bool, samples []float32, perfID int64, pipelineStart time.Time) {
// Snapshot config values under lock to avoid data races
a.mu.Lock()
soundFeedback := a.cfg.SoundFeedback
@@ -816,78 +861,156 @@
copyToClipboard := a.cfg.CopyToClipboard
a.mu.Unlock()
+ logger.Info(
+ "PERF recognize_pipeline_input id=%d has_voice=%t samples=%d audio_ms=%d copy_to_clipboard=%t since_start_ms=%d",
+ perfID,
+ hasVoice,
+ len(samples),
+ perfAudioDurationMS(samples),
+ copyToClipboard,
+ perfSinceMS(pipelineStart),
+ )
+
if !hasVoice {
logger.Info("No voice activity detected")
+ logger.Info("PERF pipeline_done id=%d result=no_voice total_ms=%d", perfID, perfSinceMS(pipelineStart))
a.indicator.SetStatus(overlay.StatusNoVoice, "无语音")
a.delayedHideIf(autoHide, 1500)
return
}
if len(samples) == 0 {
+ logger.Info("PERF pipeline_done id=%d result=no_samples total_ms=%d", perfID, perfSinceMS(pipelineStart))
a.indicator.SetStatus(overlay.StatusNoContent, "无内容")
a.delayedHideIf(autoHide, 1500)
return
}
+ engineLockStart := time.Now()
a.engineMu.Lock()
+ engineLockElapsed := time.Since(engineLockStart)
eng := a.eng
if eng == nil {
a.engineMu.Unlock()
logger.Error("Recognition skipped: engine not ready")
+ logger.Info("PERF pipeline_done id=%d result=engine_not_ready engine_lock_ms=%d total_ms=%d", perfID, perfDurationMS(engineLockElapsed), perfSinceMS(pipelineStart))
a.indicator.SetStatus(overlay.StatusError, "引擎未就绪")
a.delayedHideIf(autoHide, 2000)
return
}
+ recognizeStart := time.Now()
text, err := eng.Recognize(samples)
+ recognizeElapsed := time.Since(recognizeStart)
a.engineMu.Unlock()
+ logger.Info(
+ "PERF recognize_done id=%d engine_lock_wait_ms=%d recognize_ms=%d samples=%d audio_ms=%d since_start_ms=%d",
+ perfID,
+ perfDurationMS(engineLockElapsed),
+ perfDurationMS(recognizeElapsed),
+ len(samples),
+ perfAudioDurationMS(samples),
+ perfSinceMS(pipelineStart),
+ )
if err != nil {
logger.Error("Recognition failed: %v", err)
+ logger.Info("PERF pipeline_done id=%d result=recognize_error total_ms=%d", perfID, perfSinceMS(pipelineStart))
a.indicator.SetStatus(overlay.StatusError, "错误")
a.delayedHideIf(autoHide, 2000)
return
}
+ postProcessStart := time.Now()
text = textproc.PostProcess(text)
text = a.userdict.Apply(text)
+ postProcessElapsed := time.Since(postProcessStart)
+ logger.Info(
+ "PERF text_postprocess_done id=%d postprocess_ms=%d text_runes=%d since_start_ms=%d",
+ perfID,
+ perfDurationMS(postProcessElapsed),
+ len([]rune(text)),
+ perfSinceMS(pipelineStart),
+ )
if text == "" {
+ logger.Info("PERF pipeline_done id=%d result=empty_text total_ms=%d", perfID, perfSinceMS(pipelineStart))
a.indicator.SetStatus(overlay.StatusNoContent, "无内容")
a.delayedHideIf(autoHide, 1500)
return
}
logger.Info("Recognized: %s", text)
+ historyStart := time.Now()
a.history.Add(text)
+ logger.Info("PERF history_done id=%d history_ms=%d since_start_ms=%d", perfID, perfSinceMS(historyStart), perfSinceMS(pipelineStart))
- a.waitForHotkeyRelease(hotkeyVK)
+ hotkeyWaitStart := time.Now()
+ polls, released := a.waitForHotkeyRelease(hotkeyVK)
+ logger.Info(
+ "PERF hotkey_release_wait_done id=%d wait_ms=%d polls=%d released=%t since_start_ms=%d",
+ perfID,
+ perfSinceMS(hotkeyWaitStart),
+ polls,
+ released,
+ perfSinceMS(pipelineStart),
+ )
+ pasteStart := time.Now()
if err := a.paster.Paste(text, copyToClipboard); err != nil {
+ pasteElapsed := time.Since(pasteStart)
+ logger.Info("PERF paste_done id=%d result=error paste_ms=%d since_start_ms=%d", perfID, perfDurationMS(pasteElapsed), perfSinceMS(pipelineStart))
logger.Error("Paste failed, trying fallback: %v", err)
+ typeStart := time.Now()
if err := a.paster.TypeText(text); err != nil {
+ logger.Info("PERF fallback_type_done id=%d result=error type_ms=%d total_ms=%d", perfID, perfSinceMS(typeStart), perfSinceMS(pipelineStart))
logger.Error("Fallback type also failed: %v", err)
a.indicator.SetStatus(overlay.StatusError, "需辅助权限")
a.delayedHideIf(autoHide, 2500)
return
}
+ logger.Info("PERF fallback_type_done id=%d result=success type_ms=%d total_ms=%d", perfID, perfSinceMS(typeStart), perfSinceMS(pipelineStart))
+ } else {
+ logger.Info("PERF paste_done id=%d result=success paste_ms=%d since_start_ms=%d", perfID, perfSinceMS(pasteStart), perfSinceMS(pipelineStart))
}
a.indicator.SetStatus(overlay.StatusDone, "完成")
if soundFeedback {
sound.PlayDone()
}
+ logger.Info("PERF pipeline_done id=%d result=success total_ms=%d", perfID, perfSinceMS(pipelineStart))
a.delayedHideIf(autoHide, doneIndicatorHideDelayMs)
}
// waitForHotkeyRelease polls until the hotkey is released (max 500ms),
// then waits an additional 50ms settling delay.
-func (a *App) waitForHotkeyRelease(hotkeyVK int) {
+func (a *App) waitForHotkeyRelease(hotkeyVK int) (int, bool) {
+ polls := 0
+ released := false
for i := 0; i < 50; i++ {
+ polls = i + 1
if !a.hk.IsKeyDown(hotkeyVK) {
+ released = true
break
}
time.Sleep(10 * time.Millisecond)
}
time.Sleep(50 * time.Millisecond)
+ return polls, released
+}
+
+func newPerfTraceID() int64 {
+ return time.Now().UnixNano()
+}
+
+func perfSinceMS(start time.Time) int64 {
+ return perfDurationMS(time.Since(start))
+}
+
+func perfDurationMS(duration time.Duration) int64 {
+ return duration.Milliseconds()
+}
+
+func perfAudioDurationMS(samples []float32) int64 {
+ return int64(len(samples)) * 1000 / 16000
}
// delayedHide hides the indicator after a delay if AutoHide is enabled.
diff --git a/privatevoice.src/build/darwin/Info.plist b/privatevoice.src/build/darwin/Info.plist
index 40723d3..4612d46 100755
--- a/privatevoice.src/build/darwin/Info.plist
+++ b/privatevoice.src/build/darwin/Info.plist
@@ -17,9 +17,9 @@
<key>CFBundlePackageType</key>
<string>APPL</string>
<key>CFBundleShortVersionString</key>
- <string>2.1.37</string>
+ <string>2.1.38</string>
<key>CFBundleVersion</key>
- <string>20260629.0059</string>
+ <string>20260629.2014</string>
<key>ITSAppUsesNonExemptEncryption</key>
<false/>
<key>LSApplicationCategoryType</key>
diff --git a/privatevoice.src/frontend/package-lock.json b/privatevoice.src/frontend/package-lock.json
index 9c270ba..7bd111d 100755
--- a/privatevoice.src/frontend/package-lock.json
+++ b/privatevoice.src/frontend/package-lock.json
@@ -1,12 +1,12 @@
{
"name": "privatevoice-dictation-frontend",
- "version": "2.1.37",
+ "version": "2.1.38",
"lockfileVersion": 3,
"requires": true,
"packages": {
"": {
"name": "privatevoice-dictation-frontend",
- "version": "2.1.37",
+ "version": "2.1.38",
"dependencies": {
"@wailsio/runtime": "latest"
},
diff --git a/privatevoice.src/frontend/package.json b/privatevoice.src/frontend/package.json
index 3c39db4..eddd6fb 100755
--- a/privatevoice.src/frontend/package.json
+++ b/privatevoice.src/frontend/package.json
@@ -1,7 +1,7 @@
{
"name": "privatevoice-dictation-frontend",
"private": true,
- "version": "2.1.37",
+ "version": "2.1.38",
"type": "module",
"scripts": {
"dev": "vite dev",
diff --git a/privatevoice.src/internal/input/paste_darwin.go b/privatevoice.src/internal/input/paste_darwin.go
index bcd8aa2..3a12be2 100755
--- a/privatevoice.src/internal/input/paste_darwin.go
+++ b/privatevoice.src/internal/input/paste_darwin.go
@@ -99,6 +99,7 @@
"sync"
"time"
"unsafe"
+ "voicesnap/internal/logger"
)
const (
@@ -129,15 +130,30 @@
}
func (p *darwinPaster) Paste(text string, keepClipboard bool) error {
+ pasteStart := time.Now()
+ textRunes := len([]rune(text))
+
+ permissionStart := time.Now()
if C.ensureInputPermission() == 0 {
+ logger.Info(
+ "PERF paste_clipboard_done result=permission_error permission_ms=%d text_runes=%d keep_clipboard=%t total_ms=%d",
+ time.Since(permissionStart).Milliseconds(),
+ textRunes,
+ keepClipboard,
+ time.Since(pasteStart).Milliseconds(),
+ )
return fmt.Errorf("accessibility permission is required to paste")
}
+ permissionElapsed := time.Since(permissionStart)
state := &globalDarwinPasteState
+ stateLockStart := time.Now()
state.mu.Lock()
+ stateLockElapsed := time.Since(stateLockStart)
state.generation++
generation := state.generation
+ snapshotStart := time.Now()
originalClipboard := currentDarwinClipboardSnapshot()
if !keepClipboard {
originalClipboard = resolveDarwinRestoreTarget(
@@ -147,21 +163,53 @@
state.restoreTo,
)
}
+ snapshotElapsed := time.Since(snapshotStart)
cstr := C.CString(text)
defer C.free(unsafe.Pointer(cstr))
+ setClipboardStart := time.Now()
C.setClipboardText(cstr)
+ setClipboardElapsed := time.Since(setClipboardStart)
+
+ verifyStart := time.Now()
if !waitForDarwinClipboardText(text, darwinClipboardVerifyTimeout) {
+ verifyElapsed := time.Since(verifyStart)
state.pendingRestore = false
state.mu.Unlock()
+ logger.Info(
+ "PERF paste_clipboard_done result=verify_failed permission_ms=%d state_lock_ms=%d snapshot_ms=%d set_ms=%d verify_ms=%d text_runes=%d keep_clipboard=%t total_ms=%d",
+ permissionElapsed.Milliseconds(),
+ stateLockElapsed.Milliseconds(),
+ snapshotElapsed.Milliseconds(),
+ setClipboardElapsed.Milliseconds(),
+ verifyElapsed.Milliseconds(),
+ textRunes,
+ keepClipboard,
+ time.Since(pasteStart).Milliseconds(),
+ )
return fmt.Errorf("clipboard verification failed before paste")
}
+ verifyElapsed := time.Since(verifyStart)
+ cmdVStart := time.Now()
C.simulateCmdV()
+ cmdVElapsed := time.Since(cmdVStart)
if keepClipboard {
state.pendingRestore = false
state.mu.Unlock()
+ logger.Info(
+ "PERF paste_clipboard_done result=success permission_ms=%d state_lock_ms=%d snapshot_ms=%d set_ms=%d verify_ms=%d cmdv_ms=%d text_runes=%d keep_clipboard=%t total_ms=%d",
+ permissionElapsed.Milliseconds(),
+ stateLockElapsed.Milliseconds(),
+ snapshotElapsed.Milliseconds(),
+ setClipboardElapsed.Milliseconds(),
+ verifyElapsed.Milliseconds(),
+ cmdVElapsed.Milliseconds(),
+ textRunes,
+ keepClipboard,
+ time.Since(pasteStart).Milliseconds(),
+ )
return nil
}
@@ -171,6 +219,18 @@
state.mu.Unlock()
go restoreDarwinClipboardAfterPaste(generation, text, originalClipboard)
+ logger.Info(
+ "PERF paste_clipboard_done result=success permission_ms=%d state_lock_ms=%d snapshot_ms=%d set_ms=%d verify_ms=%d cmdv_ms=%d text_runes=%d keep_clipboard=%t total_ms=%d",
+ permissionElapsed.Milliseconds(),
+ stateLockElapsed.Milliseconds(),
+ snapshotElapsed.Milliseconds(),
+ setClipboardElapsed.Milliseconds(),
+ verifyElapsed.Milliseconds(),
+ cmdVElapsed.Milliseconds(),
+ textRunes,
+ keepClipboard,
+ time.Since(pasteStart).Milliseconds(),
+ )
return nil
}
--
Gitblit v1.9.3