projection.spec.ts 16 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362
  1. /**
  2. * The `sessionStats` projection unit: mounting the plugin beside the
  3. * projection registry serves whole-log counts and wall times folded from step
  4. * boundaries, chunks, tool pairs, and assembled messages; compositions
  5. * without the registry are unaffected; unmounting the plugin removes the key
  6. * (HMR safety). The two counting regressions pinned here are the reasons the
  7. * fold counts step boundaries instead of assistant messages: a cancelled step
  8. * never assembles a message but still counts, and a max-tokens usage-host
  9. * message (empty content) adds no extra step. Wall-time math runs against the
  10. * exported definition directly, where event times are controlled.
  11. */
  12. import { describe, expect, it } from 'vitest'
  13. import { Context } from '@deepseek-ai/cordis'
  14. import { createMessage, ToolCallId } from '@deepseek-ai/dsh-llm'
  15. import type { StreamChunk, TokenUsage } from '@deepseek-ai/dsh-llm'
  16. import SessionStore, { SessionId } from '@deepseek-ai/dsh-session'
  17. import type { Session, SessionEvent } from '@deepseek-ai/dsh-session'
  18. import SessionProjectionRegistry from '@deepseek-ai/dsh-session-projection'
  19. import * as SessionStatsPlugin from '@deepseek-ai/dsh-session-stats'
  20. import { sessionStatsProjectionDefinition } from '@deepseek-ai/dsh-session-stats/src/projection.ts'
  21. import type { SessionStatsProjection } from '@deepseek-ai/dsh-session-stats/types'
  22. async function harness(withStatsPlugin: boolean): Promise<{ ctx: Context; session: Session }> {
  23. const ctx = new Context()
  24. await ctx.plugin(SessionStore)
  25. await ctx.plugin(SessionProjectionRegistry)
  26. if (withStatsPlugin) await ctx.plugin(SessionStatsPlugin)
  27. return { ctx, session: ctx.sessions.create(SessionId('counted')) }
  28. }
  29. /** Close one step; returns the counted `step/end` seq. */
  30. function closeStep(session: Session, turn: number, step: number): number {
  31. session.append('step/start', { turn, step })
  32. return session.append('step/end', { turn, step }).seq
  33. }
  34. /** Append the max-tokens usage-host shape: an assistant/message with empty content. */
  35. function appendEmptyAssistantMessage(session: Session, turn: number, step: number): void {
  36. session.append('assistant/message', {
  37. stream: [],
  38. turn,
  39. step,
  40. message: createMessage({
  41. role: 'assistant',
  42. content: [],
  43. source: { kind: 'model', provider: 'mock', model: 'mock' },
  44. }),
  45. }, { surfaceOp: 'append' })
  46. }
  47. /** The all-zero projection value plus overrides, for exact fold expectations. */
  48. function totals(overrides: Partial<SessionStatsProjection> = {}): SessionStatsProjection {
  49. return {
  50. turns: 0, steps: 0, llmMs: 0, toolMs: 0, ttftMs: 0, ttftSteps: 0, decodeMs: 0, decodeTokens: 0,
  51. ...overrides,
  52. }
  53. }
  54. describe('sessionStats projection unit (registry drive)', () => {
  55. it('serves zero figures on the empty log', async () => {
  56. const { ctx, session } = await harness(true)
  57. expect(ctx.sessionProjections.snapshot(session).values.sessionStats).toEqual(totals())
  58. })
  59. it('counts distinct turns and closed steps and notifies the change feed with the causing seq', async () => {
  60. const { ctx, session } = await harness(true)
  61. const changes: { key: string; value: unknown; seq: number }[] = []
  62. ctx.sessionProjections.onChanged((_session, key, value, seq) => {
  63. changes.push({ key, value, seq })
  64. })
  65. session.append('turn/start', { turn: 1 })
  66. const firstSeq = closeStep(session, 1, 1)
  67. const secondSeq = closeStep(session, 1, 2)
  68. session.append('turn/end', { turn: 1, reason: { kind: 'completed' } })
  69. session.append('turn/start', { turn: 2 })
  70. const thirdSeq = closeStep(session, 2, 1)
  71. session.append('turn/end', { turn: 2, reason: { kind: 'completed' } })
  72. // Boundary events that carry no figure change (turn/start, empty-prune
  73. // turn/end, user input) fold to the same reference and stay silent;
  74. // step/start opens a boundary (internal state) and step/end commits the
  75. // counts, so each closed step notifies twice with the step/end value last.
  76. const counted = changes.filter(change => (change.value as SessionStatsProjection).steps > 0
  77. || change.seq === firstSeq)
  78. expect(changes.every(change => change.key === 'sessionStats')).toBe(true)
  79. expect(counted.map(change => ({ seq: change.seq, value: change.value }))).toContainEqual(
  80. { seq: firstSeq, value: totals({ turns: 1, steps: 1 }) },
  81. )
  82. expect(changes.at(-1)).toEqual({ key: 'sessionStats', value: totals({ turns: 2, steps: 3 }), seq: thirdSeq })
  83. const snapshot = ctx.sessionProjections.snapshot(session)
  84. expect(snapshot.values.sessionStats).toEqual(totals({ turns: 2, steps: 3 }))
  85. expect(snapshot.asOfSeq).toBe(session.seq - 1)
  86. expect(changes.map(change => change.seq)).toContain(secondSeq)
  87. })
  88. it('does not count a rejected or empty turn that closes with no step', async () => {
  89. const { ctx, session } = await harness(true)
  90. session.append('turn/start', { turn: 1 })
  91. session.append('turn/end', { turn: 1, reason: { kind: 'blocked' } })
  92. expect(ctx.sessionProjections.snapshot(session).values.sessionStats).toEqual(totals())
  93. })
  94. it('counts a cancelled step that closed without an assistant message', async () => {
  95. // Regression: an aborted stream never assembles assistant/message, but the
  96. // loop's finally still appends step/end — the step happened and counts.
  97. const { ctx, session } = await harness(true)
  98. session.append('turn/start', { turn: 1 })
  99. closeStep(session, 1, 1)
  100. session.append('turn/end', { turn: 1, reason: { kind: 'aborted', reason: { kind: 'legacy' } } })
  101. expect(ctx.sessionProjections.snapshot(session).values.sessionStats)
  102. .toMatchObject({ turns: 1, steps: 1 })
  103. })
  104. it('adds no extra step for a max-tokens usage-host assistant message', async () => {
  105. // Regression: the empty-content assistant/message exists only to host
  106. // usage and is excluded from the surface; the step counts once, from its
  107. // step/end, while the message contributes only its model wall time.
  108. const { ctx, session } = await harness(true)
  109. session.append('turn/start', { turn: 1 })
  110. session.append('step/start', { turn: 1, step: 1 })
  111. appendEmptyAssistantMessage(session, 1, 1)
  112. session.append('step/end', { turn: 1, step: 1 })
  113. session.append('turn/end', { turn: 1, reason: { kind: 'max-tokens' } })
  114. expect(ctx.sessionProjections.snapshot(session).values.sessionStats)
  115. .toMatchObject({ turns: 1, steps: 1, ttftSteps: 0, decodeTokens: 0 })
  116. })
  117. it('folds steps already in the log when the plugin mounts late (lazy cell build)', async () => {
  118. const { ctx, session } = await harness(false)
  119. session.append('turn/start', { turn: 1 })
  120. closeStep(session, 1, 1)
  121. closeStep(session, 1, 2)
  122. session.append('turn/end', { turn: 1, reason: { kind: 'completed' } })
  123. await ctx.plugin(SessionStatsPlugin)
  124. expect(ctx.sessionProjections.snapshot(session).values.sessionStats)
  125. .toMatchObject({ turns: 1, steps: 2 })
  126. })
  127. it('has no sessionStats key without the plugin, and drops it when the plugin unloads (HMR safety)', async () => {
  128. const { ctx, session } = await harness(false)
  129. expect('sessionStats' in ctx.sessionProjections.snapshot(session).values).toBe(false)
  130. const fiber = await ctx.plugin(SessionStatsPlugin)
  131. session.append('turn/start', { turn: 1 })
  132. closeStep(session, 1, 1)
  133. expect(ctx.sessionProjections.snapshot(session).values.sessionStats)
  134. .toMatchObject({ turns: 1, steps: 1 })
  135. await fiber.dispose()
  136. expect('sessionStats' in ctx.sessionProjections.snapshot(session).values).toBe(false)
  137. })
  138. })
  139. /** Build one synthetic committed event with a controlled timestamp. */
  140. function at(time: number, type: string, data: unknown): SessionEvent {
  141. return { type, seq: time, time, data } as unknown as SessionEvent
  142. }
  143. function attemptAt(
  144. time: number,
  145. chunks: readonly { readonly time: number; readonly chunk: StreamChunk }[],
  146. turn = 1,
  147. step = 1,
  148. ): SessionEvent {
  149. return at(time, 'assistant/attempt', {
  150. turn,
  151. step,
  152. stream: chunks.map(member => ({ type: 'chunk', ...member })),
  153. })
  154. }
  155. /** Fold a synthetic event list through the definition and view the result. */
  156. function fold(events: readonly SessionEvent[]): SessionStatsProjection {
  157. const state = events.reduce<Parameters<typeof sessionStatsProjectionDefinition.apply>[0]>(
  158. (folded, event) => sessionStatsProjectionDefinition.apply(folded, event),
  159. sessionStatsProjectionDefinition.init(),
  160. )
  161. return sessionStatsProjectionDefinition.wire.view(state)
  162. }
  163. describe('sessionStats wall-time fold (controlled timestamps)', () => {
  164. const message = createMessage({
  165. role: 'assistant',
  166. content: [{ type: 'text', text: 'answer' }],
  167. source: { kind: 'model', provider: 'mock', model: 'mock' },
  168. })
  169. function messageAt(
  170. time: number,
  171. chunks: readonly { readonly time: number; readonly chunk: StreamChunk }[] = [],
  172. usage?: TokenUsage,
  173. ): SessionEvent {
  174. return at(time, 'assistant/message', {
  175. turn: 1,
  176. step: 1,
  177. message,
  178. stream: chunks.map(member => ({ type: 'chunk', ...member })),
  179. ...usage === undefined ? {} : { usage },
  180. })
  181. }
  182. it('accrues model, first-token, and decode time from one fully recorded step', () => {
  183. expect(fold([
  184. at(1_000, 'step/start', { turn: 1, step: 1 }),
  185. messageAt(4_800, [{
  186. time: 1_800, chunk: { type: 'text-delta', index: 0, text: 'a' },
  187. }], { inputTokens: 10, outputTokens: 60 }),
  188. at(4_900, 'step/end', { turn: 1, step: 1 }),
  189. ])).toEqual(totals({
  190. turns: 1, steps: 1, llmMs: 3_800, ttftMs: 800, ttftSteps: 1, decodeMs: 3_000, decodeTokens: 60,
  191. }))
  192. })
  193. it('keeps the first attempt token boundary across an in-step retry (window resetForRetry parity)', () => {
  194. expect(fold([
  195. at(1_000, 'step/start', { turn: 1, step: 1 }),
  196. attemptAt(1_100, [{
  197. time: 1_100, chunk: { type: 'text-delta', index: 0, text: '' },
  198. }]),
  199. attemptAt(2_000, [{
  200. time: 1_200, chunk: { type: 'reasoning-delta', index: 0, text: 'x' },
  201. }]),
  202. attemptAt(2_500, [{
  203. time: 1_500, chunk: { type: 'text-delta', index: 0, text: 'later' },
  204. }]),
  205. at(2_000, 'llm/retry', { turn: 1, step: 1 }),
  206. messageAt(5_000, [{
  207. time: 3_000, chunk: { type: 'text-delta', index: 0, text: 'y' },
  208. }]),
  209. at(5_100, 'step/end', { turn: 1, step: 1 }),
  210. ])).toEqual(totals({ turns: 1, steps: 1, llmMs: 4_000, ttftMs: 200, ttftSteps: 1 }))
  211. })
  212. it('ignores empty deltas, non-token chunks, and chunks outside the open step', () => {
  213. expect(fold([
  214. // Attempt before any step/start: no open boundary.
  215. attemptAt(500, [{
  216. time: 500, chunk: { type: 'text-delta', index: 0, text: 'stray' },
  217. }]),
  218. at(1_000, 'step/start', { turn: 1, step: 1 }),
  219. attemptAt(1_300, [{
  220. time: 1_300, chunk: { type: 'text-delta', index: 0, text: 'other' },
  221. }], 2, 9),
  222. messageAt(2_000, [
  223. { time: 1_100, chunk: { type: 'block-start', index: 0, blockType: 'text' } },
  224. { time: 1_200, chunk: { type: 'text-delta', index: 0, text: '' } },
  225. { time: 1_400, chunk: { type: 'text-delta', index: 0, text: 'first' } },
  226. ]),
  227. at(2_100, 'step/end', { turn: 1, step: 1 }),
  228. ])).toEqual(totals({ turns: 1, steps: 1, llmMs: 1_000, ttftMs: 400, ttftSteps: 1 }))
  229. })
  230. it('uses non-empty Tool-call names or arguments as the first token', () => {
  231. expect(fold([
  232. at(1_000, 'step/start', { turn: 1, step: 1 }),
  233. messageAt(2_000, [
  234. { time: 1_100, chunk: { type: 'tool-call-delta', index: 0, id: ToolCallId('call-1'), argumentsDelta: '' } },
  235. {
  236. time: 1_200,
  237. chunk: { type: 'tool-call-delta', index: 0, id: ToolCallId('call-1'), name: 'read', argumentsDelta: '' },
  238. },
  239. ]),
  240. at(2_100, 'step/end', { turn: 1, step: 1 }),
  241. ])).toEqual(totals({ turns: 1, steps: 1, llmMs: 1_000, ttftMs: 200, ttftSteps: 1 }))
  242. expect(fold([
  243. at(1_000, 'step/start', { turn: 1, step: 1 }),
  244. messageAt(2_000, [{
  245. time: 1_300,
  246. chunk: { type: 'tool-call-delta', index: 0, id: ToolCallId('call-1'), argumentsDelta: '{' },
  247. }]),
  248. at(2_100, 'step/end', { turn: 1, step: 1 }),
  249. ])).toEqual(totals({ turns: 1, steps: 1, llmMs: 1_000, ttftMs: 300, ttftSteps: 1 }))
  250. })
  251. it('leaves a cancelled step untimed: counted by step/end, no assembled message to accrue from', () => {
  252. expect(fold([
  253. at(1_000, 'step/start', { turn: 1, step: 1 }),
  254. attemptAt(1_500, [{
  255. time: 1_500, chunk: { type: 'text-delta', index: 0, text: 'partial' },
  256. }]),
  257. at(2_000, 'step/end', { turn: 1, step: 1 }),
  258. ])).toEqual(totals({ turns: 1, steps: 1 }))
  259. })
  260. it('pairs tool wall time by callId, ignores orphan results, and prunes leftovers at turn/end', () => {
  261. const result = (callId: string): unknown =>
  262. ({ turn: 1, step: 1, message: { source: { kind: 'tool', callId } } })
  263. const paired = fold([
  264. at(1_000, 'step/start', { turn: 1, step: 1 }),
  265. at(1_100, 'tool/call', { turn: 1, step: 1, callId: 'a', name: 'read', arguments: '{}' }),
  266. at(1_200, 'tool/call', { turn: 1, step: 1, callId: 'b', name: 'read', arguments: '{}' }),
  267. // Out-of-order settlement pairs by id, not adjacency.
  268. at(4_200, 'tool/result', result('b')),
  269. at(1_600, 'tool/result', result('a')),
  270. at(5_000, 'tool/result', result('ghost')),
  271. at(5_100, 'step/end', { turn: 1, step: 1 }),
  272. ])
  273. expect(paired).toEqual(totals({ turns: 1, steps: 1, toolMs: 3_500 }))
  274. // An unresolved call is dropped at turn/end; a later result cannot pair.
  275. const pruned = fold([
  276. at(1_000, 'step/start', { turn: 1, step: 1 }),
  277. at(1_100, 'tool/call', { turn: 1, step: 1, callId: 'orphan', name: 'read', arguments: '{}' }),
  278. at(2_000, 'step/end', { turn: 1, step: 1 }),
  279. at(2_100, 'turn/end', { turn: 1, reason: { kind: 'aborted', reason: { kind: 'legacy' } } }),
  280. at(9_000, 'tool/result', result('orphan')),
  281. ])
  282. expect(pruned).toEqual(totals({ turns: 1, steps: 1 }))
  283. })
  284. it('pairs only own pendingCalls keys: a prototype-name callId without a recorded call stays unmatched', () => {
  285. const result = (callId: string): unknown =>
  286. ({ turn: 1, step: 1, message: { source: { kind: 'tool', callId } } })
  287. // Crash recovery (TOOL_NOT_STARTED) emits results with no preceding
  288. // tool/call; a provider-minted callId colliding with an Object prototype
  289. // property must read as absent, not as an inherited function that would
  290. // fold toolMs to NaN and fail the value schema.
  291. expect(fold([
  292. at(1_000, 'step/start', { turn: 1, step: 1 }),
  293. at(1_500, 'tool/result', result('toString')),
  294. at(2_000, 'step/end', { turn: 1, step: 1 }),
  295. ])).toEqual(totals({ turns: 1, steps: 1 }))
  296. // The same name pairs normally once its call is recorded.
  297. expect(fold([
  298. at(1_000, 'step/start', { turn: 1, step: 1 }),
  299. at(1_100, 'tool/call', { turn: 1, step: 1, callId: 'constructor', name: 'read', arguments: '{}' }),
  300. at(1_600, 'tool/result', result('constructor')),
  301. at(2_000, 'step/end', { turn: 1, step: 1 }),
  302. ])).toEqual(totals({ turns: 1, steps: 1, toolMs: 500 }))
  303. })
  304. it('skips decode for an invalid usage report and ignores a duplicate assembled message', () => {
  305. const events = [
  306. at(1_000, 'step/start', { turn: 1, step: 1 }),
  307. // A malformed provider report: guarded like the window fold guards node usage.
  308. messageAt(2_000, [{
  309. time: 1_400, chunk: { type: 'text-delta', index: 0, text: 'a' },
  310. }], { inputTokens: 1, outputTokens: -5 }),
  311. ]
  312. expect(fold([...events, at(2_100, 'step/end', { turn: 1, step: 1 })]))
  313. .toEqual(totals({ turns: 1, steps: 1, llmMs: 1_000, ttftMs: 400, ttftSteps: 1 }))
  314. // The first message closed the step boundary; a defensive duplicate finds
  315. // no open step and folds to the same reference.
  316. const state = events.reduce<Parameters<typeof sessionStatsProjectionDefinition.apply>[0]>(
  317. (folded, event) => sessionStatsProjectionDefinition.apply(folded, event),
  318. sessionStatsProjectionDefinition.init(),
  319. )
  320. expect(sessionStatsProjectionDefinition.apply(
  321. state,
  322. messageAt(2_050),
  323. )).toBe(state)
  324. })
  325. it('accrues nothing for unrelated events and clamps negative clock skew to zero', () => {
  326. const state = sessionStatsProjectionDefinition.init()
  327. const untouched = sessionStatsProjectionDefinition.apply(state, at(1, 'user/message', { content: [] }))
  328. expect(untouched).toBe(state)
  329. expect(fold([
  330. at(2_000, 'step/start', { turn: 1, step: 1 }),
  331. messageAt(1_000),
  332. at(2_100, 'step/end', { turn: 1, step: 1 }),
  333. ])).toEqual(totals({ turns: 1, steps: 1 }))
  334. })
  335. })