diff --git a/evals/run-evals.sh b/evals/run-evals.sh index 3457743a8..eeeb38495 100755 --- a/evals/run-evals.sh +++ b/evals/run-evals.sh @@ -334,6 +334,18 @@ CREATE TABLE IF NOT EXISTS eval_results ( details TEXT, PRIMARY KEY (run_id, case_name, run_number) ); +CREATE TABLE IF NOT EXISTS eval_metrics ( + run_id TEXT NOT NULL REFERENCES eval_runs(run_id), + category TEXT NOT NULL, + case_name TEXT NOT NULL, + run_number INTEGER NOT NULL, + input_tokens INTEGER, + output_tokens INTEGER, + cached_tokens INTEGER, + prompt_ms REAL, + predicted_tok_s REAL, + PRIMARY KEY (run_id, case_name, run_number) +); SQL } @@ -349,6 +361,73 @@ store_result() { VALUES ('$RUN_ID', '$esc_category', '$case_name', $run_number, '$esc_prompt', $passed, '$esc_details');" } +## Parses the [usage] line from stdout and stores performance metrics. +## Called after each run_prompt / store_result pair. +store_metrics() { + [[ -z "$RESULTS_DB" ]] && return + [[ ! -f "$STDOUT_FILE" ]] && return + + local case_name="$1" run_number="$2" + local usage_line + usage_line=$(grep -o '\[usage\].*' "$STDOUT_FILE" 2>/dev/null | tail -1) || return 0 + + # Parse fields from: [usage] in=X out=Y total=Z cached=C prompt_ms=P tok_s=T + local input_tokens output_tokens cached_tokens prompt_ms tok_s + input_tokens=$(echo "$usage_line" | grep -oP 'in=\K[0-9]+' || echo "") + output_tokens=$(echo "$usage_line" | grep -oP 'out=\K[0-9]+' || echo "") + cached_tokens=$(echo "$usage_line" | grep -oP 'cached=\K[0-9]+' || echo "") + prompt_ms=$(echo "$usage_line" | grep -oP 'prompt_ms=\K[0-9.]+' || echo "") + tok_s=$(echo "$usage_line" | grep -oP 'tok_s=\K[0-9.]+' || echo "") + + # Skip if no metrics found + [[ -z "$input_tokens" && -z "$cached_tokens" && -z "$prompt_ms" ]] && return 0 + + local esc_category="${CURRENT_CATEGORY//\'/\'\'}" + sqlite3 "$RESULTS_DB" \ + "INSERT INTO eval_metrics (run_id, category, case_name, run_number, input_tokens, output_tokens, cached_tokens, prompt_ms, predicted_tok_s) + VALUES ('$RUN_ID', '$esc_category', '$case_name', $run_number, + ${input_tokens:-NULL}, ${output_tokens:-NULL}, ${cached_tokens:-NULL}, + ${prompt_ms:-NULL}, ${tok_s:-NULL});" +} + +print_metrics_summary() { + [[ -z "$RESULTS_DB" ]] && return + + local count + count=$(sqlite3 "$RESULTS_DB" "SELECT COUNT(*) FROM eval_metrics WHERE run_id='$RUN_ID' AND prompt_ms IS NOT NULL;" 2>/dev/null || echo "0") + [[ "$count" == "0" ]] && return + + echo "" + echo "── Performance Metrics ──" + sqlite3 -header -column "$RESULTS_DB" < public double? UsagePercent { get; init; } + + // ── Server-side timing (llama.cpp timings object) ── + + /// + /// Server-side prompt processing (prefill) time in milliseconds. + /// Sourced from llama.cpp timings.prompt_ms. Null when the + /// provider does not report timing data. + /// + public double? PromptMs { get; init; } + + /// + /// Server-side output generation throughput in tokens per second. + /// Sourced from llama.cpp timings.predicted_per_second. + /// + public double? PredictedPerSecond { get; init; } } /// diff --git a/src/Netclaw.Actors/Protocol/SessionOutputDto.cs b/src/Netclaw.Actors/Protocol/SessionOutputDto.cs index 25d1f89fe..dfa8e2e34 100644 --- a/src/Netclaw.Actors/Protocol/SessionOutputDto.cs +++ b/src/Netclaw.Actors/Protocol/SessionOutputDto.cs @@ -67,8 +67,12 @@ public sealed record SessionOutputDto public long? InputTokens { get; init; } public long? OutputTokens { get; init; } public long? TotalTokens { get; init; } + public long? CachedInputTokens { get; init; } + public long? ReasoningTokens { get; init; } public int? ContextWindowTokens { get; init; } public double? UsagePercent { get; init; } + public double? PromptMs { get; init; } + public double? PredictedPerSecond { get; init; } // Turn Completed public int? TurnNumber { get; init; } diff --git a/src/Netclaw.Actors/Protocol/SessionOutputDtoMapper.cs b/src/Netclaw.Actors/Protocol/SessionOutputDtoMapper.cs index 08c2c6d6b..c347f970a 100644 --- a/src/Netclaw.Actors/Protocol/SessionOutputDtoMapper.cs +++ b/src/Netclaw.Actors/Protocol/SessionOutputDtoMapper.cs @@ -68,8 +68,12 @@ public static class SessionOutputDtoMapper InputTokens = msg.InputTokens, OutputTokens = msg.OutputTokens, TotalTokens = msg.TotalTokens, + CachedInputTokens = msg.CachedInputTokens, + ReasoningTokens = msg.ReasoningTokens, ContextWindowTokens = msg.ContextWindowTokens, - UsagePercent = msg.UsagePercent + UsagePercent = msg.UsagePercent, + PromptMs = msg.PromptMs, + PredictedPerSecond = msg.PredictedPerSecond, }, TurnCompleted msg => new SessionOutputDto @@ -233,8 +237,12 @@ public static SessionOutput FromDto(SessionOutputDto dto) InputTokens = dto.InputTokens, OutputTokens = dto.OutputTokens, TotalTokens = dto.TotalTokens, + CachedInputTokens = dto.CachedInputTokens, + ReasoningTokens = dto.ReasoningTokens, ContextWindowTokens = dto.ContextWindowTokens ?? 0, - UsagePercent = dto.UsagePercent + UsagePercent = dto.UsagePercent, + PromptMs = dto.PromptMs, + PredictedPerSecond = dto.PredictedPerSecond, }, SessionOutputTypes.TurnCompleted => new TurnCompleted { diff --git a/src/Netclaw.Actors/Sessions/LlmSessionActor.cs b/src/Netclaw.Actors/Sessions/LlmSessionActor.cs index c59eed4c6..a7e2d4f1a 100644 --- a/src/Netclaw.Actors/Sessions/LlmSessionActor.cs +++ b/src/Netclaw.Actors/Sessions/LlmSessionActor.cs @@ -2503,6 +2503,15 @@ private void EmitUsageOutput(UsageDetails usage) ? (double)usage.InputTokenCount.Value / contextWindow : null; + // Decode llama.cpp server-side timing from UsageDetails.AdditionalCounts. + // Canonical encoding lives in Netclaw.Providers.SelfHosted.OpenAiCompatibleChatClient + // (PromptUsKey, PredictedTokPerSecX100Key). Keep these strings in sync. + var additional = usage.AdditionalCounts; + double? promptMs = additional is not null && additional.TryGetValue("prompt_us", out var pUs) + ? pUs / 1000.0 : null; + double? predictedPerSec = additional is not null && additional.TryGetValue("predicted_tok_per_sec_x100", out var pps) + ? pps / 100.0 : null; + EmitOutput(new UsageOutput { SessionId = _sessionId, @@ -2512,7 +2521,9 @@ private void EmitUsageOutput(UsageDetails usage) CachedInputTokens = usage.CachedInputTokenCount, ReasoningTokens = usage.ReasoningTokenCount, ContextWindowTokens = contextWindow, - UsagePercent = usagePercent + UsagePercent = usagePercent, + PromptMs = promptMs, + PredictedPerSecond = predictedPerSec, }, OutputFilter.Usage); } diff --git a/src/Netclaw.Cli/HeadlessChannel.cs b/src/Netclaw.Cli/HeadlessChannel.cs index 03a7279b1..bff66734b 100644 --- a/src/Netclaw.Cli/HeadlessChannel.cs +++ b/src/Netclaw.Cli/HeadlessChannel.cs @@ -1,3 +1,4 @@ +using System.Diagnostics; using System.Text; using System.Text.Json; using Microsoft.Extensions.AI; @@ -37,6 +38,10 @@ public sealed class HeadlessChannel : IChannel private JsonUsage? _usage; private string? _resolvedSessionId; + // Client-side timing + private long _promptSentTicks; + private long _firstDeltaTicks; + public Actors.Channels.ChannelType ChannelType => Actors.Channels.ChannelType.Headless; public string DisplayName => "Headless Prompt"; @@ -130,6 +135,8 @@ private async Task RunHeadlessAsync(CancellationToken stopping) logWriter!.WriteLine($"[{_timeProvider.GetUtcNow():o}] Headless session started: {sessionId}"); logWriter.WriteLine($"[{_timeProvider.GetUtcNow():o}] PROMPT: {_prompt}"); + _promptSentTicks = Stopwatch.GetTimestamp(); + await _daemonClient.SendAsync(new Netclaw.Actors.Channels.ChannelInput { SenderId = "local-user", @@ -185,6 +192,8 @@ private void HandleOutput(SessionOutput output, StreamWriter? log) break; case TextDeltaOutput msg: + if (!_receivedTextDeltaInCurrentTurn && _promptSentTicks > 0) + Interlocked.CompareExchange(ref _firstDeltaTicks, Stopwatch.GetTimestamp(), 0); _receivedTextDeltaInCurrentTurn = true; if (_jsonOutput) _responseBuffer.Append(msg.Delta); @@ -241,14 +250,16 @@ private void HandleOutput(SessionOutput output, StreamWriter? log) OutputTokens = msg.OutputTokens, TotalTokens = msg.TotalTokens, CachedInputTokens = msg.CachedInputTokens, - ReasoningTokens = msg.ReasoningTokens + ReasoningTokens = msg.ReasoningTokens, + PromptMs = msg.PromptMs, + PredictedPerSecond = msg.PredictedPerSecond, }; } else { - Console.WriteLine($"[usage] in={msg.InputTokens} out={msg.OutputTokens} total={msg.TotalTokens}"); + Console.WriteLine($"[usage] in={msg.InputTokens} out={msg.OutputTokens} total={msg.TotalTokens} cached={msg.CachedInputTokens} prompt_ms={msg.PromptMs} tok_s={msg.PredictedPerSecond}"); } - Log(log, $"USAGE: in={msg.InputTokens} out={msg.OutputTokens} total={msg.TotalTokens} cached={msg.CachedInputTokens} reasoning={msg.ReasoningTokens} context_window={msg.ContextWindowTokens}"); + Log(log, $"USAGE: in={msg.InputTokens} out={msg.OutputTokens} total={msg.TotalTokens} cached={msg.CachedInputTokens} reasoning={msg.ReasoningTokens} context_window={msg.ContextWindowTokens} prompt_ms={msg.PromptMs} predicted_tok_s={msg.PredictedPerSecond}"); break; case ErrorOutput msg: @@ -311,12 +322,23 @@ private void HandleOutput(SessionOutput output, StreamWriter? log) private void WriteJsonEnvelope() { + // Client-side timing + var now = Stopwatch.GetTimestamp(); + double? ttftMs = _firstDeltaTicks > 0 && _promptSentTicks > 0 + ? Stopwatch.GetElapsedTime(_promptSentTicks, _firstDeltaTicks).TotalMilliseconds + : null; + double? totalMs = _promptSentTicks > 0 + ? Stopwatch.GetElapsedTime(_promptSentTicks, now).TotalMilliseconds + : null; + var envelope = new JsonEnvelope { SessionId = _resolvedSessionId!, Response = _responseBuffer.ToString(), ToolCalls = _toolCalls.Count > 0 ? _toolCalls : null, - Usage = _usage + Usage = _usage, + TtftMs = ttftMs.HasValue ? Math.Round(ttftMs.Value, 1) : null, + TotalMs = totalMs.HasValue ? Math.Round(totalMs.Value, 1) : null, }; Console.WriteLine(JsonSerializer.Serialize(envelope, s_jsonOptions)); @@ -350,6 +372,8 @@ private sealed class JsonEnvelope public required string Response { get; init; } public List? ToolCalls { get; init; } public JsonUsage? Usage { get; init; } + public double? TtftMs { get; init; } + public double? TotalMs { get; init; } } private sealed class JsonToolCall @@ -366,5 +390,7 @@ private sealed class JsonUsage public long? TotalTokens { get; init; } public long? CachedInputTokens { get; init; } public long? ReasoningTokens { get; init; } + public double? PromptMs { get; init; } + public double? PredictedPerSecond { get; init; } } } diff --git a/src/Netclaw.Daemon.Tests/Configuration/OpenAiCompatibleChatClientTests.cs b/src/Netclaw.Daemon.Tests/Configuration/OpenAiCompatibleChatClientTests.cs index 2f7839188..74a3d98d1 100644 --- a/src/Netclaw.Daemon.Tests/Configuration/OpenAiCompatibleChatClientTests.cs +++ b/src/Netclaw.Daemon.Tests/Configuration/OpenAiCompatibleChatClientTests.cs @@ -633,6 +633,167 @@ public void ParseUsage_ReturnsNull_WhenUsageFieldMissing() Assert.Null(OpenAiCompatibleChatClient.ParseUsage(doc.RootElement)); } + [Fact] + public void ParseUsage_TimingsSurviveUsageDetailsAdd() + { + // Simulate what ToChatResponse does: creates a new UsageDetails and calls Add() + // with the parsed result. Verify CachedInputTokenCount and AdditionalCounts survive. + using var doc = JsonDocument.Parse(""" + { + "usage": { "prompt_tokens": 100, "completion_tokens": 20, "total_tokens": 120 }, + "timings": { + "cache_n": 85, + "prompt_ms": 139.655, + "predicted_per_second": 31.241 + } + } + """); + + var parsed = OpenAiCompatibleChatClient.ParseUsage(doc.RootElement)!; + + // This is what ToChatResponse does internally: new UsageDetails().Add(parsed) + var aggregated = new UsageDetails(); + aggregated.Add(parsed); + + Assert.Equal(100, aggregated.InputTokenCount); + Assert.Equal(85, aggregated.CachedInputTokenCount); + Assert.NotNull(aggregated.AdditionalCounts); + Assert.Equal(139655, aggregated.AdditionalCounts["prompt_us"]); + Assert.Equal(3124, aggregated.AdditionalCounts["predicted_tok_per_sec_x100"]); + } + + [Fact] + public void ParseUsage_ReadsTokenCounts_WithoutTimings() + { + using var doc = JsonDocument.Parse(""" + { + "usage": { "prompt_tokens": 50, "completion_tokens": 10, "total_tokens": 60 } + } + """); + + var usage = OpenAiCompatibleChatClient.ParseUsage(doc.RootElement); + + Assert.NotNull(usage); + Assert.Equal(50, usage.InputTokenCount); + Assert.Equal(10, usage.OutputTokenCount); + Assert.Equal(60, usage.TotalTokenCount); + Assert.Null(usage.CachedInputTokenCount); + Assert.Null(usage.AdditionalCounts); + } + + [Fact] + public void ParseUsage_ReadsLlamaCppTimings_WhenPresent() + { + using var doc = JsonDocument.Parse(""" + { + "usage": { "prompt_tokens": 100, "completion_tokens": 20, "total_tokens": 120 }, + "timings": { + "cache_n": 85, + "prompt_n": 15, + "prompt_ms": 139.655, + "prompt_per_second": 78.766, + "predicted_n": 20, + "predicted_ms": 160.048, + "predicted_per_token_ms": 8.002, + "predicted_per_second": 31.241 + } + } + """); + + var usage = OpenAiCompatibleChatClient.ParseUsage(doc.RootElement); + + Assert.NotNull(usage); + Assert.Equal(100, usage.InputTokenCount); + Assert.Equal(20, usage.OutputTokenCount); + Assert.Equal(85, usage.CachedInputTokenCount); + + Assert.NotNull(usage.AdditionalCounts); + // prompt_ms stored as microseconds for integer precision + Assert.Equal(139655, usage.AdditionalCounts["prompt_us"]); + // predicted_per_second stored as x100 for integer precision + Assert.Equal(3124, usage.AdditionalCounts["predicted_tok_per_sec_x100"]); + // prompt_per_second stored as x100 + Assert.Equal(7876, usage.AdditionalCounts["prompt_tok_per_sec_x100"]); + // predicted_ms stored as microseconds + Assert.Equal(160048, usage.AdditionalCounts["predicted_us"]); + } + + [Fact] + public void ParseUsage_GracefullyIgnoresTimings_WhenTimingsObjectAbsent() + { + using var doc = JsonDocument.Parse(""" + { + "usage": { "prompt_tokens": 50, "completion_tokens": 10, "total_tokens": 60 } + } + """); + + var usage = OpenAiCompatibleChatClient.ParseUsage(doc.RootElement); + + Assert.NotNull(usage); + Assert.Equal(50, usage.InputTokenCount); + Assert.Null(usage.CachedInputTokenCount); + Assert.Null(usage.AdditionalCounts); + } + + [Fact] + public void ParseUsage_HandlesPartialTimings() + { + // Some fields present, others missing — should not throw + using var doc = JsonDocument.Parse(""" + { + "usage": { "prompt_tokens": 50, "completion_tokens": 10, "total_tokens": 60 }, + "timings": { "cache_n": 30 } + } + """); + + var usage = OpenAiCompatibleChatClient.ParseUsage(doc.RootElement); + + Assert.NotNull(usage); + Assert.Equal(30, usage.CachedInputTokenCount); + // No throughput fields → AdditionalCounts should be empty or null + Assert.True(usage.AdditionalCounts is null || usage.AdditionalCounts.Count == 0); + } + + [Fact] + public async Task StreamingResponse_WithTimings_SurfacesCachedTokensAndThroughput() + { + // Simulate a llama.cpp streaming response where the final chunk includes timings + const string sse = """ + data: {"id":"abc","model":"test","choices":[{"index":0,"delta":{"content":"Hi"},"finish_reason":"stop"}]} + + data: {"id":"abc","model":"test","choices":[],"usage":{"prompt_tokens":100,"completion_tokens":5,"total_tokens":105},"timings":{"cache_n":80,"prompt_n":20,"prompt_ms":50.5,"predicted_per_second":25.3}} + + data: [DONE] + + """; + + using var handler = new RecordingHandler(_ => new HttpResponseMessage(HttpStatusCode.OK) + { + Content = new StringContent(sse, Encoding.UTF8, "text/event-stream") + }); + using var httpClient = new HttpClient(handler) { BaseAddress = new Uri("http://localhost:8000") }; + var endpoint = OpenAiCompatibleEndpoint.FromBaseUrl("http://localhost:8000"); + var client = new OpenAiCompatibleChatClient(httpClient, endpoint, "test-model"); + + var updates = new List(); + await foreach (var update in client.GetStreamingResponseAsync( + [new ChatMessage(ChatRole.User, "hello")], + cancellationToken: TestContext.Current.CancellationToken)) + { + updates.Add(update); + } + + var response = updates.ToChatResponse(); + + Assert.NotNull(response.Usage); + Assert.Equal(100, response.Usage.InputTokenCount); + Assert.Equal(5, response.Usage.OutputTokenCount); + Assert.Equal(80, response.Usage.CachedInputTokenCount); + Assert.NotNull(response.Usage.AdditionalCounts); + Assert.Equal(50500, response.Usage.AdditionalCounts["prompt_us"]); + Assert.Equal(2530, response.Usage.AdditionalCounts["predicted_tok_per_sec_x100"]); + } + [Fact] public async Task StreamingRequest_IncludesStreamOptions() { diff --git a/src/Netclaw.Providers/SelfHosted/OpenAiCompatibleChatClient.cs b/src/Netclaw.Providers/SelfHosted/OpenAiCompatibleChatClient.cs index 83f5f83ce..23fb9d437 100644 --- a/src/Netclaw.Providers/SelfHosted/OpenAiCompatibleChatClient.cs +++ b/src/Netclaw.Providers/SelfHosted/OpenAiCompatibleChatClient.cs @@ -588,7 +588,10 @@ private static IEnumerable ParseStreamingUpdates(JsonElement /// /// Parses the usage object from an OpenAI-compatible response or streaming chunk. - /// Returns null when the field is absent or not an object. + /// Also reads the llama.cpp timings object when present, mapping cache_n + /// to and storing throughput/latency + /// fields in . + /// Returns null when the usage field is absent or not an object. /// internal static UsageDetails? ParseUsage(JsonElement root) { @@ -605,12 +608,84 @@ private static IEnumerable ParseStreamingUpdates(JsonElement if (promptTokens is null && completionTokens is null && totalTokens is null) return null; - return new UsageDetails + var details = new UsageDetails { InputTokenCount = promptTokens, OutputTokenCount = completionTokens, TotalTokenCount = totalTokens ?? (promptTokens ?? 0) + (completionTokens ?? 0) }; + + // llama.cpp includes a sibling `timings` object with cache and throughput data. + // This is not part of the OpenAI spec — gracefully skip when absent. + if (root.TryGetProperty("timings", out var timings) && timings.ValueKind == JsonValueKind.Object) + { + ParseLlamaCppTimings(timings, details); + } + + return details; + } + + // llama.cpp's OpenAI-compatible endpoint returns a `timings` object alongside + // `usage`. Because M.E.AI's UsageDetails.AdditionalCounts is typed + // AdditionalPropertiesDictionary, floating-point timing values are encoded + // as integer scale factors: microseconds for latency, ×100 for tokens-per-second. + // These keys are the only canonical definition; consumers (LlmSessionActor) + // duplicate the strings they read and must stay in sync. + internal const string PromptUsKey = "prompt_us"; + internal const string PromptTokPerSecX100Key = "prompt_tok_per_sec_x100"; + internal const string PredictedUsKey = "predicted_us"; + internal const string PredictedTokPerSecX100Key = "predicted_tok_per_sec_x100"; + + /// + /// Reads llama.cpp-specific timing fields into . + /// cache_n maps to ; + /// throughput and latency fields go into + /// via integer-encoded keys (see the PromptUsKey/PredictedTokPerSecX100Key + /// constants above). Consumers decode by dividing out the scale factor. + /// + internal static void ParseLlamaCppTimings(JsonElement timings, UsageDetails details) + { + if (TryGetLong(timings, "cache_n", out var cacheN)) + details.CachedInputTokenCount = cacheN; + + if (TryGetDouble(timings, "prompt_ms", out var promptMs)) + Additional(details)[PromptUsKey] = (long)(promptMs * 1000); + + if (TryGetDouble(timings, "prompt_per_second", out var promptPerSec)) + Additional(details)[PromptTokPerSecX100Key] = (long)(promptPerSec * 100); + + if (TryGetDouble(timings, "predicted_ms", out var predictedMs)) + Additional(details)[PredictedUsKey] = (long)(predictedMs * 1000); + + if (TryGetDouble(timings, "predicted_per_second", out var predictedPerSec)) + Additional(details)[PredictedTokPerSecX100Key] = (long)(predictedPerSec * 100); + + static AdditionalPropertiesDictionary Additional(UsageDetails d) + => d.AdditionalCounts ??= new AdditionalPropertiesDictionary(); + } + + private static bool TryGetLong(JsonElement obj, string name, out long value) + { + if (obj.TryGetProperty(name, out var prop) + && prop.ValueKind == JsonValueKind.Number + && prop.TryGetInt64(out value)) + { + return true; + } + value = 0; + return false; + } + + private static bool TryGetDouble(JsonElement obj, string name, out double value) + { + if (obj.TryGetProperty(name, out var prop) + && prop.ValueKind == JsonValueKind.Number + && prop.TryGetDouble(out value)) + { + return true; + } + value = 0; + return false; } private static ChatFinishReason? ParseFinishReason(JsonElement choice)