feat: show per-stage timing (듣기/LLM/TTS) in the transcript channel
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 <noreply@anthropic.com>
This commit is contained in:
javis-bot
@@ -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;
|
||||
}
|
||||
|
||||
@@ -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<void>;
|
||||
/** Fired per sentence as its audio finishes synthesising (in order). */
|
||||
onAudio?: (wav: Buffer) => void | Promise<void>;
|
||||
/** Fired once after the last clip, with TTS timing. */
|
||||
onEnd?: (end: ConverseEnd) => void | Promise<void>;
|
||||
}
|
||||
|
||||
/** 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);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
70
bot/src/userbot.test.ts
Normal file
70
bot/src/userbot.test.ts
Normal file
@@ -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("👂 듣기");
|
||||
});
|
||||
@@ -34,12 +34,66 @@ async function loadSelfbot(): Promise<any> {
|
||||
}
|
||||
}
|
||||
|
||||
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<void> {
|
||||
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);
|
||||
|
||||
@@ -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<void> {
|
||||
// "듣기 시작": 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<void>((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);
|
||||
|
||||
@@ -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)} "
|
||||
|
||||
Reference in New Issue
Block a user