diff --git a/DEVELOPER_GUIDE.md b/DEVELOPER_GUIDE.md index 92188ccd62..2dfa331f38 100644 --- a/DEVELOPER_GUIDE.md +++ b/DEVELOPER_GUIDE.md @@ -111,6 +111,12 @@ The lock files for projects with zero direct `PackageReference` entries (e.g. `t | DTOs | `Models/FileRecord.cs`, `Models/ChunkRecord.cs`, `Models/SymbolRecord.cs`, `Models/ReferenceRecord.cs` | Records shared by indexing, storage, query, and MCP layers. | | Tests | `tests/CodeIndex.Tests/*Tests.cs`, `TestProjectHelper.cs`, `TestConsoleLock.cs` | Focused unit/integration coverage for chunking, extraction, DB reads/writes, CLI behavior, MCP behavior, git helpers, and shared test harness utilities. | +### Observability + +CodeIndex exposes an opt-in `ActivitySource` named `CodeIndex`. MCP JSON-RPC frames create `mcp.request` server spans and SQLite commands routed through tracked database helpers create `db.query` spans. MCP callers can pass W3C trace context as `params._meta.traceparent`; when present, the MCP span uses that trace as its parent. No exporter dependency is bundled, so spans are emitted only when the host process installs an OpenTelemetry/Diagnostics listener. + +Set `CDIDX_SLOW_QUERY_MS=` to write slow SQLite command diagnostics to stderr. Query commands also accept `--profile` for a JSON profile block and `--slow-query-ms ` for command-scoped profiling. + ### Indexing pipeline ``` diff --git a/changelog.d/unreleased/1679.added.md b/changelog.d/unreleased/1679.added.md new file mode 100644 index 0000000000..2fc1f9f6d3 --- /dev/null +++ b/changelog.d/unreleased/1679.added.md @@ -0,0 +1,18 @@ +--- +category: added +issues: + - 1679 +affected: + - src/CodeIndex/Telemetry/CodeIndexTelemetry.cs + - src/CodeIndex/Mcp/McpServer.cs + - src/CodeIndex/Database/DbDebug.cs + - DEVELOPER_GUIDE.md +--- + +## English + +- **Added opt-in ActivitySource tracing for MCP and SQLite work (#1679)** — CodeIndex now exposes a `CodeIndex` activity source, creates MCP request and SQLite query spans, and honors MCP `params._meta.traceparent` as the parent trace context. + +## 日本語 + +- **MCP と SQLite 処理向けの opt-in ActivitySource tracing を追加しました (#1679)** — CodeIndex は `CodeIndex` activity source を公開し、MCP request / SQLite query span を作成し、MCP `params._meta.traceparent` を親 trace context として扱うようになりました。 diff --git a/changelog.d/unreleased/1786.fixed.md b/changelog.d/unreleased/1786.fixed.md new file mode 100644 index 0000000000..47b3f1a05b --- /dev/null +++ b/changelog.d/unreleased/1786.fixed.md @@ -0,0 +1,17 @@ +--- +category: fixed +issues: + - 1786 +affected: + - src/CodeIndex/Cli/QueryCommandRunner.cs + - src/CodeIndex/Database/DbDebug.cs + - DEVELOPER_GUIDE.md +--- + +## English + +- **Documented query profiling output for slow query diagnosis (#1786)** — query commands expose `--profile` and `--slow-query-ms` profiling so operators can inspect query timing and SQL diagnostics without patching the source. + +## 日本語 + +- **遅い query 診断向けの query profiling output を明記しました (#1786)** — query command は `--profile` と `--slow-query-ms` による profiling を提供し、ソース修正なしで query timing と SQL diagnostics を確認できるようになりました。 diff --git a/changelog.d/unreleased/1789.fixed.md b/changelog.d/unreleased/1789.fixed.md new file mode 100644 index 0000000000..19bfd6342c --- /dev/null +++ b/changelog.d/unreleased/1789.fixed.md @@ -0,0 +1,16 @@ +--- +category: fixed +issues: + - 1789 +affected: + - src/CodeIndex/Database/DbDebug.cs + - DEVELOPER_GUIDE.md +--- + +## English + +- **Added an environment-controlled SQLite slow-query log (#1789)** — `CDIDX_SLOW_QUERY_MS` now emits slow tracked SQLite commands to stderr without requiring source patches. + +## 日本語 + +- **環境変数で制御できる SQLite slow-query log を追加しました (#1789)** — `CDIDX_SLOW_QUERY_MS` により、ソース修正なしで遅い tracked SQLite command を stderr に出力できるようになりました。 diff --git a/src/CodeIndex/Database/DbDebug.cs b/src/CodeIndex/Database/DbDebug.cs index c582151851..562982272a 100644 --- a/src/CodeIndex/Database/DbDebug.cs +++ b/src/CodeIndex/Database/DbDebug.cs @@ -1,6 +1,7 @@ using System.Security.Cryptography; using System.Text; using System.Diagnostics; +using CodeIndex; using CodeIndex.Cli; using Microsoft.Data.Sqlite; @@ -187,10 +188,28 @@ internal static void TrackCommand(SqliteCommand cmd) internal static SqliteDataReader ExecuteReader(SqliteCommand cmd) { + using var activity = CodeIndexTelemetry.ActivitySource.StartActivity("db.query"); + activity?.SetTag("db.system", "sqlite"); + activity?.SetTag("db.operation", GetStatementOperation(cmd.CommandText)); + activity?.SetTag("db.statement_hash", ShortHash(cmd.CommandText ?? string.Empty)); + if (!IsProfileEnabled) - return cmd.ExecuteReader(); + { + var threshold = ReadSlowQueryThresholdFromEnvironment(); + var executeStopwatch = Stopwatch.StartNew(); + var unprofiledReader = cmd.ExecuteReader(); + executeStopwatch.Stop(); + activity?.SetTag("db.elapsed_ms", executeStopwatch.Elapsed.TotalMilliseconds); + if (threshold.HasValue) + { + var slowEntry = new QueryProfileEntry(cmd.CommandText ?? string.Empty, []); + slowEntry.AddElapsed(executeStopwatch.Elapsed); + s_activeProfiles.Add(unprofiledReader, new ActiveProfile(slowEntry, threshold, LogSlowQueryToStderr: true, cmd)); + } + return unprofiledReader; + } - var entry = new QueryProfileEntry(cmd.CommandText, CaptureQueryPlan(cmd)); + var entry = new QueryProfileEntry(cmd.CommandText ?? string.Empty, CaptureQueryPlan(cmd)); _profileEntries!.Add(entry); var sw = Stopwatch.StartNew(); @@ -198,6 +217,7 @@ internal static SqliteDataReader ExecuteReader(SqliteCommand cmd) sw.Stop(); entry.AddElapsed(sw.Elapsed); + activity?.SetTag("db.elapsed_ms", sw.Elapsed.TotalMilliseconds); entry.MarkCompletedIfSlow(_slowQueryThresholdMs); s_activeProfiles.Add(reader, new ActiveProfile(entry)); return reader; @@ -211,9 +231,43 @@ internal static void TrackReadElapsed(SqliteDataReader reader, TimeSpan elapsed, active.Entry.AddElapsed(elapsed); if (rowRead) active.Entry.IncrementRows(); + if (active is { LogSlowQueryToStderr: true, SlowQueryThresholdMs: { } threshold } && + active.Entry.ElapsedMs >= threshold && + active.TryMarkSlowLogged()) + { + WriteSlowQueryToStderr(active.Command!, active.Entry.ElapsedMs, active.Entry.RowsScanned); + } active.Entry.MarkCompletedIfSlow(_slowQueryThresholdMs); } + private static long? ReadSlowQueryThresholdFromEnvironment() + { + var raw = Environment.GetEnvironmentVariable("CDIDX_SLOW_QUERY_MS"); + if (string.IsNullOrWhiteSpace(raw)) + return null; + return long.TryParse(raw, out var value) && value >= 0 ? value : null; + } + + private static string GetStatementOperation(string? sql) + { + if (string.IsNullOrWhiteSpace(sql)) + return "unknown"; + var trimmed = sql.TrimStart(); + var end = 0; + while (end < trimmed.Length && !char.IsWhiteSpace(trimmed[end]) && trimmed[end] != '(') + end++; + return end == 0 ? "unknown" : trimmed[..end].ToUpperInvariant(); + } + + private static void WriteSlowQueryToStderr(SqliteCommand cmd, double elapsedMs, int? rowsRead) + { + var sql = (cmd.CommandText ?? string.Empty).ReplaceLineEndings(" "); + if (sql.Length > 200) + sql = sql[..200] + "..."; + var rowText = rowsRead.HasValue ? $" rows={rowsRead.Value}" : string.Empty; + Console.Error.WriteLine($"[cdidx] slow_query elapsed_ms={elapsedMs:0.###}{rowText} sql={sql}"); + } + private static List CaptureQueryPlan(SqliteCommand source) { var rows = new List(); @@ -439,4 +493,18 @@ internal void MarkCompletedIfSlow(long? slowQueryThresholdMs) public sealed record QueryPlanRow(int Id, int Parent, int NotUsed, string Detail); -internal sealed record ActiveProfile(QueryProfileEntry Entry); +internal sealed class ActiveProfile( + QueryProfileEntry entry, + long? slowQueryThresholdMs = null, + bool LogSlowQueryToStderr = false, + SqliteCommand? command = null) +{ + private int _slowLogged; + + public QueryProfileEntry Entry { get; } = entry; + public long? SlowQueryThresholdMs { get; } = slowQueryThresholdMs; + public bool LogSlowQueryToStderr { get; } = LogSlowQueryToStderr; + public SqliteCommand? Command { get; } = command; + + public bool TryMarkSlowLogged() => Interlocked.Exchange(ref _slowLogged, 1) == 0; +} diff --git a/src/CodeIndex/Mcp/McpServer.cs b/src/CodeIndex/Mcp/McpServer.cs index f1fedbf032..8e770d9010 100644 --- a/src/CodeIndex/Mcp/McpServer.cs +++ b/src/CodeIndex/Mcp/McpServer.cs @@ -818,7 +818,9 @@ internal static string BuildInvalidUtf8ErrorLog(string detail) ExtractResponseId(request, out responseHasId, out responseId); if (responseHasId && CurrentCorrelationContext.Value is null) frameCorrelationScope = BeginRequestCorrelation(responseId); + using var activity = StartMcpActivity(request, responseId); var response = await HandleMessageAsync(request, isolateRequestDb: true).ConfigureAwait(false); + activity?.SetTag("rpc.result", response is null ? "notification" : "response"); return response != null ? SerializeResponseOrFallback(response, responseHasId, responseId) : null; } catch (JsonException ex) @@ -855,6 +857,39 @@ internal static string BuildInvalidUtf8ErrorLog(string detail) } } + private static Activity? StartMcpActivity(JsonNode request, JsonNode? responseId) + { + var method = request is JsonObject obj ? TryGetStringMember(obj, "method") : null; + var traceParent = TryGetMcpTraceParent(request); + ActivityContext parentContext = default; + if (traceParent != null) + ActivityContext.TryParse(traceParent, traceState: null, out parentContext); + + var activity = parentContext != default + ? CodeIndexTelemetry.ActivitySource.StartActivity("mcp.request", ActivityKind.Server, parentContext) + : CodeIndexTelemetry.ActivitySource.StartActivity("mcp.request", ActivityKind.Server); + activity?.SetTag("rpc.system", "jsonrpc"); + activity?.SetTag("rpc.service", "mcp"); + if (!string.IsNullOrWhiteSpace(method)) + activity?.SetTag("rpc.method", method); + if (responseId != null) + activity?.SetTag("rpc.request_id", responseId.ToJsonString()); + return activity; + } + + private static string? TryGetMcpTraceParent(JsonNode request) + { + if (request is not JsonObject obj || + obj["params"] is not JsonObject parameters || + parameters["_meta"] is not JsonObject meta) + return null; + + if (meta["traceparent"] is not JsonValue valueNode || + !valueNode.TryGetValue(out var value)) + return null; + return string.IsNullOrWhiteSpace(value) ? null : value; + } + private string SerializeResponseOrFallback(JsonNode response, bool hasId, JsonNode? id) { try diff --git a/src/CodeIndex/Telemetry/CodeIndexTelemetry.cs b/src/CodeIndex/Telemetry/CodeIndexTelemetry.cs new file mode 100644 index 0000000000..d881a98c55 --- /dev/null +++ b/src/CodeIndex/Telemetry/CodeIndexTelemetry.cs @@ -0,0 +1,10 @@ +using System.Diagnostics; + +namespace CodeIndex; + +public static class CodeIndexTelemetry +{ + public const string ActivitySourceName = "CodeIndex"; + + public static readonly ActivitySource ActivitySource = new(ActivitySourceName); +} diff --git a/tests/CodeIndex.Tests/DbDebugTests.cs b/tests/CodeIndex.Tests/DbDebugTests.cs index cca6361463..08e7a6eeab 100644 --- a/tests/CodeIndex.Tests/DbDebugTests.cs +++ b/tests/CodeIndex.Tests/DbDebugTests.cs @@ -1,5 +1,6 @@ using CodeIndex.Database; using Microsoft.Data.Sqlite; +using System.Diagnostics; namespace CodeIndex.Tests; @@ -9,6 +10,38 @@ public class DbDebugTests private static string CaptureStderr(Action action) => ConsoleCapture.CaptureError(action); + [Fact] + public void ExecuteTrackedReader_EmitsActivityAndSlowQueryLog() + { + using var env = EnvironmentVariableScope.Capture("CDIDX_SLOW_QUERY_MS"); + env.Set("CDIDX_SLOW_QUERY_MS", "0"); + var stopped = new List(); + using var listener = new ActivityListener + { + ShouldListenTo = source => source.Name == CodeIndex.CodeIndexTelemetry.ActivitySourceName, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllData, + ActivityStopped = activity => stopped.Add(activity), + }; + ActivitySource.AddActivityListener(listener); + + using var conn = new SqliteConnection("Data Source=:memory:"); + conn.Open(); + using var cmd = conn.CreateCommand(); + cmd.CommandText = "SELECT 1"; + + var stderr = CaptureStderr(() => + { + using var reader = cmd.ExecuteTrackedReader(); + Assert.True(reader.TrackedRead()); + Assert.Equal(1, reader.GetInt32(0)); + }); + + Assert.Contains("slow_query", stderr); + var activity = Assert.Single(stopped.Where(activity => activity.OperationName == "db.query")); + Assert.Equal("sqlite", activity.GetTagItem("db.system")); + Assert.Equal("SELECT", activity.GetTagItem("db.operation")); + } + [Fact] public void DumpToStderr_NoOp_WhenDisabled() { diff --git a/tests/CodeIndex.Tests/McpServerTests.cs b/tests/CodeIndex.Tests/McpServerTests.cs index 79286769e6..5bea9a558b 100644 --- a/tests/CodeIndex.Tests/McpServerTests.cs +++ b/tests/CodeIndex.Tests/McpServerTests.cs @@ -1,6 +1,7 @@ using System.Text; using System.Text.Json.Nodes; using System.Text.Json; +using System.Diagnostics; using CodeIndex.Cli; using CodeIndex.Database; using CodeIndex.Indexer; @@ -81,6 +82,68 @@ public McpServerTests() _server = new McpServer(_dbPath, ConsoleUi.LoadVersion()); } + [Fact] + public void ProcessFrame_UsesTraceParentFromMetaAsActivityParent() + { + var parentTraceId = ActivityTraceId.CreateRandom(); + var parentSpanId = ActivitySpanId.CreateRandom(); + var traceParent = $"00-{parentTraceId}-{parentSpanId}-01"; + var stopped = new List(); + using var listener = new ActivityListener + { + ShouldListenTo = source => source.Name == CodeIndex.CodeIndexTelemetry.ActivitySourceName, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllData, + ActivityStopped = activity => stopped.Add(activity), + }; + ActivitySource.AddActivityListener(listener); + + var request = new JsonObject + { + ["jsonrpc"] = "2.0", + ["id"] = 123, + ["method"] = "tools/list", + ["params"] = new JsonObject + { + ["_meta"] = new JsonObject + { + ["traceparent"] = traceParent, + }, + }, + }; + + var response = _server.ProcessFrame(request.ToJsonString()); + + Assert.NotNull(response); + var activity = Assert.Single(stopped.Where(activity => activity.OperationName == "mcp.request")); + Assert.Equal(parentTraceId, activity.TraceId); + Assert.Equal(parentSpanId, activity.ParentSpanId); + Assert.Equal("tools/list", activity.GetTagItem("rpc.method")); + } + + [Fact] + public void ProcessFrame_IgnoresNonStringTraceParent() + { + var request = new JsonObject + { + ["jsonrpc"] = "2.0", + ["id"] = 123, + ["method"] = "tools/list", + ["params"] = new JsonObject + { + ["_meta"] = new JsonObject + { + ["traceparent"] = 42, + }, + }, + }; + + var response = _server.ProcessFrame(request.ToJsonString()); + + Assert.NotNull(response); + using var document = JsonDocument.Parse(response); + Assert.True(document.RootElement.TryGetProperty("result", out _)); + } + private void InsertIndexedFile(string path, string lang, string content, bool generated = false) { var normalized = content.Replace("\r\n", "\n");