Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG] Performance degradation in v5.0.18 #2451

Open
alexbereznikov opened this issue Mar 19, 2024 · 5 comments · May be fixed by #2453 or #2454
Open

[BUG] Performance degradation in v5.0.18 #2451

alexbereznikov opened this issue Mar 19, 2024 · 5 comments · May be fixed by #2453 or #2454
Labels
bug

Comments

@alexbereznikov
Copy link

alexbereznikov commented Mar 19, 2024 •
edited

Version
v5.0.18, v5.0.19

Describe the bug
Upsert performance degraded in ~14 times in v5.0.18 when compared to 5.0.17

Code to Reproduce
Running this snippet with v5.0.17 and 5.0.18 is enough to see the issue. On my machine, 5.0.17 runs in 12 seconds, and 5.0.18 runs in 2m 50 seconds.

internal class Program
{
    private const string DbName = "test.db";
    private const int Records = 100_0000;
    private const int Chunk = 1000;

    static void Main(string[] args)
    {
        if (File.Exists(DbName))
        {
            File.Delete(DbName);
        }

        using (var db = new LiteDatabase(
            new ConnectionString
            {
                Filename = DbName,
            }))
        {
            var collection = db.GetCollection<TestRecord>();
            collection.EnsureIndex(x => x.Index);

            var data = GenerateData();

            var sw = Stopwatch.StartNew();

            foreach (var chunk in data)
            {
                collection.Upsert(chunk);
            }

            Console.Write(sw.Elapsed);
        }
    }

    private static IReadOnlyCollection<IReadOnlyCollection<TestRecord>> GenerateData()
    {
        var records = new List<TestRecord>(Records);

        for (var i = 0; i < Records; i++)
        {
            records.Add(new TestRecord
            {
                Index = i,
                First = Random.Shared.Next(),
                Second = Random.Shared.Next(),
            });
        }

        return records.Chunk(Chunk).ToArray();
    }

    private sealed class TestRecord
    {
        public int Index { get; init; }

        public int First { get; init; }

        public int Second { get; init; }
    }
}

Expected behavior
Expected behavior is that performance in v5.0.18 is more or less the same as in v5.0.17

Screenshots/Stacktrace
N/A

Additional context
I haven't experimented much, upserting in chunks because that's what we do in our app, maybe chunk size matters, maybe not. Also haven't tried other operations.
@alexbereznikov alexbereznikov changed the title [BUG] Performance degradation in v5.0.19 [BUG] Performance degradation in v5.0.18 Mar 19, 2024
@alexbereznikov
Copy link
Author

So I decided to profile this repro to understand what leads to this performance degradation. Profiling for 5.0.19 gives the following results:
image
As we can see, CommitAndReleaseTransaction takes 4x more time than upsert itself, and for some reason we're doing writing to disk in the same thread.

And here is how it looks for v5.0.17:
image
As we can see, in v5.0.17 CommitAndReleaseTransaction takes little to no time, and all the writing is offloaded to a separate thread.

After some investigation, turns out that there is an issue in AsyncManualResetEvent - when Set is being called, execution continues in DiskWriterQueue.ExecuteQueue after await _queueHasItems.WaitAsync(). I would say, we don't need this separate class at all, as .NET provides a way to await any WaitHandle using thread pool (see https://github.com/StephenCleary/AsyncEx/blob/v5.0.0/src/Nito.AsyncEx.Interop.WaitHandles/Interop/WaitHandleAsyncFactory.cs, DoFromWaitHandle). So I changed that event to ManualResetEventSlim in conjunction with this method.

Now repro runs in 42 seconds. 4x faster than 5.0.19 but still ~3x slower than 5.0.17. Further profiling results:
image
As we can see, for some reason we do call BasePage.ToString a lot, as well as formatting strings. I'm 100% sure that this should not happen on the hot path. Here is the issue (BasePage.Get):

ENSURE(this.IsValidPos(position), $"invalid segment position in index footer: {ToString()}/{index}");
ENSURE(this.IsValidLen(length), $"invalid segment length in index footer: {ToString()}/{index}");

So I just commented these 2 lines to check and 1 in IndexService, and it runs in 13 seconds, pretty close to v5.0.17.

@alexbereznikov alexbereznikov linked a pull request Mar 20, 2024 that will close this issue
Open
@alexbereznikov
Copy link
Author

Created PR to fix the first part - #2453

@alexbereznikov alexbereznikov linked a pull request Mar 20, 2024 that will close this issue
Open
@alexbereznikov
Copy link
Author

Created PR to fix the second part - #2454

@alexbereznikov
Copy link
Author

@mbdavid Sorry but I believe this is a critical issue, in the current state v5.0.19 is not usable. I did all the research and fixes, please consider merging it.

@viveleltsi
Copy link

I agree. This fix will help me too. thank you for your work @alexbereznikov . I hope it will be merged

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
2 participants
@alexbereznikov @viveleltsi