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/app.go | 149 +++++++++++++++++++++++++++++++++++++++++++++----
1 files changed, 136 insertions(+), 13 deletions(-)
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.
--
Gitblit v1.9.3