diff --git a/.env.example b/.env.example index 3454599..c5071c7 100644 --- a/.env.example +++ b/.env.example @@ -36,6 +36,16 @@ Cache__AnalyticsExpirationMinutes=3 Cache__AnalyticsLocalExpirationSeconds=30 Cache__MaximumPayloadKilobytes=2048 +# OpenTelemetry 默认收集 HTTP、运行时和数据库指标；配置 OTLP 地址后才会外发。 +Observability__Enabled=true +Observability__ServiceName=jiaowu-api +Observability__SlowQueryThresholdMilliseconds=500 +# 默认不记录完整 SQL，避免日志或追踪系统接触业务数据。 +Observability__IncludeSqlText=false +Observability__MaximumSqlTextLength=2000 +# OTEL_EXPORTER_OTLP_ENDPOINT=https://otel-collector.example.edu.cn:4317 +# OTEL_EXPORTER_OTLP_HEADERS=Authorization=Bearer%20REPLACE_WITH_TOKEN + # 运维控制台备份目录必须位于持久化、仅服务账号可写的位置。 Operations__BackupDirectory=/var/lib/jiaowu/backups Operations__BackupWarningHours=24 diff --git a/README.md b/README.md index 4c57519..c2ff716 100644 --- a/README.md +++ b/README.md @@ -322,6 +322,34 @@ Redis 只作为可丢弃的查询缓存。连接失败时应用回源数据库 `allkeys-lfu` 淘汰策略，不启用持久化。`compose.app.example.yml` 不创建 Redis； 如需连接外部 Redis，在 `.env` 中配置上述连接串即可。 +### OpenTelemetry 与慢查询定位 + +应用已接入 OpenTelemetry 的 ASP.NET Core、HttpClient、.NET Runtime 指标，并通过 +`Jiaowu.Api.Database` ActivitySource 和 Meter 记录 EF Core 数据库命令。配置 +`OTEL_EXPORTER_OTLP_ENDPOINT` 后才启动 OpenTelemetry SDK 并向 OTLP Collector 外发； +未配置时不会创建无处消费的请求 Span，也不会尝试连接本地 Collector，结构化慢查询日志 +仍然有效。 + +```text +Observability__Enabled=true +Observability__ServiceName=jiaowu-api +Observability__SlowQueryThresholdMilliseconds=500 +OTEL_EXPORTER_OTLP_ENDPOINT=https://otel-collector.example.edu.cn:4317 +``` + +数据库指标包括 `jiaowu.db.command.duration`、`jiaowu.db.command.slow` 和 +`jiaowu.db.command.failed`。为关键 EF 查询添加 `TagWith("模块.查询名")` 后，日志和 +追踪会直接显示该稳定名称；无标签查询只显示操作类型和 SQL 模板哈希。默认 +`Observability__IncludeSqlText=false`，不会把 SQL、参数值或连接串发送到日志和追踪 +系统。仅在受控诊断窗口内临时启用完整 SQL 模板，并限制 Collector 权限与保留时间。 + +应用侧阈值用于关联接口、TraceId 和查询名称；生产 MySQL 还应由数据库管理员启用慢查询 +日志，并将 `long_query_time` 设为与应用阈值一致。先按查询哈希/标签汇总高频慢查询，再 +对脱敏后的 `SELECT` 在测试库或只读副本执行 `EXPLAIN ANALYZE`，根据实际扫描行数和循环 +次数决定是否补组合索引或改写投影。`EXPLAIN ANALYZE` 会真实执行语句，不能直接用于生产 +写操作。参考 [MySQL 慢查询日志](https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html) +和 [MySQL 8.4 EXPLAIN](https://dev.mysql.com/doc/refman/8.4/en/explain.html)。 + ### 后台任务与 RabbitMQ 自动排课、课表发布和补考自动生成使用数据库 Outbox 保存任务消息。创建业务任务与 diff --git a/src/Jiaowu.Api/Infrastructure/Observability/DatabaseCommandTelemetryInterceptor.cs b/src/Jiaowu.Api/Infrastructure/Observability/DatabaseCommandTelemetryInterceptor.cs new file mode 100644 index 0000000..8adc50a --- /dev/null +++ b/src/Jiaowu.Api/Infrastructure/Observability/DatabaseCommandTelemetryInterceptor.cs @@ -0,0 +1,281 @@ +using System.Data.Common; +using System.Diagnostics; +using System.Diagnostics.Metrics; +using System.Security.Cryptography; +using System.Text; +using Microsoft.EntityFrameworkCore.Diagnostics; + +namespace Jiaowu.Api.Infrastructure.Observability; + +public sealed class DatabaseCommandTelemetryInterceptor( + ObservabilityOptions options, + ILogger logger) + : DbCommandInterceptor +{ + public const string ActivitySourceName = "Jiaowu.Api.Database"; + public const string MeterName = "Jiaowu.Api.Database"; + + private static readonly ActivitySource ActivitySource = + new(ActivitySourceName); + private static readonly Meter Meter = new(MeterName); + private static readonly Histogram CommandDuration = + Meter.CreateHistogram( + "jiaowu.db.command.duration", + "ms", + "EF Core database command duration"); + private static readonly Counter SlowCommandCount = + Meter.CreateCounter( + "jiaowu.db.command.slow", + "{command}", + "EF Core commands exceeding the configured slow-query threshold"); + private static readonly Counter FailedCommandCount = + Meter.CreateCounter( + "jiaowu.db.command.failed", + "{command}", + "Failed EF Core database commands"); + + public override DbDataReader ReaderExecuted( + DbCommand command, + CommandExecutedEventData eventData, + DbDataReader result) + { + Observe(command, eventData.Duration, "reader"); + return result; + } + + public override ValueTask ReaderExecutedAsync( + DbCommand command, + CommandExecutedEventData eventData, + DbDataReader result, + CancellationToken cancellationToken = default) + { + Observe(command, eventData.Duration, "reader"); + return ValueTask.FromResult(result); + } + + public override int NonQueryExecuted( + DbCommand command, + CommandExecutedEventData eventData, + int result) + { + Observe(command, eventData.Duration, "nonquery"); + return result; + } + + public override ValueTask NonQueryExecutedAsync( + DbCommand command, + CommandExecutedEventData eventData, + int result, + CancellationToken cancellationToken = default) + { + Observe(command, eventData.Duration, "nonquery"); + return ValueTask.FromResult(result); + } + + public override object? ScalarExecuted( + DbCommand command, + CommandExecutedEventData eventData, + object? result) + { + Observe(command, eventData.Duration, "scalar"); + return result; + } + + public override ValueTask ScalarExecutedAsync( + DbCommand command, + CommandExecutedEventData eventData, + object? result, + CancellationToken cancellationToken = default) + { + Observe(command, eventData.Duration, "scalar"); + return ValueTask.FromResult(result); + } + + public override void CommandFailed( + DbCommand command, + CommandErrorEventData eventData) => + Observe( + command, + eventData.Duration, + "failed", + eventData.Exception.GetType().Name); + + public override Task CommandFailedAsync( + DbCommand command, + CommandErrorEventData eventData, + CancellationToken cancellationToken = default) + { + Observe( + command, + eventData.Duration, + "failed", + eventData.Exception.GetType().Name); + return Task.CompletedTask; + } + + public override void CommandCanceled( + DbCommand command, + CommandEndEventData eventData) => + Observe(command, eventData.Duration, "canceled", "canceled"); + + public override Task CommandCanceledAsync( + DbCommand command, + CommandEndEventData eventData, + CancellationToken cancellationToken = default) + { + Observe(command, eventData.Duration, "canceled", "canceled"); + return Task.CompletedTask; + } + + private void Observe( + DbCommand command, + TimeSpan duration, + string commandKind, + string? errorType = null) + { + if (!options.Enabled) return; + + var queryName = GetQueryName(command.CommandText); + var statementHash = GetStatementHash(command.CommandText); + var provider = GetProviderName(command); + var traceId = Activity.Current?.TraceId.ToString() ?? "none"; + var tags = new TagList + { + { "db.system.name", provider }, + { "db.operation.name", commandKind }, + { "db.query.name", queryName } + }; + if (errorType is not null) + tags.Add("error.type", errorType); + + var durationMilliseconds = duration.TotalMilliseconds; + CommandDuration.Record(durationMilliseconds, tags); + if (errorType is not null) + FailedCommandCount.Add(1, tags); + + using var activity = ActivitySource.StartActivity( + ActivityKind.Client, + Activity.Current?.Context ?? default, + startTime: DateTimeOffset.UtcNow - duration, + name: queryName); + if (activity is not null) + { + activity.SetTag("db.system.name", provider); + activity.SetTag("db.operation.name", commandKind); + activity.SetTag("db.query.name", queryName); + activity.SetTag("db.statement.hash", statementHash); + activity.SetTag( + "db.namespace", + EmptyToNull(command.Connection?.Database)); + if (options.IncludeSqlText) + { + activity.SetTag( + "db.query.text", + Truncate(command.CommandText, options.MaximumSqlTextLength)); + } + if (errorType is not null) + { + activity.SetTag("error.type", errorType); + activity.SetStatus(ActivityStatusCode.Error, errorType); + } + activity.SetEndTime(DateTime.UtcNow); + } + + if (errorType is not null) + { + logger.LogError( + "Database command failed after {DurationMs:F1} ms: " + + "{QueryName} ({CommandKind}, {Provider}, hash {StatementHash}, " + + "error {ErrorType}, trace {TraceId}).", + durationMilliseconds, + queryName, + commandKind, + provider, + statementHash, + errorType, + traceId); + return; + } + + if (durationMilliseconds < options.SlowQueryThresholdMilliseconds) + return; + + SlowCommandCount.Add(1, tags); + if (options.IncludeSqlText) + { + logger.LogWarning( + "Slow database command took {DurationMs:F1} ms: " + + "{QueryName} ({CommandKind}, {Provider}, hash {StatementHash}, " + + "trace {TraceId}). " + + "SQL template: {SqlTemplate}", + durationMilliseconds, + queryName, + commandKind, + provider, + statementHash, + traceId, + Truncate(command.CommandText, options.MaximumSqlTextLength)); + } + else + { + logger.LogWarning( + "Slow database command took {DurationMs:F1} ms: " + + "{QueryName} ({CommandKind}, {Provider}, hash {StatementHash}, " + + "trace {TraceId}).", + durationMilliseconds, + queryName, + commandKind, + provider, + statementHash, + traceId); + } + } + + internal static string GetQueryName(string commandText) + { + using var reader = new StringReader(commandText); + while (reader.ReadLine() is { } line) + { + var trimmed = line.Trim(); + if (trimmed.Length == 0) continue; + if (trimmed.StartsWith("-- ", StringComparison.Ordinal)) + return Truncate(trimmed[3..].Trim(), 120); + return $"{FirstToken(trimmed)}:{GetStatementHash(commandText)}"; + } + + return $"unknown:{GetStatementHash(commandText)}"; + } + + internal static string GetStatementHash(string commandText) + { + var bytes = SHA256.HashData(Encoding.UTF8.GetBytes(commandText)); + return Convert.ToHexString(bytes.AsSpan(0, 6)).ToLowerInvariant(); + } + + private static string FirstToken(string value) + { + var end = value.IndexOfAny([' ', '\t', '\r', '\n', '(']); + var token = end < 0 ? value : value[..end]; + return token.Length == 0 + ? "command" + : token.ToLowerInvariant(); + } + + private static string GetProviderName(DbCommand command) + { + var typeName = command.GetType().FullName ?? command.GetType().Name; + if (typeName.Contains("MySql", StringComparison.OrdinalIgnoreCase)) + return "mysql"; + if (typeName.Contains("Sqlite", StringComparison.OrdinalIgnoreCase)) + return "sqlite"; + return "other_sql"; + } + + private static string? EmptyToNull(string? value) => + string.IsNullOrWhiteSpace(value) ? null : value; + + private static string Truncate(string value, int maximumLength) => + value.Length <= maximumLength + ? value + : value[..maximumLength]; +} diff --git a/src/Jiaowu.Api/Infrastructure/Observability/ObservabilityOptions.cs b/src/Jiaowu.Api/Infrastructure/Observability/ObservabilityOptions.cs new file mode 100644 index 0000000..aee799f --- /dev/null +++ b/src/Jiaowu.Api/Infrastructure/Observability/ObservabilityOptions.cs @@ -0,0 +1,12 @@ +namespace Jiaowu.Api.Infrastructure.Observability; + +public sealed class ObservabilityOptions +{ + public const string SectionName = "Observability"; + + public bool Enabled { get; set; } = true; + public string ServiceName { get; set; } = "jiaowu-api"; + public int SlowQueryThresholdMilliseconds { get; set; } = 500; + public bool IncludeSqlText { get; set; } + public int MaximumSqlTextLength { get; set; } = 2000; +} diff --git a/src/Jiaowu.Api/Infrastructure/Timetables/TimetableDataService.cs b/src/Jiaowu.Api/Infrastructure/Timetables/TimetableDataService.cs index 7ff5312..4771ed0 100644 --- a/src/Jiaowu.Api/Infrastructure/Timetables/TimetableDataService.cs +++ b/src/Jiaowu.Api/Infrastructure/Timetables/TimetableDataService.cs @@ -28,6 +28,7 @@ public sealed class TimetableDataService(AppDbContext db) allowUnpublishedPlan, cancellationToken); var slots = await db.ScheduleTimeSlots.AsNoTracking() + .TagWith("Timetable.LoadTimeSlots") .Where(x => x.AcademicTermId == term.Id && x.IsEnabled) .OrderBy(x => x.PeriodNumber) .Select(x => new TimetableSlotDto( @@ -76,6 +77,7 @@ public sealed class TimetableDataService(AppDbContext db) } entries = await source + .TagWith("Timetable.LoadScheduleEntries") .OrderBy(x => x.DayOfWeek) .ThenBy(x => x.StartPeriod) .ThenBy(x => x.TeachingTask!.Course!.Code) @@ -283,6 +285,7 @@ public sealed class TimetableDataService(AppDbContext db) } return await source + .TagWith("Timetable.LoadFlexibleCourses") .OrderBy(x => x.Course!.Code) .ThenBy(x => x.TaskNumber) .Select(x => new FlexibleCourseDto( @@ -326,6 +329,7 @@ public sealed class TimetableDataService(AppDbContext db) legacyQuery, resourceType, resourceId, studentId); var legacySessions = await legacyQuery + .TagWith("Timetable.LoadLegacyExamEntries") .OrderBy(x => x.ExamDate) .ThenBy(x => x.StartPeriod) .Select(x => new ExamSessionProjection( @@ -416,6 +420,7 @@ public sealed class TimetableDataService(AppDbContext db) db, studentId.Value); var sessions = await db.ExperimentSessions.AsNoTracking() + .TagWith("Timetable.LoadExperimentEntries") .AsSplitQuery() .Where(x => x.ExperimentProject!.TeachingTask!.AcademicTermId == term.Id && diff --git a/src/Jiaowu.Api/Jiaowu.Api.csproj b/src/Jiaowu.Api/Jiaowu.Api.csproj index 32bd256..3a8e64c 100644 --- a/src/Jiaowu.Api/Jiaowu.Api.csproj +++ b/src/Jiaowu.Api/Jiaowu.Api.csproj @@ -31,6 +31,11 @@ + + + + + diff --git a/src/Jiaowu.Api/Program.cs b/src/Jiaowu.Api/Program.cs index 5e18551..d7858c8 100644 --- a/src/Jiaowu.Api/Program.cs +++ b/src/Jiaowu.Api/Program.cs @@ -7,6 +7,7 @@ using Jiaowu.Api.Infrastructure.Auth; using Jiaowu.Api.Infrastructure.Caching; using Jiaowu.Api.Infrastructure.Exams; using Jiaowu.Api.Infrastructure.Middleware; +using Jiaowu.Api.Infrastructure.Observability; using Jiaowu.Api.Infrastructure.OfficialDocuments; using Jiaowu.Api.Infrastructure.Operations; using Jiaowu.Api.Infrastructure.Persistence; @@ -19,6 +20,9 @@ using Microsoft.EntityFrameworkCore; using Microsoft.Extensions.Caching.Distributed; using Microsoft.IdentityModel.Tokens; using Microsoft.OpenApi.Models; +using OpenTelemetry.Metrics; +using OpenTelemetry.Resources; +using OpenTelemetry.Trace; using System.Threading.RateLimiting; EnvironmentFile.Load(); @@ -78,6 +82,9 @@ var backgroundJobOptions = builder.Configuration var operationsOptions = builder.Configuration .GetSection(OperationsOptions.SectionName) .Get() ?? new OperationsOptions(); +var observabilityOptions = builder.Configuration + .GetSection(ObservabilityOptions.SectionName) + .Get() ?? new ObservabilityOptions(); var rabbitMqOptions = builder.Configuration .GetSection(RabbitMqOptions.SectionName) .Get() ?? new RabbitMqOptions(); @@ -110,6 +117,24 @@ if (databaseOptions.CommandTimeoutSeconds is < 5 or > 300) "Database:CommandTimeoutSeconds 必须在 5 到 300 秒之间。"); } +if (string.IsNullOrWhiteSpace(observabilityOptions.ServiceName) || + observabilityOptions.ServiceName.Length > 100 || + observabilityOptions.SlowQueryThresholdMilliseconds is < 1 or > 60000 || + observabilityOptions.MaximumSqlTextLength is < 256 or > 20000) +{ + throw new InvalidOperationException( + "Observability 服务名、慢查询阈值或 SQL 文本长度超出允许范围。"); +} + +var otlpEndpoint = builder.Configuration["OTEL_EXPORTER_OTLP_ENDPOINT"]; +if (!string.IsNullOrWhiteSpace(otlpEndpoint) && + (!Uri.TryCreate(otlpEndpoint, UriKind.Absolute, out var parsedOtlpEndpoint) || + parsedOtlpEndpoint.Scheme is not ("http" or "https"))) +{ + throw new InvalidOperationException( + "OTEL_EXPORTER_OTLP_ENDPOINT 必须是有效的 HTTP 或 HTTPS 绝对地址。"); +} + if (cacheOptions.ReferenceExpirationMinutes is < 1 or > 1440 || cacheOptions.TimetableExpirationMinutes is < 1 or > 1440 || cacheOptions.AnalyticsExpirationMinutes is < 1 or > 1440 || @@ -193,11 +218,16 @@ builder.Services.AddSingleton(cacheOptions); builder.Services.AddSingleton(officialDocumentOptions); builder.Services.AddSingleton(backgroundJobOptions); builder.Services.AddSingleton(operationsOptions); +builder.Services.AddSingleton(observabilityOptions); builder.Services.AddSingleton(rabbitMqOptions); +builder.Services.AddSingleton(); builder.Services.Configure( builder.Configuration.GetSection(OfficialDocumentOptions.SectionName)); -builder.Services.AddDbContextPool(options => +builder.Services.AddDbContextPool((services, options) => { + options.AddInterceptors( + services.GetRequiredService()); + if (databaseOptions.Provider.Equals("SQLite", StringComparison.OrdinalIgnoreCase)) { var sqliteConnectionString = builder.Configuration.GetConnectionString("SQLite") @@ -240,6 +270,28 @@ builder.Services.AddDbContextPool(options => }); }); +if (observabilityOptions.Enabled && + !string.IsNullOrWhiteSpace(otlpEndpoint)) +{ + builder.Services + .AddOpenTelemetry() + .ConfigureResource(resource => + resource.AddService(observabilityOptions.ServiceName)) + .WithMetrics(metrics => metrics + .AddAspNetCoreInstrumentation() + .AddHttpClientInstrumentation() + .AddRuntimeInstrumentation() + .AddMeter(DatabaseCommandTelemetryInterceptor.MeterName)) + .WithTracing(tracing => tracing + .AddAspNetCoreInstrumentation(options => + options.Filter = context => + !context.Request.Path.StartsWithSegments("/health/live")) + .AddHttpClientInstrumentation() + .AddSource(DatabaseCommandTelemetryInterceptor.ActivitySourceName)) + .WithMetrics(metrics => metrics.AddOtlpExporter()) + .WithTracing(tracing => tracing.AddOtlpExporter()); +} + var redisConnectionString = builder.Configuration.GetConnectionString("Redis"); if (cacheOptions.Enabled && !string.IsNullOrWhiteSpace(redisConnectionString)) { diff --git a/src/Jiaowu.Api/appsettings.json b/src/Jiaowu.Api/appsettings.json index 35d9a83..d25ac0d 100644 --- a/src/Jiaowu.Api/appsettings.json +++ b/src/Jiaowu.Api/appsettings.json @@ -19,6 +19,13 @@ "AnalyticsLocalExpirationSeconds": 30, "MaximumPayloadKilobytes": 2048 }, + "Observability": { + "Enabled": true, + "ServiceName": "jiaowu-api", + "SlowQueryThresholdMilliseconds": 500, + "IncludeSqlText": false, + "MaximumSqlTextLength": 2000 + }, "Operations": { "BackupDirectory": "data/backups", "BackupWarningHours": 24, diff --git a/tests/Jiaowu.Api.Tests/DatabaseCommandTelemetryInterceptorTests.cs b/tests/Jiaowu.Api.Tests/DatabaseCommandTelemetryInterceptorTests.cs new file mode 100644 index 0000000..7b89f29 --- /dev/null +++ b/tests/Jiaowu.Api.Tests/DatabaseCommandTelemetryInterceptorTests.cs @@ -0,0 +1,88 @@ +using System.Diagnostics.Metrics; +using Jiaowu.Api.Infrastructure.Observability; +using Jiaowu.Api.Infrastructure.Persistence; +using Microsoft.Data.Sqlite; +using Microsoft.EntityFrameworkCore; +using Microsoft.Extensions.Logging.Abstractions; + +namespace Jiaowu.Api.Tests; + +public sealed class DatabaseCommandTelemetryInterceptorTests +{ + [Fact] + public void Query_name_uses_tag_without_exposing_statement_text() + { + const string sql = + "-- Timetable.LoadMixedExamEntries\n" + + "SELECT * FROM ExamRooms WHERE SecretValue = @p0"; + + var queryName = + DatabaseCommandTelemetryInterceptor.GetQueryName(sql); + + Assert.Equal("Timetable.LoadMixedExamEntries", queryName); + Assert.DoesNotContain("SecretValue", queryName); + Assert.DoesNotContain("@p0", queryName); + } + + [Fact] + public void Untagged_query_name_is_stable_hash_not_statement_text() + { + const string sql = + "SELECT * FROM Students WHERE StudentNumber = @studentNumber"; + + var first = DatabaseCommandTelemetryInterceptor.GetQueryName(sql); + var second = DatabaseCommandTelemetryInterceptor.GetQueryName(sql); + + Assert.Equal(first, second); + Assert.StartsWith("select:", first); + Assert.DoesNotContain("Students", first); + Assert.DoesNotContain("StudentNumber", first); + } + + [Fact] + public async Task Ef_command_records_duration_metric() + { + await using var connection = + new SqliteConnection("Data Source=:memory:"); + await connection.OpenAsync(); + + var setupOptions = new DbContextOptionsBuilder() + .UseSqlite(connection) + .Options; + await using (var setupDb = new AppDbContext(setupOptions)) + await setupDb.Database.EnsureCreatedAsync(); + + double? recordedDuration = null; + using var listener = new MeterListener + { + InstrumentPublished = (instrument, meterListener) => + { + if (instrument.Meter.Name == + DatabaseCommandTelemetryInterceptor.MeterName && + instrument.Name == "jiaowu.db.command.duration") + { + meterListener.EnableMeasurementEvents(instrument); + } + } + }; + listener.SetMeasurementEventCallback( + (_, measurement, _, _) => recordedDuration = measurement); + listener.Start(); + + var interceptor = new DatabaseCommandTelemetryInterceptor( + new ObservabilityOptions(), + NullLogger.Instance); + var queryOptions = new DbContextOptionsBuilder() + .UseSqlite(connection) + .AddInterceptors(interceptor) + .Options; + await using var db = new AppDbContext(queryOptions); + + await db.AcademicTerms + .TagWith("Observability.Tests.TermCount") + .CountAsync(); + + Assert.NotNull(recordedDuration); + Assert.True(recordedDuration >= 0); + } +}