Browse Source

More fixes

pull/1330/head
Sebastian Stehle 2 weeks ago
parent
commit
0fc5efc132
  1. 17
      backend/src/Squidex.Data.MongoDb/Domain/Apps/Entities/Contents/Operations/QueryByQuery.cs
  2. 24
      backend/src/Squidex.Infrastructure/Log/BackgroundRequestLogStore.cs
  3. 4
      backend/src/Squidex.Infrastructure/Log/RequestLogStoreOptions.cs
  4. 3
      backend/src/Squidex.Infrastructure/LogMessages.cs
  5. 56
      backend/tests/Squidex.Infrastructure.Tests/Log/BackgroundRequestLogStoreTests.cs
  6. 97
      resolved.md
  7. 61
      todo.md

17
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; 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()) else if (query.IsSatisfiedByIndex())
{ {
// It is faster to filter with sorting when there is an index, because it forces the index to be used. // 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<Content>(contentTotal, contentEntities); return ResultList.Create<Content>(contentTotal, contentEntities);
} }
private static string CreateTotalKey(App app, List<Schema> 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<IResultList<Content>> QueryAsync(Schema schema, Q q, public async Task<IResultList<Content>> QueryAsync(Schema schema, Q q,
CancellationToken ct) CancellationToken ct)
{ {

24
backend/src/Squidex.Infrastructure/Log/BackgroundRequestLogStore.cs

@ -20,6 +20,8 @@ public sealed class BackgroundRequestLogStore : DisposableObjectBase, IRequestLo
private readonly CompletionTimer logTimer; private readonly CompletionTimer logTimer;
private readonly RequestLogStoreOptions options; private readonly RequestLogStoreOptions options;
private readonly ConcurrentQueue<Request> jobs = new ConcurrentQueue<Request>(); private readonly ConcurrentQueue<Request> jobs = new ConcurrentQueue<Request>();
private int jobsCount;
private int jobsDropped;
private bool isUpdating; private bool isUpdating;
public bool HasPendingJobs => !jobs.IsEmpty || isUpdating; public bool HasPendingJobs => !jobs.IsEmpty || isUpdating;
@ -68,10 +70,21 @@ public sealed class BackgroundRequestLogStore : DisposableObjectBase, IRequestLo
isUpdating = true; isUpdating = true;
try 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<Request>(options.BatchSize); var batch = new List<Request>(options.BatchSize);
while (jobs.TryDequeue(out var dequeued)) while (jobs.TryDequeue(out var dequeued))
{ {
Interlocked.Decrement(ref jobsCount);
batch.Add(dequeued); batch.Add(dequeued);
if (batch.Count >= options.BatchSize) if (batch.Count >= options.BatchSize)
@ -123,6 +136,17 @@ public sealed class BackgroundRequestLogStore : DisposableObjectBase, IRequestLo
return Task.CompletedTask; 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); jobs.Enqueue(request);
return Task.CompletedTask; return Task.CompletedTask;

4
backend/src/Squidex.Infrastructure/Log/RequestLogStoreOptions.cs

@ -16,4 +16,8 @@ public sealed class RequestLogStoreOptions
public int BatchSize { get; set; } = 1000; public int BatchSize { get; set; } = 1000;
public int WriteIntervall { 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;
} }

3
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.")] [LoggerMessage(Level = LogLevel.Error, Message = "Failed to track usage in background.")]
public static partial void LogTrackUsageFailed(ILogger logger, Exception exception); 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}.")] [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); public static partial void LogFailedToRepairDomainObjectSnapshot(ILogger logger, Type type, DomainId id, Exception exception);

56
backend/tests/Squidex.Infrastructure.Tests/Log/BackgroundRequestLogStoreTests.cs

@ -116,7 +116,61 @@ public class BackgroundRequestLogStoreTests
.MustHaveHappened(); .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<CancellationToken>._))
.MustHaveHappened();
A.CallTo(() => requestLogRepository.InsertManyAsync(A<IEnumerable<Request>>._, A<CancellationToken>._))
.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<CancellationToken>._))
.MustHaveHappened();
A.CallTo(() => requestLogRepository.InsertManyAsync(Batch("100", "109"), A<CancellationToken>._))
.MustHaveHappened();
}
private async Task WaitForCompletion() private async Task WaitForCompletion()
{
await WaitForDrain();
sut.Dispose();
}
private async Task WaitForDrain()
{ {
sut.Next(); sut.Next();
@ -128,8 +182,6 @@ public class BackgroundRequestLogStoreTests
await Task.Delay(20, tcs.Token); await Task.Delay(20, tcs.Token);
} }
sut.Dispose();
} }
private static IEnumerable<Request> Batch(string from, string to) private static IEnumerable<Request> Batch(string from, string to)

97
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<IGrouping<...>>` through the method signatures. threading a materialized `List<IGrouping<...>>` through the method signatures.
**Verified:** build clean, all suites green. **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<Request>`. `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.

61
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 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 [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<Request>`; `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 ## S3 — Moderate
### 18. Sequential N+1 schema and component lookups ### 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 ## Suggested order of attack
1. **Engine pooling (items 1–3)** — now the largest open cost by a wide margin. One 1. **Engine pooling (items 1–3)** — by a wide margin the largest remaining cost, and the
change in `JintScriptEngine` addresses it, and items 2 and 3 mostly disappear with it. only one left that can dominate a request. One change in `JintScriptEngine` addresses
2. **Item 11** — small, self-contained; removes an uncached full-collection count from a it, and items 2 and 3 mostly disappear with it.
paged endpoint. 2. **Items 18 and 19** — steady-state allocation and a warm-cache N+1; both are small and
3. **Item 10** — stability under load rather than throughput; an unbounded queue that neither is likely to show up next to item 1.
turns a storage outage into an OOM.
4. **Everything else** — steady-state allocation and lock overhead; measure with a Everything correctness-shaped is closed, as is everything in the stability category. What
profiler on a representative content-list request before and after. 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
All the correctness-shaped findings are now closed. What remains is genuine performance a scripted content list comes from reading the loops, not from a trace.
work, which is exactly the category that should be profiled before it is written.
--- ---

Loading…
Cancel
Save