Add slow recognition diagnostics

Ariver

2026-07-01 2547282e0942a09b67fccfd53cf62a403ccd4a52

Add slow recognition diagnostics

 privatevoice.src/app.go

@@ -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
@@ -859,6 +860,8 @@
    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(
@@ -901,12 +904,13 @@
    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),
        perfDurationMS(recognizeElapsed),
        recognizeElapsedMS,
        len(samples),
        perfAudioDurationMS(samples),
        perfSinceMS(pipelineStart),
@@ -976,8 +980,70 @@
    if soundFeedback {
        sound.PlayDone()
    }
    logger.Info("PERF pipeline_done id=%d result=success total_ms=%d", perfID, perfSinceMS(pipelineStart))
    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),
@@ -1114,7 +1180,7 @@
    }
    tailCaptureEng, ok := eng.(engine.ReleaseTailCaptureEngine)
    if !ok {
        return defaultReleaseTailDelay
        return 0
    }
    delay := tailCaptureEng.ReleaseTailCaptureDelay()
    if delay < 0 {

 privatevoice.src/app_live_caption_test.go

@@ -38,12 +38,12 @@
    }
}

func TestReleaseTailCaptureDelayDefaultsToProtectionWindow(t *testing.T) {
func TestReleaseTailCaptureDelayDefaultsToNoProtectionWindow(t *testing.T) {
    a := &App{}
    a.replaceEngine(plainTestEngine{})

    if got := a.releaseTailCaptureDelay(); got != defaultReleaseTailDelay {
        t.Fatalf("releaseTailCaptureDelay() = %v, want %v", got, defaultReleaseTailDelay)
    if got := a.releaseTailCaptureDelay(); got != 0 {
        t.Fatalf("releaseTailCaptureDelay() = %v, want 0", got)
    }
}

@@ -56,6 +56,28 @@
    }
}

func TestSlowRecognitionReason(t *testing.T) {
    tests := []struct {
        name        string
        recognizeMS int64
        totalMS     int64
        want        string
    }{
        {name: "fast", recognizeMS: 2000, totalMS: 2500, want: ""},
        {name: "recognize", recognizeMS: 2001, totalMS: 2400, want: "recognize"},
        {name: "total", recognizeMS: 1000, totalMS: 2501, want: "total"},
        {name: "both", recognizeMS: 2001, totalMS: 2501, want: "recognize,total"},
    }

    for _, tt := range tests {
        t.Run(tt.name, func(t *testing.T) {
            if got := slowRecognitionReason(tt.recognizeMS, tt.totalMS); got != tt.want {
                t.Fatalf("slowRecognitionReason(%d, %d) = %q, want %q", tt.recognizeMS, tt.totalMS, got, tt.want)
            }
        })
    }
}

func TestHoldPreCaptureUsesEngineCapability(t *testing.T) {
    a := &App{}
    a.replaceEngine(holdPreCaptureTestEngine{enabled: true})

 privatevoice.src/internal/engine/engine_darwin.go

@@ -28,6 +28,7 @@

type sherpaEngine struct {
    recognizer *sherpa.OfflineRecognizer
    backendKind string
    hwInfo     string
}

@@ -67,6 +68,7 @@
            logger.Info("Engine initialized: %s", info)
            return &sherpaEngine{
                recognizer: recognizer,
                backendKind: resolved.BackendKind,
                hwInfo:     info,
            }, nil
        }
@@ -313,6 +315,13 @@
    return e.hwInfo
}

func (e *sherpaEngine) ReleaseTailCaptureDelay() time.Duration {
    if e.backendKind == model.BackendSenseVoice {
        return senseVoiceReleaseTailDelay
    }
    return 0
}

func (e *xasrStreamingEngine) HardwareInfo() string {
    return e.hwInfo
}

 privatevoice.src/internal/engine/engine_darwin_test.go

@@ -187,15 +187,32 @@
    }
}

func TestXASREnablesHoldPreCapture(t *testing.T) {
    if !(&xasrStreamingEngine{}).HoldPreCaptureEnabled() {
        t.Fatal("X-ASR should enable hold pre-capture")
func TestSenseVoiceRequestsReleaseTailCaptureDelay(t *testing.T) {
    got := (&sherpaEngine{backendKind: model.BackendSenseVoice}).ReleaseTailCaptureDelay()
    if got != 100*time.Millisecond {
        t.Fatalf("ReleaseTailCaptureDelay() = %v, want 100ms", got)
    }
}

func TestOfflineSherpaDoesNotRequestReleaseTailCapture(t *testing.T) {
    if _, ok := any(&sherpaEngine{}).(ReleaseTailCaptureEngine); ok {
        t.Fatal("offline sherpa engine should not request release tail capture")
func TestOtherSherpaModelsDoNotRequestReleaseTailCaptureDelay(t *testing.T) {
    for _, backendKind := range []string{
        model.BackendMoonshine,
        model.BackendTransducer,
        model.BackendNemoTransducer,
        model.BackendQwen3ASR,
    } {
        t.Run(backendKind, func(t *testing.T) {
            got := (&sherpaEngine{backendKind: backendKind}).ReleaseTailCaptureDelay()
            if got != 0 {
                t.Fatalf("ReleaseTailCaptureDelay() = %v, want 0", got)
            }
        })
    }
}

func TestXASREnablesHoldPreCapture(t *testing.T) {
    if !(&xasrStreamingEngine{}).HoldPreCaptureEnabled() {
        t.Fatal("X-ASR should enable hold pre-capture")
    }
}


 privatevoice.src/internal/engine/engine_linux.go

@@ -4,6 +4,7 @@

import (
    "fmt"
    "time"
    "voicesnap/internal/logger"
    "voicesnap/internal/model"

@@ -57,6 +58,10 @@
    return e.hwInfo
}

func (e *sherpaEngine) ReleaseTailCaptureDelay() time.Duration {
    return senseVoiceReleaseTailDelay
}

func (e *sherpaEngine) Close() {
    if e.recognizer != nil {
        sherpa.DeleteOfflineRecognizer(e.recognizer)

 privatevoice.src/internal/engine/engine_windows.go

@@ -4,6 +4,7 @@

import (
    "fmt"
    "time"
    "voicesnap/internal/logger"
    "voicesnap/internal/model"

@@ -68,6 +69,10 @@
    return e.hwInfo
}

func (e *sherpaEngine) ReleaseTailCaptureDelay() time.Duration {
    return senseVoiceReleaseTailDelay
}

func (e *sherpaEngine) Close() {
    if e.recognizer != nil {
        sherpa.DeleteOfflineRecognizer(e.recognizer)

 privatevoice.src/internal/engine/release_tail.go

New file
@@ -0,0 +1,5 @@
package engine

import "time"

const senseVoiceReleaseTailDelay = 100 * time.Millisecond

 privatevoice.src/system_load_darwin.go

New file
@@ -0,0 +1,16 @@
//go:build darwin

package main

/*
#include <stdlib.h>
*/
import "C"

func currentSystemLoadAverage() ([3]float64, bool) {
    var values [3]C.double
    if C.getloadavg(&values[0], 3) != 3 {
        return [3]float64{}, false
    }
    return [3]float64{float64(values[0]), float64(values[1]), float64(values[2])}, true
}

 privatevoice.src/system_load_other.go

New file
@@ -0,0 +1,7 @@
//go:build !darwin

package main

func currentSystemLoadAverage() ([3]float64, bool) {
    return [3]float64{}, false
}