From 292d0294592578249626ffa042615691fb486b09 Mon Sep 17 00:00:00 2001 From: biss Date: Tue, 11 Aug 2026 11:32:50 +0800 Subject: [PATCH] =?UTF-8?q?=E5=BC=83=E7=94=A8=20OpenTelemetry=EF=BC=8C?= =?UTF-8?q?=E5=B9=B6=E5=BB=BA=E7=AB=8B=E6=97=A5=E5=BF=97=E9=A9=B1=E5=8A=A8?= =?UTF-8?q?=E7=9A=84=E7=9C=9F=E5=AE=9E=E6=85=A2=E6=8E=A5=E5=8F=A3=E5=9F=BA?= =?UTF-8?q?=E7=BA=BF?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .env.example | 6 +- README.md | 35 ++++---- .../SlowRequestLoggingMiddleware.cs | 49 +++++++++++ .../DatabaseCommandTelemetryInterceptor.cs | 83 ++----------------- .../Observability/ObservabilityOptions.cs | 2 + src/Jiaowu.Api/Jiaowu.Api.csproj | 5 -- src/Jiaowu.Api/Program.cs | 37 +-------- src/Jiaowu.Api/appsettings.json | 2 + ...atabaseCommandTelemetryInterceptorTests.cs | 25 +----- 9 files changed, 87 insertions(+), 157 deletions(-) create mode 100644 src/Jiaowu.Api/Infrastructure/Middleware/SlowRequestLoggingMiddleware.cs diff --git a/.env.example b/.env.example index a5b55ca..721fc35 100644 --- a/.env.example +++ b/.env.example @@ -44,15 +44,15 @@ Cache__AnalyticsExpirationMinutes=3 Cache__AnalyticsLocalExpirationSeconds=30 Cache__MaximumPayloadKilobytes=2048 -# OpenTelemetry 默认收集 HTTP、运行时和数据库指标；配置 OTLP 地址后才会外发。 +# 应用日志建立接口与慢 SQL 基线；日志系统可按 DurationMs、RequestId、QueryName 聚合。 Observability__Enabled=true Observability__ServiceName=jiaowu-api +Observability__LogAllApiRequests=true +Observability__SlowRequestThresholdMilliseconds=1000 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 # 系统内“运维与审计 → 系统性能”从 Prometheus 只读查询汇总指标。 PerformanceReporting__Enabled=false diff --git a/README.md b/README.md index f48291c..e8d06ad 100644 --- a/README.md +++ b/README.md @@ -366,39 +366,36 @@ 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，结构化慢查询日志 -仍然有效。 +应用不依赖 OpenTelemetry。启用 `Observability` 后，会为每个 `/api` 请求写入结构化的 +方法、路径、终结点、状态码、耗时和请求号；超过阈值或返回 5xx 的请求会提升为 Warning。 +EF Core 数据库命令超过阈值时同样写入查询名称、SQL 模板哈希、数据库类型、耗时和相同的 +请求号。用日志平台按 `DurationMs` 聚合即可得到真实的 P50/P95/P99 和慢接口排行。 ```text Observability__Enabled=true Observability__ServiceName=jiaowu-api +Observability__LogAllApiRequests=true +Observability__SlowRequestThresholdMilliseconds=1000 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 权限与保留时间。 +为关键 EF 查询添加 `TagWith("模块.查询名")` 后，慢 SQL 日志会直接显示稳定名称；无标签 +查询只显示操作类型和 SQL 模板哈希。默认 `Observability__IncludeSqlText=false`，不会把 +SQL 模板、参数值或连接串写入日志。仅在受控诊断窗口内临时启用 SQL 模板记录，并限制日志 +访问权限与保留时间。 -应用侧阈值用于关联接口、TraceId 和查询名称；生产 MySQL 还应由数据库管理员启用慢查询 +应用侧请求号用于关联接口和查询名称；生产 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)。 -OpenTelemetry Collector 将指标写入 Prometheus 后，超级管理员可直接在“组织与权限 → -运维与审计 → 系统性能”查看请求量、5xx 比例、HTTP/数据库 P95、慢查询趋势，以及最慢 -接口和数据库查询排行。报表由 API 使用固定 PromQL 只读查询 Prometheus，浏览器不会 -接触 Prometheus 地址或令牌；结果默认缓存 30 秒。原始 Trace 和更长时间范围仍建议在 -Grafana 中下钻，配置其地址后页面会显示跳转入口。 +如部署环境另行提供 Prometheus 兼容指标源，超级管理员仍可在“组织与权限 → 运维与审计 → +系统性能”查看其汇总数据。该页面只读查询外部指标源，浏览器不会接触其地址或令牌；结果 +默认缓存 30 秒。应用本身不会再通过 OpenTelemetry 向该指标源写入数据。 ```text PerformanceReporting__Enabled=true @@ -471,7 +468,7 @@ Outbox 租约恢复改为按维护周期执行，避免积压发布时每条消 消息默认保留 14 天并按每批 500 条清理，可使用 `CompletedRetentionDays`、 `MaintenanceIntervalSeconds` 和 `CleanupBatchSize` 调整。应用暴露 `Jiaowu.BackgroundJobs` Meter，其中包含发布量、处理量、发布耗时、处理耗时和清理量， -可接入现有 OpenTelemetry/运行时指标采集器。MySQL 或 RabbitMQ 暂时不可用时，未完成 +可由现有日志平台或运行时指标采集器汇总。MySQL 或 RabbitMQ 暂时不可用时，未完成 消息会根据 Outbox 状态和租约继续补投。迁移服务应先应用 `BackgroundJobOutbox` 数据库迁移，再启动应用实例。 diff --git a/src/Jiaowu.Api/Infrastructure/Middleware/SlowRequestLoggingMiddleware.cs b/src/Jiaowu.Api/Infrastructure/Middleware/SlowRequestLoggingMiddleware.cs new file mode 100644 index 0000000..126d34d --- /dev/null +++ b/src/Jiaowu.Api/Infrastructure/Middleware/SlowRequestLoggingMiddleware.cs @@ -0,0 +1,49 @@ +using System.Diagnostics; +using Jiaowu.Api.Infrastructure.Observability; + +namespace Jiaowu.Api.Infrastructure.Middleware; + +public sealed class SlowRequestLoggingMiddleware( + RequestDelegate next, + ObservabilityOptions options, + ILogger logger) +{ + public async Task InvokeAsync(HttpContext context) + { + if (!options.Enabled || + !context.Request.Path.StartsWithSegments("/api")) + { + await next(context); + return; + } + + var startedAt = Stopwatch.GetTimestamp(); + await next(context); + + var durationMilliseconds = Stopwatch.GetElapsedTime(startedAt).TotalMilliseconds; + var endpoint = context.GetEndpoint()?.DisplayName ?? context.Request.Path.Value ?? "/api"; + if (durationMilliseconds >= options.SlowRequestThresholdMilliseconds || + context.Response.StatusCode >= StatusCodes.Status500InternalServerError) + { + logger.LogWarning( + "Slow API request completed: {Method} {Path} ({Endpoint}) returned {StatusCode} in {DurationMs:F1} ms, request {RequestId}.", + context.Request.Method, + context.Request.Path.Value, + endpoint, + context.Response.StatusCode, + durationMilliseconds, + context.TraceIdentifier); + } + else if (options.LogAllApiRequests) + { + logger.LogInformation( + "API request completed: {Method} {Path} ({Endpoint}) returned {StatusCode} in {DurationMs:F1} ms, request {RequestId}.", + context.Request.Method, + context.Request.Path.Value, + endpoint, + context.Response.StatusCode, + durationMilliseconds, + context.TraceIdentifier); + } + } +} diff --git a/src/Jiaowu.Api/Infrastructure/Observability/DatabaseCommandTelemetryInterceptor.cs b/src/Jiaowu.Api/Infrastructure/Observability/DatabaseCommandTelemetryInterceptor.cs index 8adc50a..9a2062d 100644 --- a/src/Jiaowu.Api/Infrastructure/Observability/DatabaseCommandTelemetryInterceptor.cs +++ b/src/Jiaowu.Api/Infrastructure/Observability/DatabaseCommandTelemetryInterceptor.cs @@ -1,6 +1,4 @@ using System.Data.Common; -using System.Diagnostics; -using System.Diagnostics.Metrics; using System.Security.Cryptography; using System.Text; using Microsoft.EntityFrameworkCore.Diagnostics; @@ -9,31 +7,10 @@ namespace Jiaowu.Api.Infrastructure.Observability; public sealed class DatabaseCommandTelemetryInterceptor( ObservabilityOptions options, + IHttpContextAccessor httpContextAccessor, 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, @@ -138,82 +115,41 @@ public sealed class DatabaseCommandTelemetryInterceptor( 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 requestId = httpContextAccessor.HttpContext?.TraceIdentifier ?? "background"; 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}).", + "error {ErrorType}, request {RequestId}).", durationMilliseconds, queryName, commandKind, provider, statementHash, errorType, - traceId); + requestId); 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}). " + + "request {RequestId}). " + "SQL template: {SqlTemplate}", durationMilliseconds, queryName, commandKind, provider, statementHash, - traceId, + requestId, Truncate(command.CommandText, options.MaximumSqlTextLength)); } else @@ -221,13 +157,13 @@ public sealed class DatabaseCommandTelemetryInterceptor( logger.LogWarning( "Slow database command took {DurationMs:F1} ms: " + "{QueryName} ({CommandKind}, {Provider}, hash {StatementHash}, " + - "trace {TraceId}).", + "request {RequestId}).", durationMilliseconds, queryName, commandKind, provider, statementHash, - traceId); + requestId); } } @@ -271,9 +207,6 @@ public sealed class DatabaseCommandTelemetryInterceptor( 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 diff --git a/src/Jiaowu.Api/Infrastructure/Observability/ObservabilityOptions.cs b/src/Jiaowu.Api/Infrastructure/Observability/ObservabilityOptions.cs index aee799f..82389c2 100644 --- a/src/Jiaowu.Api/Infrastructure/Observability/ObservabilityOptions.cs +++ b/src/Jiaowu.Api/Infrastructure/Observability/ObservabilityOptions.cs @@ -6,6 +6,8 @@ public sealed class ObservabilityOptions public bool Enabled { get; set; } = true; public string ServiceName { get; set; } = "jiaowu-api"; + public bool LogAllApiRequests { get; set; } = true; + public int SlowRequestThresholdMilliseconds { get; set; } = 1000; public int SlowQueryThresholdMilliseconds { get; set; } = 500; public bool IncludeSqlText { get; set; } public int MaximumSqlTextLength { get; set; } = 2000; diff --git a/src/Jiaowu.Api/Jiaowu.Api.csproj b/src/Jiaowu.Api/Jiaowu.Api.csproj index b9d71b0..4cb36ba 100644 --- a/src/Jiaowu.Api/Jiaowu.Api.csproj +++ b/src/Jiaowu.Api/Jiaowu.Api.csproj @@ -47,11 +47,6 @@ - - - - - diff --git a/src/Jiaowu.Api/Program.cs b/src/Jiaowu.Api/Program.cs index f7f7f27..f4a44df 100644 --- a/src/Jiaowu.Api/Program.cs +++ b/src/Jiaowu.Api/Program.cs @@ -28,9 +28,6 @@ using Microsoft.EntityFrameworkCore; using Microsoft.Extensions.Caching.Distributed; using Microsoft.IdentityModel.Tokens; using Microsoft.OpenApi; -using OpenTelemetry.Metrics; -using OpenTelemetry.Resources; -using OpenTelemetry.Trace; using Swashbuckle.AspNetCore.SwaggerUI; using System.Threading.RateLimiting; @@ -179,6 +176,7 @@ if (databaseOptions.CommandTimeoutSeconds is < 5 or > 300) if (string.IsNullOrWhiteSpace(observabilityOptions.ServiceName) || observabilityOptions.ServiceName.Length > 100 || + observabilityOptions.SlowRequestThresholdMilliseconds is < 1 or > 60000 || observabilityOptions.SlowQueryThresholdMilliseconds is < 1 or > 60000 || observabilityOptions.MaximumSqlTextLength is < 256 or > 20000) { @@ -208,15 +206,6 @@ if (performanceReportingOptions.CacheSeconds is < 5 or > 300 || "PerformanceReporting 数据源、超时、缓存或指标名称配置无效。"); } -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 || @@ -319,6 +308,7 @@ builder.Services.AddSingleton(performanceReportingOptions); builder.Services.AddSingleton(clickHouseAnalyticsOptions); builder.Services.AddSingleton(rabbitMqOptions); builder.Services.AddSingleton(); +builder.Services.AddHttpContextAccessor(); builder.Services.AddMemoryCache(); builder.Services.AddHttpClient((services, client) => { @@ -379,28 +369,6 @@ builder.Services.AddDbContextPool((services, 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)) { @@ -753,6 +721,7 @@ app.UseStaticFiles(new StaticFileOptions }); app.UseCors("Web"); app.UseRateLimiter(); +app.UseMiddleware(); app.UseAuthentication(); app.UseAuthorization(); app.UseMiddleware(); diff --git a/src/Jiaowu.Api/appsettings.json b/src/Jiaowu.Api/appsettings.json index c1d0064..7cb516d 100644 --- a/src/Jiaowu.Api/appsettings.json +++ b/src/Jiaowu.Api/appsettings.json @@ -22,6 +22,8 @@ "Observability": { "Enabled": true, "ServiceName": "jiaowu-api", + "LogAllApiRequests": true, + "SlowRequestThresholdMilliseconds": 1000, "SlowQueryThresholdMilliseconds": 500, "IncludeSqlText": false, "MaximumSqlTextLength": 2000 diff --git a/tests/Jiaowu.Api.Tests/DatabaseCommandTelemetryInterceptorTests.cs b/tests/Jiaowu.Api.Tests/DatabaseCommandTelemetryInterceptorTests.cs index 7b89f29..7d26de9 100644 --- a/tests/Jiaowu.Api.Tests/DatabaseCommandTelemetryInterceptorTests.cs +++ b/tests/Jiaowu.Api.Tests/DatabaseCommandTelemetryInterceptorTests.cs @@ -1,6 +1,6 @@ -using System.Diagnostics.Metrics; using Jiaowu.Api.Infrastructure.Observability; using Jiaowu.Api.Infrastructure.Persistence; +using Microsoft.AspNetCore.Http; using Microsoft.Data.Sqlite; using Microsoft.EntityFrameworkCore; using Microsoft.Extensions.Logging.Abstractions; @@ -40,7 +40,7 @@ public sealed class DatabaseCommandTelemetryInterceptorTests } [Fact] - public async Task Ef_command_records_duration_metric() + public async Task Ef_command_executes_with_logging_interceptor() { await using var connection = new SqliteConnection("Data Source=:memory:"); @@ -52,25 +52,9 @@ public sealed class DatabaseCommandTelemetryInterceptorTests 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(), + new HttpContextAccessor(), NullLogger.Instance); var queryOptions = new DbContextOptionsBuilder() .UseSqlite(connection) @@ -82,7 +66,6 @@ public sealed class DatabaseCommandTelemetryInterceptorTests .TagWith("Observability.Tests.TermCount") .CountAsync(); - Assert.NotNull(recordedDuration); - Assert.True(recordedDuration >= 0); + Assert.Equal(0, await db.AcademicTerms.CountAsync()); } }