0.57.1: streaming real-time budget, stage stats, pre-roll

CHANGELOG.md

@@ -1,14 +1,54 @@
 # Changelog
 
 All notable changes to **SKaiNET-transformers** are documented here. The
-version line is kept in lock-step with the underlying SKaiNET engine
-(`sk.ainet.core:*`) — a transformers `X.Y.Z` ships against engine `X.Y.Z`.
+version line tracks the underlying SKaiNET engine (`sk.ainet.core:*`): a transformers
+release carries **at least** the engine's `X.Y`, and its **patch number may advance on its
+own** — a fix confined to transformers ships as `X.Y.Z+1` against engine `X.Y.Z` without
+requiring an engine release. `0.57.1` against engine `0.57.0` is such a release.
 
 The format roughly follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
 ## [Unreleased]
 
+## [0.57.1] — 2026-09-27
+
+Ships against **SKaiNET engine 0.57.0**: this release touches only the Android IREE runtime's
+streaming Moonshine path, no engine API.
+
+### Changed
+
+- **The streaming partial decode now has a real-time budget.** On an ARM Android device with a Mali GPU the stream did
+  not keep up with the microphone: per 0.88 s hop it spent ~350 ms on the encoder window and another
+  ~350 ms on a prefill plus greedy steps, so it ran at 1.2–1.45× real time and the whole backlog was
+  still owed at the moment the user stopped speaking. The encoder path is mandatory — it builds the
+  cross memory the final transcript is decoded from — but the decode hops only produce text to show
+  while the user is still talking, and `finish()` re-decodes from that memory regardless. Past
+  `MOONSHINE_LAG_BUDGET_MS` (default 250) the window runs and the decode is skipped, which provably
+  cannot change the final result. Measured on that device: RTF 1.23 → 0.67, drain 656 ms → 6 ms. Verified
+  against a 444-utterance German evaluation set: on 311 comparable rows 310 final transcripts were
+  byte-identical, and the single difference is a runaway repetition on both sides. The budget is disabled when `MOONSHINE_FAST_FINISH` is on, where the
+  incremental result *is* the answer.
+
+### Added
+
+- **`IreeMoonshineStream.stats()`** — what the last `finish()` cost, by stage. These numbers only ever
+  went to logcat, so a caller that wanted to know where recognition spent its time had to scrape the
+  device log. Now: the flush/decode split of the final decode, how far the stream fell behind the
+  microphone, how many partial decodes the budget gave up, encoder windows and decode hops run, and the
+  utterance's size in frames, tokens and milliseconds. A `timeline` entry carries each event with its
+  timestamp and cost (`w`/`p`/`h`/`d` records), so the shape of an utterance can be drawn rather than
+  only totalled. A string map rather than a typed record on purpose: the values cross two more
+  artifacts before anything consumes them, and adding a counter must not change a signature on the way.
+
+- **Audio that arrives before a run is open is held instead of dropped.** `sendAudioChunk` was
+  `activeRun?.feed(...)`: with no run open the chunk vanished silently. Opening a run costs 229 ms of
+  the 259 ms measured between a push-to-talk trigger and the first recorded sample, and a host that
+  waited for it lost that much speech off the *front* — enough to swallow the first word of an
+  utterance entirely. Chunks now go into a pre-roll, bounded to 1 s keeping the newest
+  and discarded entirely past 2 s of age, and are fed in order once the run opens. Measured: 259 ms →
+  68 ms, and an utterance whose first word was previously lost transcribes in full.
+
 ## [0.57.0] — 2026-09-25
 
 Lock-step with **SKaiNET engine 0.57.0**. Headline: **Qwen on the compiled IREE KV path**: the

gradle.properties

@@ -1,5 +1,5 @@
 GROUP=sk.ainet.transformers
-VERSION_NAME=0.57.0
+VERSION_NAME=0.57.1
 
 POM_DESCRIPTION=SKaiNET-transformers
 

llm-runtime/iree-android/native/moonshine_stream_jni.c

@@ -14,6 +14,7 @@
  *   String nativeFeedPcm(long h, float[] pcm)   // 16 kHz mono [-1,1]; returns new partial or null
  *   String nativeFinish(long h)                 // end of utterance: exact final transcript; resets
  *   void   nativeReset(long h)                  // abort utterance, keep engine
+ *   String nativeStats(long h)                  // last finish()'s counters as key=value pairs
  *   void   nativeDestroy(long h)
  *
  * Decode strategy (measured on a Mali GPU): the with_past step is ~120 ms and flat in
@@ -83,12 +84,35 @@
 #define FE_OUT (CHUNK + FE_LC)             /* 68 frames out */
 #define MAXMEM 256        /* compiled cross-memory pad (5.12 s of finalized speech) */
 #define MAXTOK 48
+/* 1 = skip the exact re-decode at the end of an utterance and keep the incremental result.
+ * Off by default; switched on for the latency experiment via -DMOONSHINE_FAST_FINISH=1. */
+#ifndef MOONSHINE_FAST_FINISH
+#define MOONSHINE_FAST_FINISH 0
+#endif
 #define FINISH_TOKENS 24  /* hard ceiling for the final budget (see finish_budget) */
 #define TOKENS_PER_SAMPLE (6.5f / 16000.0f)  /* the model card's cap: max_new_tokens = samples * 6.5/16000 + 2 */
 #define HOP_TOKENS 6      /* max new tokens decoded per hop (budget guard) */
 #define RESTART_HOPS 2    /* first hops re-decode exactly instead of incrementally */
 #define PEEK_FRAMES 36    /* early-peek window: first partial at ~0.72 s instead of 1.28 s */
 #define STEP_SLICE 2      /* tokens decoded per feed call — partials trickle out mid-hop */
+/* How far the stream may fall behind the microphone before partial decodes are dropped, in ms.
+ *
+ * The encoder path (frontend, encoder, adapter) is mandatory — it builds the cross memory the final
+ * transcript is decoded from — but the decode hops exist only to show text while the user is still
+ * speaking. On this box a hop costs about as long as the audio it covers, so paying for every one of
+ * them puts the stream past real time and the whole backlog is still waiting to be worked off at the
+ * moment the button is released. Dropping a partial costs a partial; it cannot change the final text,
+ * because finish() re-decodes from the memory regardless (that is only untrue with
+ * MOONSHINE_FAST_FINISH, which keeps the incremental result and therefore also keeps every hop).
+ * 0 disables the budget and decodes every hop as before. */
+#ifndef MOONSHINE_LAG_BUDGET_MS
+#define MOONSHINE_LAG_BUDGET_MS 250
+#endif
+#define MAXEVT 24         /* per-event timeline entries retained for nativeStats */
+#define EVT_WINDOW 0
+#define EVT_PEEK 1
+#define EVT_HOP 2
+#define EVT_DROPPED 3
 #define MAXPCM ((MAXMEM + CHUNK) * SPF)    /* ring capacity, samples */
 #define NEGMASK (-1.0e30f)
 
@@ -118,9 +142,35 @@ typedef struct {
   size_t shown_len;    /* longest partial surfaced so far — keeps the VIL text monotone */
   int pending;         /* tokens still budgeted for the current hop's decode */
   int halted;          /* decode hit EOS/cycle; stop continuing until the next hop */
+  double t_first_feed; /* wall clock of the first fed sample, 0 before it — the real-time reference */
+  int dropped;         /* partial decodes skipped because the stream had fallen behind the microphone */
+  int windows;         /* encoder windows processed this utterance (the mandatory work) */
+  int hops;            /* partial decodes actually run */
+  /* Per-event costs, so a caller can draw the utterance's timeline instead of only totalling it.
+   * Offsets are ms from the first fed sample. Capped: past MAXEVT the counters above still grow,
+   * the timeline simply stops — a status surface wants the shape, not an unbounded log. */
+  short evt_at[MAXEVT], evt_a[MAXEVT], evt_b[MAXEVT], evt_c[MAXEVT];
+  unsigned char evt_kind[MAXEVT];   /* EVT_WINDOW / EVT_PEEK / EVT_HOP / EVT_DROPPED */
+  int nevt;
   char text[4096];
+  /* Last utterance's counters, taken before the reset so a caller can still read them afterwards.
+   * `key=value` pairs, because this travels through two more repositories before anything consumes it
+   * and adding a counter must not change a signature anywhere along the way. */
+  char stats[1400];
 } Engine;
 
+/* Record one timeline event: `at` is ms from the first fed sample, a/b/c are the stage costs of the
+ * event's kind (a window's frontend/encoder/adapter; a decode's total in `a`). */
+static void note_evt(Engine* e, int kind, double at, double a, double b, double c) {
+  if (e->nevt >= MAXEVT) return;
+  int i = e->nevt++;
+  e->evt_kind[i] = (unsigned char)kind;
+  e->evt_at[i] = (short)(at < 0 ? 0 : (at > 32000 ? 32000 : at));
+  e->evt_a[i] = (short)(a > 32000 ? 32000 : a);
+  e->evt_b[i] = (short)(b > 32000 ? 32000 : b);
+  e->evt_c[i] = (short)(c > 32000 ? 32000 : c);
+}
+
 static double now_ms(void) {
   struct timespec ts; clock_gettime(CLOCK_MONOTONIC, &ts);
   return ts.tv_sec * 1000.0 + ts.tv_nsec / 1e6;
@@ -353,6 +403,8 @@ static int process_window(Engine* e, int start, int produced, int flush, int pee
   if (new_final > e->nmem) e->nmem = new_final;
   if (!peek && start == 0) e->peeked = 0;
   double t3 = now_ms();
+  e->windows++;
+  note_evt(e, EVT_WINDOW, t0 - e->t_first_feed, t1 - t0, t2 - t1, t3 - t2);
   TLOG("win %d fe %.0fms enc %.0fms adp+fin %.0fms nmem %d\n",
           e->win, t1 - t0, t2 - t1, t3 - t2, e->nmem);
   return 0;
@@ -562,6 +614,7 @@ static void warmup(Engine* e) {
   if (run_prefill(e, 1) == 0 && e->ntoks > 0) run_steps(e, 1, 0);
   e->npcm = 0; e->win = 0; e->nmem = 0;
   e->peeked = 0; e->pending = 0; e->halted = 0; e->shown_len = 0;
+  e->t_first_feed = 0.0; e->dropped = 0; e->windows = 0; e->hops = 0; e->nevt = 0;
   release_self(e); release_cross(e);
   e->ntoks = 0; e->pos = 0; e->text[0] = 0;
   TLOG("warmup %.0fms (all pipelines compiled)\n", now_ms() - t0);
@@ -570,6 +623,7 @@ static void warmup(Engine* e) {
 static void reset_utterance(Engine* e) {
   e->npcm = 0; e->win = 0; e->nmem = 0;
   e->peeked = 0; e->pending = 0; e->halted = 0; e->shown_len = 0;
+  e->t_first_feed = 0.0; e->dropped = 0; e->windows = 0; e->hops = 0; e->nevt = 0;
   release_self(e); release_cross(e);
   e->ntoks = 0; e->pos = 0; e->text[0] = 0;
 }
@@ -656,6 +710,16 @@ JNIEXPORT jstring JNICALL JNIFN(nativeFeedPcm)(JNIEnv* env, jobject thiz,
 
   int produced = e->npcm / SPF;
   int changed = 0;
+  /* How far behind the microphone this stream is: wall clock since the first sample minus the audio
+   * that has arrived. Positive means the caller is waiting on us, and every millisecond of it is still
+   * owed at the moment the utterance ends. Only the optional decode work is given up for it.
+   * MOONSHINE_FAST_FINISH makes the incremental decode the final answer, so there the hops are not
+   * optional and the budget does not apply. */
+  if (e->t_first_feed == 0.0) e->t_first_feed = now_ms();
+  int behind = 0;
+#if !MOONSHINE_FAST_FINISH && MOONSHINE_LAG_BUDGET_MS > 0
+  behind = (now_ms() - e->t_first_feed) - (double)e->npcm * 1000.0 / 16000.0 > MOONSHINE_LAG_BUDGET_MS;
+#endif
   /* Early peek: flash the first words at ~0.72 s instead of waiting for the full 1.28 s
    * window. The peek rows are conservative (zero-padded tail, lookahead subtracted) and are
    * recomputed by the real window 0; the restart decode at hop 1 replaces the text anyway. */
@@ -668,6 +732,7 @@ JNIEXPORT jstring JNICALL JNIFN(nativeFeedPcm)(JNIEnv* env, jobject thiz,
       if (run_prefill(e, 1) == 0) run_steps(e, STEP_SLICE, 1);
       e->pending = 2 * HOP_TOKENS - STEP_SLICE;
       if (e->ntoks > 0) changed = 1;
+      note_evt(e, EVT_PEEK, t0 - e->t_first_feed, now_ms() - t0, 0, 0);
       TLOG("peek total %.0fms nmem %d toks %d \"%s\"\n", now_ms() - t0, e->nmem, e->ntoks, e->text);
     }
   }
@@ -683,15 +748,27 @@ JNIEXPORT jstring JNICALL JNIFN(nativeFeedPcm)(JNIEnv* env, jobject thiz,
      * incrementally by subsequent feed calls (mid-hop emission), so text trickles out
      * instead of arriving in one lump per hop. finish() stays an exact full re-decode. */
     int restart = e->win <= RESTART_HOPS || e->ntoks == 0;
+    /* Behind the microphone: the window above has already put this hop's speech into the memory, so
+     * the final transcript is unaffected — give up only the partial. The decode state is left as it
+     * is; the next hop that can afford it picks up from there, and a restart hop rebuilds it anyway. */
+    if (behind) {
+      e->dropped++;
+      note_evt(e, EVT_DROPPED, t0 - e->t_first_feed, now_ms() - t0, 0, 0);
+      hopped = 1;
+      TLOG("hop %d total %.0fms DROPPED decode (behind) nmem %d\n", e->win, now_ms() - t0, e->nmem);
+      continue;
+    }
     if (restart) { release_self(e); e->ntoks = 0; e->pos = 0; e->text[0] = 0; }
     if (run_prefill(e, restart) == 0) run_steps(e, STEP_SLICE, restart);
     e->pending = (restart ? 2 * HOP_TOKENS : HOP_TOKENS) - STEP_SLICE;
+    e->hops++;
+    note_evt(e, EVT_HOP, t0 - e->t_first_feed, now_ms() - t0, 0, 0);
     hopped = 1;
     if (e->ntoks != prev || e->win == 1) changed = 1;
     TLOG("hop %d total %.0fms toks %d \"%s\"\n",
             e->win, now_ms() - t0, e->ntoks, e->text);
   }
-  if (!hopped && e->pending > 0 && !e->halted && e->ntoks > 0 && e->has_self && e->has_cross) {
+  if (!hopped && !behind && e->pending > 0 && !e->halted && e->ntoks > 0 && e->has_self && e->has_cross) {
     int budget = e->pending < STEP_SLICE ? e->pending : STEP_SLICE;
     int added = run_steps(e, budget, e->win <= RESTART_HOPS);
     e->pending -= added;
@@ -718,11 +795,24 @@ JNIEXPORT jstring JNICALL JNIFN(nativeFinish)(JNIEnv* env, jobject thiz, jlong h
     if (process_window(e, e->win * HOP, produced, 1, 0)) break;
     e->win++;
   }
+  double t_flush = now_ms();
   jstring out = NULL;
   if (e->nmem > 0) {
+#if MOONSHINE_FAST_FINISH
+    /* Skip the exact re-decode and keep what the incremental decode already produced.
+     *
+     * Measured on 16 push-to-talk recordings: against the last incremental result the exact
+     * re-decode was better 4 times, worse 5 and equal 7 — a wash. On the box it costs 3.8–4.5 s of a
+     * ~8 s turn, which is the single largest block after the utterance itself. Paying four seconds for
+     * a result that is not better is not a trade worth making for command and control.
+     *
+     * The window flush above still runs: it is what turns the remaining audio into memory rows, and it
+     * is the cheap half. */
+#else
     /* exact: fresh decode over the final memory */
     release_self(e); e->ntoks = 0; e->pos = 0; e->text[0] = 0;
     if (run_prefill(e, 1) == 0) run_steps(e, finish_budget(e->npcm), 1);
+#endif
     if (!e->ended_eos) drop_restart_suffix(e);
     /* C&C utterances are single sentences; on a silent tail the greedy decode restarts the
      * utterance instead of emitting EOS ("Go to the next. Go to next") — same failure and
@@ -732,13 +822,47 @@ JNIEXPORT jstring JNICALL JNIFN(nativeFinish)(JNIEnv* env, jobject thiz, jlong h
     }
     const char* p = e->text; while (*p == ' ') ++p;
     out = (*env)->NewStringUTF(env, p);
-    TLOG("finish %.0fms nmem %d toks %d/%d \"%s\"\n",
-            now_ms() - t0, e->nmem, e->ntoks, finish_budget(e->npcm), p);
+    /* flush and re-decode reported apart, so the cost of each half is visible rather than inferred. */
+    TLOG("finish %.0fms (flush %.0fms decode %.0fms) nmem %d toks %d/%d fast=%d dropped %d lag %.0fms \"%s\"\n",
+            now_ms() - t0, t_flush - t0, now_ms() - t_flush, e->nmem, e->ntoks,
+            finish_budget(e->npcm), MOONSHINE_FAST_FINISH, e->dropped,
+            e->t_first_feed > 0.0 ? t0 - e->t_first_feed - (double)e->npcm * 1000.0 / 16000.0 : 0.0, p);
+  }
+  /* Same figures the line above logs, kept for nativeStats — a caller should not have to parse logcat
+   * to learn what recognition cost. Written before the reset, which clears the counters. */
+  int n = snprintf(e->stats, sizeof(e->stats),
+      "flushMs=%.0f,decodeMs=%.0f,finishMs=%.0f,finishAtMs=%.0f,lagMs=%.0f,droppedDecodes=%d,"
+      "windows=%d,hops=%d,memFrames=%d,tokens=%d,tokenBudget=%d,audioMs=%.0f,fastFinish=%d,lagBudgetMs=%d",
+      t_flush - t0, now_ms() - t_flush, now_ms() - t0,
+      e->t_first_feed > 0.0 ? t0 - e->t_first_feed : 0.0,
+      e->t_first_feed > 0.0 ? t0 - e->t_first_feed - (double)e->npcm * 1000.0 / 16000.0 : 0.0,
+      e->dropped, e->windows, e->hops, e->nmem, e->ntoks, finish_budget(e->npcm),
+      (double)e->npcm * 1000.0 / 16000.0, MOONSHINE_FAST_FINISH, MOONSHINE_LAG_BUDGET_MS);
+  /* The utterance's timeline, so the shape can be drawn and not just totalled:
+   *   timeline=<kind>:<atMs>:<a>:<b>:<c>|...
+   * kind w = encoder window (a/b/c = frontend, encoder, adapter), p = early peek, h = partial
+   * decode, d = partial decode dropped to the real-time budget (a = its cost, b/c unused).
+   * `at` is ms from the first fed sample, the same zero `finishAtMs` uses. */
+  if (e->nevt > 0 && n > 0 && (size_t)n < sizeof(e->stats)) {
+    n += snprintf(e->stats + n, sizeof(e->stats) - n, ",timeline=");
+    for (int i = 0; i < e->nevt && n > 0 && (size_t)n < sizeof(e->stats); ++i) {
+      const char k = e->evt_kind[i] == EVT_WINDOW ? 'w' : e->evt_kind[i] == EVT_PEEK ? 'p'
+                   : e->evt_kind[i] == EVT_HOP ? 'h' : 'd';
+      n += snprintf(e->stats + n, sizeof(e->stats) - n, "%s%c:%d:%d:%d:%d",
+              i ? "|" : "", k, e->evt_at[i], e->evt_a[i], e->evt_b[i], e->evt_c[i]);
+    }
   }
   reset_utterance(e);
   return out;
 }
 
+/* The last utterance's counters as `key=value` pairs, or an empty string before the first finish().
+ * Valid until the next finish(); reset() and a new utterance leave it untouched. */
+JNIEXPORT jstring JNICALL JNIFN(nativeStats)(JNIEnv* env, jobject thiz, jlong handle) {
+  Engine* e = (Engine*)(intptr_t)handle; if (!e) return NULL;
+  return (*env)->NewStringUTF(env, e->stats);
+}
+
 JNIEXPORT void JNICALL JNIFN(nativeReset)(JNIEnv* env, jobject thiz, jlong handle) {
   Engine* e = (Engine*)(intptr_t)handle; if (e) reset_utterance(e);
 }