From 0fc5efc132cd124004ece89224faf82e2b33fb2f Mon Sep 17 00:00:00 2001 From: Sebastian Stehle Date: Mon, 24 Aug 2026 15:02:58 +0200 Subject: [PATCH] More fixes --- .../Contents/Operations/QueryByQuery.cs | 17 ++++ .../Log/BackgroundRequestLogStore.cs | 24 +++++ .../Log/RequestLogStoreOptions.cs | 4 + .../src/Squidex.Infrastructure/LogMessages.cs | 3 + .../Log/BackgroundRequestLogStoreTests.cs | 56 ++++++++++- resolved.md | 97 +++++++++++++++++++ todo.md | 61 +++--------- 7 files changed, 211 insertions(+), 51 deletions(-) diff --git a/backend/src/Squidex.Data.MongoDb/Domain/Apps/Entities/Contents/Operations/QueryByQuery.cs b/backend/src/Squidex.Data.MongoDb/Domain/Apps/Entities/Contents/Operations/QueryByQuery.cs index e4b785b7c..db5523639 100644 --- a/backend/src/Squidex.Data.MongoDb/Domain/Apps/Entities/Contents/Operations/QueryByQuery.cs +++ b/backend/src/Squidex.Data.MongoDb/Domain/Apps/Entities/Contents/Operations/QueryByQuery.cs @@ -64,6 +64,13 @@ internal sealed class QueryByQuery(MongoCountCollection countCollection) : Opera { contentTotal = -1; } + else if (isDefault) + { + // Cache total count by app and schemas because no other filters are applied (aka default). + var totalKey = CreateTotalKey(app, schemas); + + contentTotal = await countCollection.GetOrAddAsync(totalKey, ct => Collection.Find(filter).CountDocumentsAsync(ct), ct); + } else if (query.IsSatisfiedByIndex()) { // It is faster to filter with sorting when there is an index, because it forces the index to be used. @@ -78,6 +85,16 @@ internal sealed class QueryByQuery(MongoCountCollection countCollection) : Opera return ResultList.Create(contentTotal, contentEntities); } + private static string CreateTotalKey(App app, List schemas) + { + // The schemas depend on the permissions of the user and are not in a stable order, so the ids + // are sorted. They are also hashed, because the key is the ID of the count document and there + // can be enough schemas to exceed the maximum key size of MongoDB. + var schemaIds = schemas.Select(x => x.Id.ToString()).Order(StringComparer.Ordinal); + + return $"{app.Id}_Schemas_{string.Join('_', schemaIds).ToSha256Base64()}"; + } + public async Task> QueryAsync(Schema schema, Q q, CancellationToken ct) { diff --git a/backend/src/Squidex.Infrastructure/Log/BackgroundRequestLogStore.cs b/backend/src/Squidex.Infrastructure/Log/BackgroundRequestLogStore.cs index 6d1ae4dbb..fb44cec9e 100644 --- a/backend/src/Squidex.Infrastructure/Log/BackgroundRequestLogStore.cs +++ b/backend/src/Squidex.Infrastructure/Log/BackgroundRequestLogStore.cs @@ -20,6 +20,8 @@ public sealed class BackgroundRequestLogStore : DisposableObjectBase, IRequestLo private readonly CompletionTimer logTimer; private readonly RequestLogStoreOptions options; private readonly ConcurrentQueue jobs = new ConcurrentQueue(); + private int jobsCount; + private int jobsDropped; private bool isUpdating; public bool HasPendingJobs => !jobs.IsEmpty || isUpdating; @@ -68,10 +70,21 @@ public sealed class BackgroundRequestLogStore : DisposableObjectBase, IRequestLo isUpdating = true; try { + // Report the entries that have been dropped since the last run, so that the gap in the + // request log is visible instead of silent. + var dropped = Interlocked.Exchange(ref jobsDropped, 0); + + if (dropped > 0) + { + LogMessages.LogRequestLogDropped(log, dropped); + } + var batch = new List(options.BatchSize); while (jobs.TryDequeue(out var dequeued)) { + Interlocked.Decrement(ref jobsCount); + batch.Add(dequeued); if (batch.Count >= options.BatchSize) @@ -123,6 +136,17 @@ public sealed class BackgroundRequestLogStore : DisposableObjectBase, IRequestLo return Task.CompletedTask; } + // The queue is only drained by a timer. If the repository is not available for a longer time + // the queue would grow until the process runs out of memory, so new entries are dropped. + // Logging a request is never important enough to take the whole process down. + if (Volatile.Read(ref jobsCount) >= options.MaxPendingItems) + { + Interlocked.Increment(ref jobsDropped); + return Task.CompletedTask; + } + + Interlocked.Increment(ref jobsCount); + jobs.Enqueue(request); return Task.CompletedTask; diff --git a/backend/src/Squidex.Infrastructure/Log/RequestLogStoreOptions.cs b/backend/src/Squidex.Infrastructure/Log/RequestLogStoreOptions.cs index c84c5b50f..e84401f4c 100644 --- a/backend/src/Squidex.Infrastructure/Log/RequestLogStoreOptions.cs +++ b/backend/src/Squidex.Infrastructure/Log/RequestLogStoreOptions.cs @@ -16,4 +16,8 @@ public sealed class RequestLogStoreOptions public int BatchSize { get; set; } = 1000; public int WriteIntervall { get; set; } = 1000; + + // Requests are only written every few seconds. When the repository is not available the pending + // entries would grow without a limit, therefore they are dropped when this size is reached. + public int MaxPendingItems { get; set; } = 50_000; } diff --git a/backend/src/Squidex.Infrastructure/LogMessages.cs b/backend/src/Squidex.Infrastructure/LogMessages.cs index 9a5d0bb09..2a103cf3e 100644 --- a/backend/src/Squidex.Infrastructure/LogMessages.cs +++ b/backend/src/Squidex.Infrastructure/LogMessages.cs @@ -56,6 +56,9 @@ internal static partial class LogMessages [LoggerMessage(Level = LogLevel.Error, Message = "Failed to track usage in background.")] public static partial void LogTrackUsageFailed(ILogger logger, Exception exception); + [LoggerMessage(Level = LogLevel.Warning, Message = "Dropped {count} request log entries, because the pending queue is full.")] + public static partial void LogRequestLogDropped(ILogger logger, int count); + [LoggerMessage(Level = LogLevel.Error, Message = "Failed to repair snapshot for domain object of type {type} with ID {id}.")] public static partial void LogFailedToRepairDomainObjectSnapshot(ILogger logger, Type type, DomainId id, Exception exception); diff --git a/backend/tests/Squidex.Infrastructure.Tests/Log/BackgroundRequestLogStoreTests.cs b/backend/tests/Squidex.Infrastructure.Tests/Log/BackgroundRequestLogStoreTests.cs index 23a0d4af5..892e12b96 100644 --- a/backend/tests/Squidex.Infrastructure.Tests/Log/BackgroundRequestLogStoreTests.cs +++ b/backend/tests/Squidex.Infrastructure.Tests/Log/BackgroundRequestLogStoreTests.cs @@ -116,7 +116,61 @@ public class BackgroundRequestLogStoreTests .MustHaveHappened(); } + [Fact] + public async Task Should_drop_logs_when_pending_queue_is_full() + { + options.MaxPendingItems = 10; + + for (var i = 0; i < 25; i++) + { + await sut.LogAsync(new Request { Key = i.ToString(CultureInfo.InvariantCulture) }, ct); + } + + await WaitForCompletion(); + + // The first entries are kept and everything above the limit is dropped. + A.CallTo(() => requestLogRepository.InsertManyAsync(Batch("0", "9"), A._)) + .MustHaveHappened(); + + A.CallTo(() => requestLogRepository.InsertManyAsync(A>._, A._)) + .MustHaveHappenedOnceExactly(); + } + + [Fact] + public async Task Should_accept_logs_again_after_pending_queue_has_been_written() + { + options.MaxPendingItems = 10; + + for (var i = 0; i < 25; i++) + { + await sut.LogAsync(new Request { Key = i.ToString(CultureInfo.InvariantCulture) }, ct); + } + + await WaitForDrain(); + + // The queue must not stay full after it has been drained. + for (var i = 100; i < 110; i++) + { + await sut.LogAsync(new Request { Key = i.ToString(CultureInfo.InvariantCulture) }, ct); + } + + await WaitForCompletion(); + + A.CallTo(() => requestLogRepository.InsertManyAsync(Batch("0", "9"), A._)) + .MustHaveHappened(); + + A.CallTo(() => requestLogRepository.InsertManyAsync(Batch("100", "109"), A._)) + .MustHaveHappened(); + } + private async Task WaitForCompletion() + { + await WaitForDrain(); + + sut.Dispose(); + } + + private async Task WaitForDrain() { sut.Next(); @@ -128,8 +182,6 @@ public class BackgroundRequestLogStoreTests await Task.Delay(20, tcs.Token); } - - sut.Dispose(); } private static IEnumerable Batch(string from, string to) diff --git a/resolved.md b/resolved.md index 73ed64c26..7dc2cbb72 100644 --- a/resolved.md +++ b/resolved.md @@ -524,3 +524,100 @@ Deduplicating it was tried and reverted: the gain is small enough that it does n threading a materialized `List>` through the method signatures. **Verified:** build clean, all suites green. + +--- + +### 10. Unbounded in-memory request-log queue — **FIXED** +`backend/src/Squidex.Infrastructure/Log/BackgroundRequestLogStore.cs` +`backend/src/Squidex.Infrastructure/Log/RequestLogStoreOptions.cs` + +**Was:** `jobs` was an unbounded `ConcurrentQueue`. `LogAsync` enqueues on every +API request while the flush timer drains only once per `WriteIntervall` (1s by default). +If `InsertManyAsync` threw — Mongo unreachable, disk full — the drain aborted and the +surviving entries stayed queued while new ones kept arriving. A sustained storage outage +under load grew the queue until the process ran out of memory: the request *log* taking +down the whole server. + +**Now:** a soft bound with an explicit drop counter. + +```csharp +if (Volatile.Read(ref jobsCount) >= options.MaxPendingItems) +{ + Interlocked.Increment(ref jobsDropped); + return Task.CompletedTask; +} + +Interlocked.Increment(ref jobsCount); + +jobs.Enqueue(request); +``` + +`jobsCount` is decremented as the drain dequeues, so the queue accepts entries again once +it has been written. Each drain reports what it dropped via a new +`LogRequestLogDropped` message, so the gap in the request log is visible rather than +silent. `MaxPendingItems` defaults to 50,000 — roughly 50 seconds of headroom at 1000 +requests/second — and is configurable. + +The bound is deliberately *soft*: two threads can both observe `jobsCount < max` and both +enqueue, so the queue can overshoot by the number of concurrent writers. That is fine for +a backpressure limit and avoids a lock on the hot path. + +A `Channel` with `BoundedChannelFullMode.DropWrite` was the alternative. The counter was +chosen because it keeps the existing drain loop unchanged and makes the drop explicit at +the call site instead of hiding it behind a channel option. + +**Verified:** two new tests — +`Should_drop_logs_when_pending_queue_is_full` and +`Should_accept_logs_again_after_pending_queue_has_been_written`. Both **fail on the +pre-fix code**. The second was additionally mutation-checked: removing the +`Interlocked.Decrement` from the drain loop kills it and nothing else, confirming it +really covers the recovery path rather than passing incidentally. This required splitting +the test helper, because the existing `WaitForCompletion` disposes the store and so cannot +be used to drain twice. `Squidex.Infrastructure.Tests` green (1033). + +--- + +### 11. Cross-schema content queries never used the cached total — **FIXED** +`backend/src/Squidex.Data.MongoDb/Domain/Apps/Entities/Contents/Operations/QueryByQuery.cs` + +**Was:** + +```csharp +var (filter, isDefault) = CreateFilter(app.Id, schemas.Select(x => x.Id), ...); +``` + +`isDefault` was computed and then discarded. The multi-schema overload had no +`else if (isDefault)` branch, unlike the single-schema overload thirty lines below which +routes through `countCollection.GetOrAddAsync`. So the "all schemas" `/contents` endpoint +ran a full uncached `CountDocumentsAsync` over every content in the app on each page. + +**Now:** the branch is mirrored, keyed by app plus the schema set: + +```csharp +else if (isDefault) +{ + var totalKey = CreateTotalKey(app, schemas); + + contentTotal = await countCollection.GetOrAddAsync(totalKey, ct => Collection.Find(filter).CountDocumentsAsync(ct), ct); +} +``` + +**The key needs care, which is why it is not just an interpolated list.** The schema set +depends on the caller's permissions and arrives in no guaranteed order, so the ids are +sorted before hashing — otherwise the same query would produce different keys and never +hit. And the key becomes the `_id` of the count document, where MongoDB caps index keys at +1024 bytes; a raw join of 37-character ids would exceed that at roughly 27 schemas. Hashing +gives a bounded, deterministic key: + +```csharp +var schemaIds = schemas.Select(x => x.Id.ToString()).Order(StringComparer.Ordinal); + +return $"{app.Id}_Schemas_{string.Join('_', schemaIds).ToSha256Base64()}"; +``` + +The `_Schemas_` marker keeps this key space distinct from the single-schema overload's +`$"{appId}_{schemaId}"`. The two must not share entries in any case: their filters differ +(`Filter.In` vs `Filter.Eq`, and different existence guards), so the counts are not +interchangeable. + +**Verified:** build clean, all suites green. diff --git a/todo.md b/todo.md index f8e786f0e..013f7a69f 100644 --- a/todo.md +++ b/todo.md @@ -9,9 +9,9 @@ overhead / allocation churn), **S4** low (worth fixing while nearby). Item numbers are stable and never reused. Completed items move to [resolved.md](resolved.md) keeping their number, so gaps in the sequence here are -expected — items **4**, **5**, **6**, **7**, **8**, **9**, **12**, **13**, **14**, **15**, **16**, **17** and **20** are closed and live there. +expected — items **4**–**17** and **20** are closed and live there. -**Status: 7 open of 20 — items 1, 2, 3, 10, 11, 18, 19. The other 13 are in [resolved.md](resolved.md).** +**Status: 5 open of 20 — items 1, 2, 3, 18, 19. The other 15 are in [resolved.md](resolved.md).** --- @@ -66,42 +66,6 @@ already isolated in `ContentScriptVars`. --- -## S2 — High - -### 10. Unbounded in-memory request-log queue -`backend/src/Squidex.Infrastructure/Log/BackgroundRequestLogStore.cs:22,126` - -`jobs` is an unbounded `ConcurrentQueue`; `LogAsync` enqueues on every API -request and the flush timer runs once per `WriteIntervall`. If `InsertManyAsync` throws -(Mongo unreachable, disk full), the `TrackAsync` loop aborts and the surviving items -stay queued while new ones keep arriving. A sustained storage outage under load grows -the queue until OOM — the logging subsystem takes down the whole process. - -`BackgroundUsageTracker` uses a `ConcurrentDictionary` keyed by (key, category, date), -so it is naturally bounded and not affected. - -**Fix:** bound the queue (drop-oldest with a counter, or `Channel` with -`BoundedChannelFullMode.DropWrite`) and log the drop count. - ---- - -### 11. Cross-schema content queries never use the cached total -`backend/src/Squidex.Data.MongoDb/Domain/Apps/Entities/Contents/Operations/QueryByQuery.cs:56` - -```csharp -var (filter, isDefault) = CreateFilter(app.Id, schemas.Select(x => x.Id), ...); -``` - -`isDefault` is computed and then discarded — the multi-schema overload has no -`else if (isDefault)` branch, unlike the single-schema overload 30 lines below which -routes through `countCollection.GetOrAddAsync`. So the "all schemas" `/contents` -endpoint runs a full `CountDocumentsAsync` over every content in the app on each page -request, uncached. - -**Fix:** mirror the single-schema branch, keyed by app + sorted schema-id set. - ---- - ## S3 — Moderate ### 18. Sequential N+1 schema and component lookups @@ -141,17 +105,16 @@ from several steps. The headers never change for the lifetime of a `Context`. ## Suggested order of attack -1. **Engine pooling (items 1–3)** — now the largest open cost by a wide margin. One - change in `JintScriptEngine` addresses it, and items 2 and 3 mostly disappear with it. -2. **Item 11** — small, self-contained; removes an uncached full-collection count from a - paged endpoint. -3. **Item 10** — stability under load rather than throughput; an unbounded queue that - turns a storage outage into an OOM. -4. **Everything else** — steady-state allocation and lock overhead; measure with a - profiler on a representative content-list request before and after. - -All the correctness-shaped findings are now closed. What remains is genuine performance -work, which is exactly the category that should be profiled before it is written. +1. **Engine pooling (items 1–3)** — by a wide margin the largest remaining cost, and the + only one left that can dominate a request. One change in `JintScriptEngine` addresses + it, and items 2 and 3 mostly disappear with it. +2. **Items 18 and 19** — steady-state allocation and a warm-cache N+1; both are small and + neither is likely to show up next to item 1. + +Everything correctness-shaped is closed, as is everything in the stability category. What +remains is pure throughput work — exactly the category that should be profiled before it +is written. Item 1 in particular is worth measuring first: the estimate that it dominates +a scripted content list comes from reading the loops, not from a trace. ---