弃用 OpenTelemetry,并建立日志驱动的真实慢接口基线

This commit is contained in:
2026-08-11 11:32:50 +08:00 Unverified
parent 9708f81764
commit 292d029459
9 changed files with 87 additions and 157 deletions
+3 -3
View File
@@ -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
+16 -19
View File
@@ -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` 数据库迁移,再启动应用实例。
@@ -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<SlowRequestLoggingMiddleware> 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);
}
}
}
@@ -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<DatabaseCommandTelemetryInterceptor> 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<double> CommandDuration =
Meter.CreateHistogram<double>(
"jiaowu.db.command.duration",
"ms",
"EF Core database command duration");
private static readonly Counter<long> SlowCommandCount =
Meter.CreateCounter<long>(
"jiaowu.db.command.slow",
"{command}",
"EF Core commands exceeding the configured slow-query threshold");
private static readonly Counter<long> FailedCommandCount =
Meter.CreateCounter<long>(
"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
@@ -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;
-5
View File
@@ -47,11 +47,6 @@
</PackageReference>
<PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite" Version="10.0.10" />
<PackageReference Include="MySql.EntityFrameworkCore" Version="10.0.9" />
<PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol" Version="1.17.0" />
<PackageReference Include="OpenTelemetry.Extensions.Hosting" Version="1.17.0" />
<PackageReference Include="OpenTelemetry.Instrumentation.AspNetCore" Version="1.17.0" />
<PackageReference Include="OpenTelemetry.Instrumentation.Http" Version="1.17.0" />
<PackageReference Include="OpenTelemetry.Instrumentation.Runtime" Version="1.17.0" />
<PackageReference Include="QRCoder" Version="1.8.0" />
<PackageReference Include="RabbitMQ.Client" Version="7.2.2" />
<PackageReference Include="SkiaSharp" Version="4.151.1" />
+3 -34
View File
@@ -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<DatabaseCommandTelemetryInterceptor>();
builder.Services.AddHttpContextAccessor();
builder.Services.AddMemoryCache();
builder.Services.AddHttpClient<PerformanceReportService>((services, client) =>
{
@@ -379,28 +369,6 @@ builder.Services.AddDbContextPool<AppDbContext>((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<SlowRequestLoggingMiddleware>();
app.UseAuthentication();
app.UseAuthorization();
app.UseMiddleware<AuditMiddleware>();
+2
View File
@@ -22,6 +22,8 @@
"Observability": {
"Enabled": true,
"ServiceName": "jiaowu-api",
"LogAllApiRequests": true,
"SlowRequestThresholdMilliseconds": 1000,
"SlowQueryThresholdMilliseconds": 500,
"IncludeSqlText": false,
"MaximumSqlTextLength": 2000
@@ -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<double>(
(_, measurement, _, _) => recordedDuration = measurement);
listener.Start();
var interceptor = new DatabaseCommandTelemetryInterceptor(
new ObservabilityOptions(),
new HttpContextAccessor(),
NullLogger<DatabaseCommandTelemetryInterceptor>.Instance);
var queryOptions = new DbContextOptionsBuilder<AppDbContext>()
.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());
}
}