From 78dddd8f9d020165d038c00e04a8e14de092bef3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ricardo=20Gro=C3=9F?= Date: Sun, 18 Oct 2026 14:27:40 +0200 Subject: [PATCH] fix(storage): raise LockTimeout.Default to 5 s so writers queued behind slow commits do not time out (#303) A writer waits for the I/O of every writer queued ahead of it: an auto-committing write holds the collection lock until its commit is in the WAL, and a checkpoint holds the page-file write lock while it syncs the data file. With 500 ms, a healthy but slow disk (and every commit once #280 syncs the WAL) turned those waits into TimeoutException and a rolled-back write. LockTimeout.Default is now 5 s read / 5 s write, the same as the WAL's own lock timeout, so a timeout means a stuck writer, not a slow one. Immediate and From() are unchanged; PageFileConfig.LockTimeout already reaches every lock, which the new tests pin. Co-Authored-By: Claude Fable 5.1 --- src/BLite.Core/Storage/LockTimeout.cs | 20 ++- src/BLite.Core/Storage/PageFile.cs | 3 +- src/BLite.Core/Storage/StorageEngine.cs | 2 +- tests/BLite.Tests/IndexPageReleaseTests.cs | 3 +- tests/BLite.Tests/LockTimeoutDefaultTests.cs | 179 +++++++++++++++++++ 5 files changed, 197 insertions(+), 10 deletions(-) create mode 100644 tests/BLite.Tests/LockTimeoutDefaultTests.cs diff --git a/src/BLite.Core/Storage/LockTimeout.cs b/src/BLite.Core/Storage/LockTimeout.cs index 10693990..a2959821 100644 --- a/src/BLite.Core/Storage/LockTimeout.cs +++ b/src/BLite.Core/Storage/LockTimeout.cs @@ -60,15 +60,23 @@ namespace BLite.Core.Storage; public static LockTimeout Immediate => new() { ReadTimeoutMs = 0, WriteTimeoutMs = 0, MaxConcurrentWriters = 0 }; /// - /// Balanced default: 500 ms write timeout, 500 ms read timeout, - /// 96 max concurrent writers. + /// Balanced default: 5 s write timeout, 5 s read timeout, 96 max concurrent writers. /// - /// 500 ms is long enough for commits under normal load (observed p99 well under 500 ms) - /// but short enough to fail-fast when the engine is saturated rather than leaving - /// threads blocked for seconds, starving the thread-pool. + /// A writer waits for other writers' I/O, not only for their CPU work: an auto-committing + /// write holds the collection lock (in single-file mode, typed collections share one lock for + /// the whole file) until its commit is in the WAL, and a checkpoint holds the page-file write + /// lock while it syncs the data file. Writers queued behind each other wait for several such + /// writes, and a disk can stall for hundreds of milliseconds. 5 s matches the WAL's own lock + /// timeout, so a means a writer that is stuck (a deadlock or a + /// hung disk), not one that is slow. + /// + /// + /// The asynchronous write paths wait with , + /// which blocks no thread while waiting. Use for fail-fast + /// (SQLITE_BUSY) behaviour, or for other values. /// /// - public static LockTimeout Default => new() { ReadTimeoutMs = 500, WriteTimeoutMs = 500, MaxConcurrentWriters = 96 }; + public static LockTimeout Default => new() { ReadTimeoutMs = 5_000, WriteTimeoutMs = 5_000, MaxConcurrentWriters = 96 }; /// /// Creates a from explicit millisecond values. diff --git a/src/BLite.Core/Storage/PageFile.cs b/src/BLite.Core/Storage/PageFile.cs index 36b42b63..dc259ef9 100644 --- a/src/BLite.Core/Storage/PageFile.cs +++ b/src/BLite.Core/Storage/PageFile.cs @@ -46,7 +46,8 @@ public readonly struct PageFileConfig /// Lock acquisition timeouts for read and write operations. /// Controls how long the engine waits for a contended lock before throwing /// (analogous to SQLite's SQLITE_BUSY). - /// Defaults to (500 ms read / 500 ms write). + /// The , , and + /// presets use (5 s read / 5 s write). /// Use for fail-fast behaviour. /// public LockTimeout LockTimeout { get; init; } diff --git a/src/BLite.Core/Storage/StorageEngine.cs b/src/BLite.Core/Storage/StorageEngine.cs index 4c5d256b..82c3cd8d 100644 --- a/src/BLite.Core/Storage/StorageEngine.cs +++ b/src/BLite.Core/Storage/StorageEngine.cs @@ -483,7 +483,7 @@ public void Dispose() // its truncation and frees fail, leaking the pages for good. Wait for it to finish (#209). // // The wait lasts as long as that checkpoint, not a lock timeout: on a loaded CI runner one - // took longer than WriteTimeoutMs (500 ms) and was cut short while releasing the pages. It + // took longer than WriteTimeoutMs (then 500 ms) and was cut short while releasing the pages. It // cannot hang: every lock the checkpoint takes (commit lock, cross-process writer lock, // page file locks) is waited for with its own timeout, its I/O is finite (the WAL images, // one flush, the truncation, one free per queued page), it waits for nothing Dispose diff --git a/tests/BLite.Tests/IndexPageReleaseTests.cs b/tests/BLite.Tests/IndexPageReleaseTests.cs index df8d2353..52688c70 100644 --- a/tests/BLite.Tests/IndexPageReleaseTests.cs +++ b/tests/BLite.Tests/IndexPageReleaseTests.cs @@ -334,9 +334,8 @@ public async Task Dispose_DuringPendingFreeCheckpoint_DoesNotLeakTheQueuedPages( [Fact] public async Task Dispose_WaitsForThePendingFreeCheckpoint_LongerThanTheLockTimeout() { - var storage = new StorageEngine(_dbPath, PageFileConfig.Default); + var storage = new StorageEngine(_dbPath, PageFileConfig.Default with { LockTimeout = LockTimeout.From(500, 500) }); var timeout = storage.LockTimeout.WriteTimeoutMs; - Assert.InRange(timeout, 1, 1000); var checkpoint = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); typeof(StorageEngine).GetField("_pendingFreeCheckpointTask", Flags)!.SetValue(storage, checkpoint.Task); diff --git a/tests/BLite.Tests/LockTimeoutDefaultTests.cs b/tests/BLite.Tests/LockTimeoutDefaultTests.cs new file mode 100644 index 00000000..7065ad5d --- /dev/null +++ b/tests/BLite.Tests/LockTimeoutDefaultTests.cs @@ -0,0 +1,179 @@ +using System.Collections.Concurrent; +using System.Diagnostics; +using System.Reflection; +using BLite.Core; +using BLite.Core.Storage; +using BLite.Core.Transactions; +using BLite.Shared; + +namespace BLite.Tests; + +/// +/// #303: a writer waits for the commits queued ahead of it, and each commit waits for the disk, so +/// must outlast several slow commits, and a timeout set on +/// must reach every lock that waits with it. +/// +public class LockTimeoutDefaultTests : IDisposable +{ + private const BindingFlags Flags = BindingFlags.NonPublic | BindingFlags.Instance; + private readonly string _dir = Path.Combine(Path.GetTempPath(), $"locktimeout_{Guid.NewGuid():N}"); + + public LockTimeoutDefaultTests() => Directory.CreateDirectory(_dir); + + public void Dispose() + { + try { Directory.Delete(_dir, recursive: true); } catch { /* best-effort */ } + } + + [Fact] + public void Default_IsFiveSecondsForReadsAndWrites() + { + Assert.Equal(LockTimeout.From(readTimeoutMs: 5_000, writeTimeoutMs: 5_000, maxConcurrentWriters: 96), LockTimeout.Default); + } + + [Fact] + public void Presets_AndDetectedConfigs_UseTheDefault() + { + Assert.Equal(LockTimeout.Default, PageFileConfig.Small.LockTimeout); + Assert.Equal(LockTimeout.Default, PageFileConfig.Default.LockTimeout); + Assert.Equal(LockTimeout.Default, PageFileConfig.Large.LockTimeout); + Assert.Equal(LockTimeout.Default, PageFileConfig.Server(Path.Combine(_dir, "server.db")).LockTimeout); + + foreach (var (name, config) in new[] { ("small", PageFileConfig.Small), ("large", PageFileConfig.Large) }) + { + var path = Path.Combine(_dir, name + ".db"); + new BLiteEngine(path, config).Dispose(); + Assert.Equal(LockTimeout.Default, PageFileConfig.DetectFromFile(path)!.Value.LockTimeout); + } + + using var memory = BLiteEngine.CreateInMemory(); + Assert.Equal(LockTimeout.Default, memory.Storage.LockTimeout); + } + + /// + /// A configured timeout reaches the WAL, the main, index and collection page files, the + /// admission gate and both kinds of collection. + /// + [Fact] + public async Task ConfiguredTimeout_ReachesEveryLock() + { + var timeout = LockTimeout.From(readTimeoutMs: 1_234, writeTimeoutMs: 2_345, maxConcurrentWriters: 7); + var path = Path.Combine(_dir, "engine", "test.db"); + Directory.CreateDirectory(Path.GetDirectoryName(path)!); + using (var engine = new BLiteEngine(path, PageFileConfig.Server(path) with { LockTimeout = timeout })) + { + var col = engine.GetOrCreateCollection("docs"); + await col.InsertAsync(col.CreateDocument(["value"], b => b.AddInt32("value", 1))); + var storage = engine.Storage; + + Assert.Equal(timeout, storage.LockTimeout); + Assert.Equal(2_345, (int)Field(Field(storage, "_wal"), "_writeTimeoutMs")); + Assert.Equal(timeout, PageFileLockTimeout(Field(storage, "_pageFile"))); + Assert.Equal(timeout, PageFileLockTimeout(Field(storage, "_indexFile"))); + var collectionFiles = (ConcurrentDictionary>)Field(storage, "_collectionFiles"); + Assert.NotEmpty(collectionFiles); + foreach (var file in collectionFiles.Values) + Assert.Equal(timeout, PageFileLockTimeout(file.Value)); + Assert.Equal(7, ((SemaphoreSlim)Field(storage, "_writerGate")).CurrentCount); + Assert.Equal(2_345, WriteLockTimeoutMs(col)); + } + + var ctxPath = Path.Combine(_dir, "context", "test.db"); + Directory.CreateDirectory(Path.GetDirectoryName(ctxPath)!); + using (var db = new TestDbContext(ctxPath, PageFileConfig.Default with { LockTimeout = timeout })) + Assert.Equal(2_345, WriteLockTimeoutMs(db.TestDocuments)); + } + + /// + /// The commit lock waits for the configured write timeout, not for the default: with the lock + /// held, an auto-committing insert fails after about 150 ms, well before the 5 s default. + /// + [Fact] + public async Task CommitLock_WaitsForTheConfiguredWriteTimeout() + { + using var engine = new BLiteEngine(Path.Combine(_dir, "commit.db"), + PageFileConfig.Default with { LockTimeout = LockTimeout.From(150, 150) }); + var col = engine.GetOrCreateCollection("docs"); + await col.InsertAsync(col.CreateDocument(["value"], b => b.AddInt32("value", 0))); + + var commitLock = (SemaphoreSlim)Field(engine.Storage, "_commitLock"); + await commitLock.WaitAsync(); + try + { + var sw = Stopwatch.StartNew(); + var ex = await Assert.ThrowsAsync(async () => + await col.InsertAsync(col.CreateDocument(["value"], b => b.AddInt32("value", 1)))); + sw.Stop(); + Assert.Contains("commit lock", ex.Message); + Assert.InRange(sw.ElapsedMilliseconds, 100, 3_000); + } + finally + { + commitLock.Release(); + } + } + + /// + /// Writers on one collection queue behind each other's commits, and each commit here takes + /// 150 ms to reach the WAL (a disk sync on a slow disk). The last of 8 writers waits about a + /// second, twice the 500 ms the default used to allow, and none of them may time out. + /// + [Fact] + public async Task WritersQueuedBehindSlowCommits_DoNotTimeOut() + { + const int writers = 8; + const int commitMs = 150; + var wal = new SlowFlushWriteAheadLog(new MemoryWriteAheadLog(), commitMs); + var pages = new MemoryPageStorage(16384); + pages.Open(); + using var engine = BLiteEngine.CreateFromStorage(new StorageEngine(pages, wal)); + var col = engine.GetOrCreateCollection("docs"); + await col.InsertAsync(col.CreateDocument(["value"], b => b.AddInt32("value", -1))); + + wal.Slow = true; + var start = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var inserts = Enumerable.Range(0, writers).Select(w => Task.Run(async () => + { + await start.Task; + var sw = Stopwatch.StartNew(); + await col.InsertAsync(col.CreateDocument(["value"], b => b.AddInt32("value", w))); + return sw.ElapsedMilliseconds; + })).ToList(); + start.SetResult(true); + var elapsed = await Task.WhenAll(inserts); + + Assert.True(elapsed.Max() > 500, $"the slowest writer took {elapsed.Max()} ms; the scenario must wait longer than the old 500 ms default"); + Assert.Equal(writers + 1, (await col.FindAllAsync().ToListAsync()).Count); + } + + private static object Field(object owner, string name) + => owner.GetType().GetField(name, Flags)!.GetValue(owner)!; + + private static LockTimeout PageFileLockTimeout(object pageFile) + => ((PageFileConfig)Field(Assert.IsType(pageFile), "_config")).LockTimeout; + + private static int WriteLockTimeoutMs(object collection) + => (int)collection.GetType().GetProperty("WriteLockTimeoutMs", Flags)!.GetValue(collection)!; + + /// Delays every flush, like a WAL whose commit waits for a slow disk sync. + private sealed class SlowFlushWriteAheadLog(IWriteAheadLog inner, int delayMs) : IWriteAheadLog + { + public volatile bool Slow; + + public async Task FlushAsync(CancellationToken ct = default) + { + if (Slow) await Task.Delay(delayMs, ct).ConfigureAwait(false); + await inner.FlushAsync(ct).ConfigureAwait(false); + } + + public ValueTask WriteBeginRecordAsync(ulong transactionId, CancellationToken ct = default) => inner.WriteBeginRecordAsync(transactionId, ct); + public ValueTask WriteCommitRecordAsync(ulong transactionId, CancellationToken ct = default) => inner.WriteCommitRecordAsync(transactionId, ct); + public ValueTask WriteAbortRecordAsync(ulong transactionId, CancellationToken ct = default) => inner.WriteAbortRecordAsync(transactionId, ct); + public ValueTask WriteDataRecordAsync(ulong transactionId, uint pageId, ReadOnlyMemory afterImage, CancellationToken ct = default) + => inner.WriteDataRecordAsync(transactionId, pageId, afterImage, ct); + public long GetCurrentSize() => inner.GetCurrentSize(); + public Task TruncateAsync(CancellationToken ct = default) => inner.TruncateAsync(ct); + public List ReadAll() => inner.ReadAll(); + public void Dispose() => inner.Dispose(); + } +}