From de5384d166361a0df17d37340e7845e91a40c1e3 Mon Sep 17 00:00:00 2001 From: javis-bot Date: Sat, 13 Jun 2026 23:58:49 +0900 Subject: [PATCH] =?UTF-8?q?feat:=20show=20per-stage=20timing=20(=EB=93=A3?= =?UTF-8?q?=EA=B8=B0/LLM/TTS)=20in=20the=20transcript=20channel?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The transcript channel only showed STT and LLM seconds. Add wall-clock start/end times and durations for listening, LLM and TTS so it's obvious what takes long; STT surfaces as the gap between listening end and LLM start. - bridge: emit llm_start_ms/llm_end_ms on meta and tts_*_ms on the end event - bot: capture the listening window, assemble full timing after the stream, and render a per-stage breakdown in the transcript message Co-Authored-By: Claude Opus 4.7 --- bot/src/bridge.test.ts | 19 +++++++++-- bot/src/bridge.ts | 17 ++++++++++ bot/src/userbot.test.ts | 70 +++++++++++++++++++++++++++++++++++++++ bot/src/userbot.ts | 72 +++++++++++++++++++++++++++++++++-------- bot/src/voice.ts | 71 +++++++++++++++++++++++++++++++--------- bridge/server.py | 27 +++++++++++++++- 6 files changed, 242 insertions(+), 34 deletions(-) create mode 100644 bot/src/userbot.test.ts diff --git a/bot/src/bridge.test.ts b/bot/src/bridge.test.ts index 1293673..04e9763 100644 --- a/bot/src/bridge.test.ts +++ b/bot/src/bridge.test.ts @@ -33,10 +33,12 @@ test("converseStream surfaces meta first, then plays each sentence clip in order transcript: "안녕", reply: "안녕하세요. 반갑습니다!", broadcast_action: "start", + llm_start_ms: 1000, + llm_end_ms: 2600, }), JSON.stringify({ type: "audio", seq: 0, audio_b64: clipA.toString("base64") }), JSON.stringify({ type: "audio", seq: 1, audio_b64: clipB.toString("base64") }), - JSON.stringify({ type: "end" }), + JSON.stringify({ type: "end", tts_sec: 0.9, tts_start_ms: 2600, tts_end_ms: 3500 }), ].join("\n") + "\n"; const orig = globalThis.fetch; @@ -50,6 +52,7 @@ test("converseStream surfaces meta first, then plays each sentence clip in order const events: string[] = []; const clips: Buffer[] = []; let meta: any; + let end: any; await converseStream(Buffer.from("wav"), true, { onMeta: (m) => { meta = m; @@ -59,13 +62,23 @@ test("converseStream surfaces meta first, then plays each sentence clip in order clips.push(c); events.push("audio"); }, + onEnd: (e) => { + end = e; + events.push("end"); + }, }); expect(meta.transcript).toBe("안녕"); expect(meta.broadcast_action).toBe("start"); - // Meta must arrive before any audio, and clips must stay in order. - expect(events).toEqual(["meta", "audio", "audio"]); + // LLM wall-clock window rides on the meta line. + expect(meta.llm_start_ms).toBe(1000); + expect(meta.llm_end_ms).toBe(2600); + // Meta must arrive before any audio, the end (with TTS timing) comes last, + // and clips stay in order. + expect(events).toEqual(["meta", "audio", "audio", "end"]); expect(clips.map((c) => c.toString())).toEqual(["clipA", "clipB"]); + expect(end.tts_start_ms).toBe(2600); + expect(end.tts_end_ms).toBe(3500); } finally { globalThis.fetch = orig; } diff --git a/bot/src/bridge.ts b/bot/src/bridge.ts index 1b5a0a3..fc93ace 100644 --- a/bot/src/bridge.ts +++ b/bot/src/bridge.ts @@ -50,6 +50,19 @@ export interface ConverseMeta { /** Per-stage timing (seconds) for diagnosing latency. */ stt_sec?: number; think_sec?: number; + /** Wall-clock LLM window (epoch ms) so the transcript channel can show when + * the reply engine started/finished. */ + llm_start_ms?: number; + llm_end_ms?: number; +} + +/** Final event of a streamed turn, carrying TTS timing (synthesis runs after + * the meta line, so it can't be reported there). */ +export interface ConverseEnd { + tts_sec?: number; + /** Wall-clock TTS window (epoch ms). */ + tts_start_ms?: number; + tts_end_ms?: number; } export interface ConverseStreamHandlers { @@ -57,6 +70,8 @@ export interface ConverseStreamHandlers { onMeta?: (meta: ConverseMeta) => void | Promise; /** Fired per sentence as its audio finishes synthesising (in order). */ onAudio?: (wav: Buffer) => void | Promise; + /** Fired once after the last clip, with TTS timing. */ + onEnd?: (end: ConverseEnd) => void | Promise; } /** Parse a byte stream of newline-delimited JSON into objects, one per line. */ @@ -102,6 +117,8 @@ export async function converseStream( } else if (ev.type === "audio" && ev.audio_b64) { const clip = decodeWav(ev.audio_b64); if (clip) await handlers.onAudio?.(clip); + } else if (ev.type === "end") { + await handlers.onEnd?.(ev as ConverseEnd); } } } diff --git a/bot/src/userbot.test.ts b/bot/src/userbot.test.ts new file mode 100644 index 0000000..46a82d6 --- /dev/null +++ b/bot/src/userbot.test.ts @@ -0,0 +1,70 @@ +import { test, expect } from "bun:test"; + +// userbot.ts imports the runtime `config`, which requires DISCORD_GUILD_ID. +process.env.DISCORD_GUILD_ID ||= "test-guild"; +const { formatTurnMessage } = await import("./userbot.ts"); + +test("formatTurnMessage shows a per-stage timing breakdown with durations", () => { + const msg = formatTurnMessage({ + transcript: "안녕하세요", + reply: "네, 안녕하세요", + listenStartMs: 10_000, + listenEndMs: 12_000, // 듣기 2.0s + llmStartMs: 12_500, // STT/전송 gap 0.5s + llmEndMs: 14_100, // LLM 1.6s + ttsStartMs: 14_100, + ttsEndMs: 15_000, // TTS 0.9s + }); + + expect(msg).toContain('🗣️ "안녕하세요"'); + expect(msg).toContain("🤖 답변: 네, 안녕하세요"); + expect(msg).toContain("👂 듣기 2.0초"); + expect(msg).toContain("🧠 LLM 1.6초"); + expect(msg).toContain("(STT/전송 0.5초)"); + expect(msg).toContain("🔊 TTS 0.9초"); + // Total spans listening start -> TTS end. + expect(msg).toContain("합계 5.0초"); +}); + +test("formatTurnMessage omits the STT gap note when it is negligible", () => { + const msg = formatTurnMessage({ + transcript: "테스트", + reply: "응답", + listenStartMs: 0, + listenEndMs: 1000, + llmStartMs: 1000, // no gap + llmEndMs: 2000, + }); + expect(msg).not.toContain("STT/전송"); + expect(msg).toContain("🧠 LLM 1.0초"); +}); + +test("formatTurnMessage reports a dropped turn with only the listening stage", () => { + const msg = formatTurnMessage({ + transcript: "", + reply: "", + note: "너무 짧음(<300ms)", + listenStartMs: 0, + listenEndMs: 200, + }); + expect(msg).toContain("❌ 너무 짧음(<300ms)"); + expect(msg).toContain("👂 듣기 0.2초"); + expect(msg).not.toContain("🧠 LLM"); + expect(msg).not.toContain("🔊 TTS"); +}); + +test("formatTurnMessage falls back to the plain line when no timing is present", () => { + const msg = formatTurnMessage({ transcript: "안녕", reply: "하이" }); + expect(msg).toBe('🎤 들음 → 🗣️ "안녕"\n🤖 답변: 하이'); + expect(msg).not.toContain("⏱️"); +}); + +test("formatTurnMessage drops out-of-order (negative) spans instead of showing junk", () => { + const msg = formatTurnMessage({ + transcript: "안녕", + reply: "하이", + listenStartMs: 5000, + listenEndMs: 4000, // negative span -> omitted + }); + expect(msg).not.toContain("👂 듣기"); +}); diff --git a/bot/src/userbot.ts b/bot/src/userbot.ts index d7984d5..c6cea8c 100644 --- a/bot/src/userbot.ts +++ b/bot/src/userbot.ts @@ -34,12 +34,66 @@ async function loadSelfbot(): Promise { } } -interface TurnInfo { +export interface TurnInfo { transcript: string; reply: string; note?: string; - sttSec?: number; - thinkSec?: number; + /** Wall-clock epoch-ms markers for each pipeline stage. STT is the gap + * between listenEndMs and llmStartMs. */ + listenStartMs?: number; + listenEndMs?: number; + llmStartMs?: number; + llmEndMs?: number; + ttsStartMs?: number; + ttsEndMs?: number; +} + +/** Local wall-clock HH:MM:SS for an epoch-ms instant. */ +function clock(ms?: number): string { + if (ms == null) return "?"; + const d = new Date(ms); + const p = (n: number) => String(n).padStart(2, "0"); + return `${p(d.getHours())}:${p(d.getMinutes())}:${p(d.getSeconds())}`; +} + +/** Seconds between two epoch-ms instants, 1 decimal, or null if either side is + * missing or the span is negative (clock skew / out-of-order markers). */ +function durSec(a?: number, b?: number): string | null { + if (a == null || b == null) return null; + const s = (b - a) / 1000; + if (s < 0) return null; + return s.toFixed(1); +} + +/** Build the transcript-channel message: transcript + reply, plus a per-stage + * timing breakdown (listening / LLM / TTS) with start→end wall-clock times and + * durations, so it's obvious what took long. Pure + exported for testing. */ +export function formatTurnMessage(info: TurnInfo): string { + const head = info.transcript + ? `🎤 들음 → 🗣️ "${info.transcript}"\n🤖 답변: ${(info.reply || "").trim() || "(무응답)"}` + : `🎤 들음 → ❌ ${info.note || "무시됨"}`; + + const lines: string[] = []; + const listen = durSec(info.listenStartMs, info.listenEndMs); + if (listen != null) { + lines.push(` 👂 듣기 ${listen}초 ${clock(info.listenStartMs)} → ${clock(info.listenEndMs)}`); + } + const llm = durSec(info.llmStartMs, info.llmEndMs); + if (llm != null) { + const stt = durSec(info.listenEndMs, info.llmStartMs); + const gap = stt != null && Number(stt) >= 0.1 ? ` (STT/전송 ${stt}초)` : ""; + lines.push(` 🧠 LLM ${llm}초 ${clock(info.llmStartMs)} → ${clock(info.llmEndMs)}${gap}`); + } + const tts = durSec(info.ttsStartMs, info.ttsEndMs); + if (tts != null) { + lines.push(` 🔊 TTS ${tts}초 ${clock(info.ttsStartMs)} → ${clock(info.ttsEndMs)}`); + } + + if (!lines.length) return head; + const lastEnd = info.ttsEndMs ?? info.llmEndMs ?? info.listenEndMs; + const total = durSec(info.listenStartMs, lastEnd); + const totalNote = total != null ? ` (합계 ${total}초)` : ""; + return `${head}\n⏱️ 타이밍${totalNote}\n${lines.join("\n")}`; } /** Mirror EVERY heard utterance (and why it did/didn't answer) to a text @@ -47,17 +101,7 @@ interface TurnInfo { async function postTranscript(client: AnyClient, info: TurnInfo): Promise { const chId = config.transcriptChannelId; if (!chId) return; - const timing = - info.sttSec != null || info.thinkSec != null - ? ` ⏱️ stt ${info.sttSec ?? "?"}s · llm ${info.thinkSec ?? "?"}s` - : ""; - let msg: string; - if (info.transcript) { - const r = (info.reply || "").trim(); - msg = `🎤 들음 → 🗣️ "${info.transcript}"\n🤖 답변: ${r || "(무응답)"}${timing}`; - } else { - msg = `🎤 들음 → ❌ ${info.note || "무시됨"}${timing}`; - } + const msg = formatTurnMessage(info); try { const ch: any = await client.channels.fetch(chId).catch(() => null); if (ch?.send) await ch.send(msg); diff --git a/bot/src/voice.ts b/bot/src/voice.ts index d1c5e10..c95f995 100644 --- a/bot/src/voice.ts +++ b/bot/src/voice.ts @@ -77,8 +77,16 @@ export class VoiceSession { transcript: string; reply: string; note?: string; - sttSec?: number; - thinkSec?: number; + /** Wall-clock epoch-ms markers for each pipeline stage, so the transcript + * channel can show what took long. Listening is measured here (capture + * start -> end of speech); LLM/TTS come from the brain bridge. STT shows + * up as the gap between listenEndMs and llmStartMs. */ + listenStartMs?: number; + listenEndMs?: number; + llmStartMs?: number; + llmEndMs?: number; + ttsStartMs?: number; + ttsEndMs?: number; }) => void; /** Live screen-share state, sent with each turn so the brain routes search * (Chrome while broadcasting, Gemini when off). */ @@ -150,6 +158,8 @@ export class VoiceSession { } private async captureUtterance(userId: string): Promise { + // "듣기 시작": the moment we begin capturing this speaker's utterance. + const listenStartMs = Date.now(); const opusStream = this.connection.receiver.subscribe(userId, { end: { behavior: EndBehaviorType.AfterSilence, duration: config.silenceMs }, }); @@ -163,13 +173,23 @@ export class VoiceSession { pcmStream.on("data", (c: Buffer) => chunks.push(c)); await new Promise((resolve) => pcmStream.once("end", () => resolve())); + // "듣기 종료": end of speech (silence detected). Anything after this is + // STT + reply + TTS on the brain side. + const listenEndMs = Date.now(); if (!chunks.length) return; const mono = stereoToMono(Buffer.concat(chunks)); // Ignore blips shorter than ~300ms (likely noise / key clicks) — but still // report them so the transcript channel shows every captured utterance. if (mono.length < DISCORD_RATE * 0.3 * 2) { - this.onTurn?.({ user: userId, transcript: "", reply: "", note: "너무 짧음(<300ms)" }); + this.onTurn?.({ + user: userId, + transcript: "", + reply: "", + note: "너무 짧음(<300ms)", + listenStartMs, + listenEndMs, + }); return; } const wav = pcm16MonoToWav(mono, DISCORD_RATE); @@ -178,30 +198,49 @@ export class VoiceSession { // Streaming turn: the brain sends transcript/reply first, then one audio // clip per sentence as it is synthesised. We enqueue each clip on arrival // so the first sentence starts playing while the rest are still spoken. + // The transcript-channel report is sent once the stream ends so it can + // include TTS timing (synthesis runs after the meta line). Audio still + // plays as it arrives — only the diagnostic text post waits. + let metaSeen: { + transcript: string; + reply: string; + note?: string; + llm_start_ms?: number; + llm_end_ms?: number; + } | undefined; + let endSeen: { tts_start_ms?: number; tts_end_ms?: number } | undefined; await converseStream(wav, this.getBroadcasting?.(), { - onMeta: async (meta) => { - // Report EVERY turn (even empty/VAD-dropped) so the transcript channel - // explains why a turn did or didn't answer. - this.onTurn?.({ - user: userId, - transcript: meta.transcript, - reply: meta.reply, - note: meta.note, - sttSec: meta.stt_sec, - thinkSec: meta.think_sec, - }); + onMeta: async (m) => { + metaSeen = m; // Apply any broadcast directive the brain requested (e.g. user said // "방송 켜줘 / 꺼줘") before the reply audio plays. The meta line // always precedes the audio clips, so awaiting here preserves order. - if (meta.broadcast_action && this.onBroadcastAction) { + if (m.broadcast_action && this.onBroadcastAction) { try { - await this.onBroadcastAction(meta.broadcast_action); + await this.onBroadcastAction(m.broadcast_action); } catch (e) { console.error("[voice] broadcast action failed:", e); } } }, onAudio: (clip) => this.play(clip), + onEnd: (end) => { + endSeen = end; + }, + }); + // Report EVERY turn (even empty/VAD-dropped) so the transcript channel + // explains why a turn did or didn't answer, with full stage timing. + this.onTurn?.({ + user: userId, + transcript: metaSeen?.transcript ?? "", + reply: metaSeen?.reply ?? "", + note: metaSeen?.note, + listenStartMs, + listenEndMs, + llmStartMs: metaSeen?.llm_start_ms, + llmEndMs: metaSeen?.llm_end_ms, + ttsStartMs: endSeen?.tts_start_ms, + ttsEndMs: endSeen?.tts_end_ms, }); } catch (err) { console.error("[voice] converse failed:", err); diff --git a/bridge/server.py b/bridge/server.py index 5c86794..e33199a 100644 --- a/bridge/server.py +++ b/bridge/server.py @@ -453,6 +453,12 @@ def http_converse_stream(): def gen(): import time + + def now_ms() -> int: + # Wall-clock epoch ms so the Node side can line these up against its + # own Date.now() capture timestamps (same host, same clock). + return int(time.time() * 1000) + t0 = time.monotonic() stt = transcribe(raw) t_stt = time.monotonic() @@ -464,8 +470,10 @@ def http_converse_stream(): "stt_sec": round(t_stt - t0, 1), "broadcast_action": None}) + "\n" yield json.dumps({"type": "end"}) + "\n" return + llm_start_ms = now_ms() result = think(transcript, stt.get("language"), broadcasting) t_think = time.monotonic() + llm_end_ms = now_ms() reply = result.get("reply", "") yield json.dumps({ "type": "meta", @@ -476,20 +484,37 @@ def http_converse_stream(): "note": "ok" if reply.strip() else "답변 없음", "stt_sec": round(t_stt - t0, 1), "think_sec": round(t_think - t_stt, 1), + # Wall-clock LLM window (epoch ms) for the transcript-channel timing + # breakdown. STT shows up as the gap between the Node-side capture + # end and llm_start_ms. + "llm_start_ms": llm_start_ms, + "llm_end_ms": llm_end_ms, "broadcast_action": result.get("broadcast_action"), }) + "\n" tts_total = 0.0 + tts_start_ms = None + tts_end_ms = None for seq, sentence in enumerate(split_sentences(reply)): ts = time.monotonic() + if tts_start_ms is None: + tts_start_ms = now_ms() audio = synthesize(sentence) tts_total += time.monotonic() - ts + tts_end_ms = now_ms() if audio: yield json.dumps({ "type": "audio", "seq": seq, "audio_b64": base64.b64encode(audio).decode("ascii"), }) + "\n" - yield json.dumps({"type": "end"}) + "\n" + # The end event carries TTS timing because synthesis happens AFTER the + # meta line (it is pipelined sentence-by-sentence). + yield json.dumps({ + "type": "end", + "tts_sec": round(tts_total, 1), + "tts_start_ms": tts_start_ms, + "tts_end_ms": tts_end_ms, + }) + "\n" print( f"[bridge] ⏱️ turn stt={t_stt - t0:.1f}s think(LLM)={t_think - t_stt:.1f}s " f"tts={tts_total:.1f}s total={time.monotonic() - t0:.1f}s replylen={len(reply)} "