From 2547282e0942a09b67fccfd53cf62a403ccd4a52 Mon Sep 17 00:00:00 2001
From: Ariver <shanghai3168@gmail.com>
Date: Wed, 01 Jul 2026 23:21:18 +0800
Subject: [PATCH] Add slow recognition diagnostics
---
privatevoice.src/app.go | 224 ++++++++++++++++++++++++++++++++++++++++++++++++++++---
1 files changed, 210 insertions(+), 14 deletions(-)
diff --git a/privatevoice.src/app.go b/privatevoice.src/app.go
index 783c115..89ea0b6 100755
--- a/privatevoice.src/app.go
+++ b/privatevoice.src/app.go
@@ -28,8 +28,8 @@
)
const (
- appVersion = "2.1.34"
- appBuild = "20260623.1312"
+ appVersion = "2.1.38"
+ appBuild = "20260629.2014"
appDisplayVersion = appVersion + " (build " + appBuild + ")"
appName = "PrivateVoice Dictation"
@@ -37,6 +37,8 @@
silenceTimeoutDuration = 3 * time.Second // auto-stop after this much silence in free-talk
silenceGracePeriod = 2 * time.Second // don't auto-stop within first 2s of free-talk
holdActivationDelay = 180 * time.Millisecond
+ slowRecognizeThresholdMs = int64(2000)
+ slowPipelineThresholdMs = int64(2500)
doneIndicatorHideDelayMs = 250
liveCaptionInterval = 120 * time.Millisecond
liveCaptionMaxBytes = 108
@@ -538,8 +540,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)
}()
}
@@ -714,8 +719,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)
}()
}
@@ -767,21 +775,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 {
@@ -792,101 +822,261 @@
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
hotkeyVK := a.cfg.HotkeyVK
autoHide := a.cfg.AutoHide
copyToClipboard := a.cfg.CopyToClipboard
+ selectedModelID := a.cfg.SelectedModelID
+ languageID := a.cfg.LanguageID
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)
+ recognizeElapsedMS := perfDurationMS(recognizeElapsed)
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),
+ recognizeElapsedMS,
+ 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()
}
+ totalMS := perfSinceMS(pipelineStart)
+ logger.Info("PERF pipeline_done id=%d result=success total_ms=%d", perfID, totalMS)
+ logSlowRecognitionIfNeeded(perfID, eng, selectedModelID, languageID, samples, recognizeElapsedMS, totalMS)
a.delayedHideIf(autoHide, doneIndicatorHideDelayMs)
+}
+
+func logSlowRecognitionIfNeeded(perfID int64, eng engine.Engine, modelID, languageID string, samples []float32, recognizeMS, totalMS int64) {
+ reason := slowRecognitionReason(recognizeMS, totalMS)
+ if reason == "" {
+ return
+ }
+
+ engineInfo := ""
+ if eng != nil {
+ engineInfo = eng.HardwareInfo()
+ }
+
+ load, hasLoad := currentSystemLoadAverage()
+ if hasLoad {
+ logger.Info(
+ "PERF slow_recognition id=%d reason=%s model_id=%q language_id=%q engine=%q audio_ms=%d samples=%d recognize_ms=%d total_ms=%d load1=%.2f load5=%.2f load15=%.2f",
+ perfID,
+ reason,
+ modelID,
+ languageID,
+ engineInfo,
+ perfAudioDurationMS(samples),
+ len(samples),
+ recognizeMS,
+ totalMS,
+ load[0],
+ load[1],
+ load[2],
+ )
+ return
+ }
+
+ logger.Info(
+ "PERF slow_recognition id=%d reason=%s model_id=%q language_id=%q engine=%q audio_ms=%d samples=%d recognize_ms=%d total_ms=%d load_unavailable=true",
+ perfID,
+ reason,
+ modelID,
+ languageID,
+ engineInfo,
+ perfAudioDurationMS(samples),
+ len(samples),
+ recognizeMS,
+ totalMS,
+ )
+}
+
+func slowRecognitionReason(recognizeMS, totalMS int64) string {
+ recognizeSlow := recognizeMS > slowRecognizeThresholdMs
+ totalSlow := totalMS > slowPipelineThresholdMs
+ switch {
+ case recognizeSlow && totalSlow:
+ return "recognize,total"
+ case recognizeSlow:
+ return "recognize"
+ case totalSlow:
+ return "total"
+ default:
+ return ""
+ }
}
// 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.
@@ -985,6 +1175,9 @@
}
func releaseTailCaptureDelayForEngine(eng engine.Engine) time.Duration {
+ if eng == nil {
+ return 0
+ }
tailCaptureEng, ok := eng.(engine.ReleaseTailCaptureEngine)
if !ok {
return 0
@@ -997,9 +1190,12 @@
}
func holdPreCaptureEnabledForEngine(eng engine.Engine) bool {
+ if eng == nil {
+ return false
+ }
preCaptureEng, ok := eng.(engine.HoldPreCaptureEngine)
if !ok {
- return false
+ return true
}
return preCaptureEng.HoldPreCaptureEnabled()
}
--
Gitblit v1.9.3