Add performance diagnostics build

Ariver

2026-06-29 9d4f977026bbb4516f8cc97f715c0dc28bf2a13f

Add performance diagnostics build

 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)

### 双构建线

 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.

 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>

 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"
      },

 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",

 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
}