Add slow recognition diagnostics

Ariver

2026-07-01 2547282e0942a09b67fccfd53cf62a403ccd4a52

 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"

@@ -37,7 +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
   defaultReleaseTailDelay  = 300 * time.Millisecond
   slowRecognizeThresholdMs = int64(2000)
   slowPipelineThresholdMs  = int64(2500)
   doneIndicatorHideDelayMs = 250
   liveCaptionInterval      = 120 * time.Millisecond
   liveCaptionMaxBytes      = 108
@@ -539,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)
   }()
}

@@ -715,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)
   }()
}

@@ -768,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 {
@@ -793,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.
@@ -991,7 +1180,7 @@
   }
   tailCaptureEng, ok := eng.(engine.ReleaseTailCaptureEngine)
   if !ok {
      return defaultReleaseTailDelay
      return 0
   }
   delay := tailCaptureEng.ReleaseTailCaptureDelay()
   if delay < 0 {