Is a bug? Regarding the issue of being unable to recover when the number of keys is very large

[cnjeffreyloo]

When I generate a large amount of data using Tsavorite in Garnet (with the number of keys exceeding 300 million), and then save a checkpoint and load it again, an error occurs, and I can no longer recover the original data. What could be the issue?

Here is the source code:

using System.Diagnostics;
using Tsavorite.core;

namespace large_tsavority_test;

using LongAllocator = BlittableAllocator<long, long, StoreFunctions<long, long, LongKeyComparer, DefaultRecordDisposer<long, long>>>;
using LongStoreFunctions = StoreFunctions<long, long, LongKeyComparer, DefaultRecordDisposer<long, long>>;

class Program
{
    const int DataSize = 300000000;
    // const int DataSize = 100000;

    static async Task Main()
    {
        CleanData();
        await CreateLargeData();
        await LoadDataAndVerify();
    }

    private static void CleanData()
    {
        var sw = Stopwatch.StartNew();
        Console.WriteLine("Cleaning data ...");
        if (Directory.Exists("./data"))
        {
            Directory.Delete("./data", true);
        }
        sw.Stop();
        Console.WriteLine($"  - Cleaning data done. (Elapsed: {sw.Elapsed.TotalSeconds:f2}s)");
    }

    private static TsavoriteKV<long, long, LongStoreFunctions, LongAllocator> CreateStore(bool tryRecoverLatest = false)
    {
        var settings = new KVSettings<long, long>("./data")
        {
            TryRecoverLatest = tryRecoverLatest,
            // IndexSize = 1L << 20,
            // MemorySize = 1L << 30,
            // PageSize = 1L << 20,
        };
        var store = new TsavoriteKV<long, long, LongStoreFunctions, LongAllocator>(
            settings, 
            StoreFunctions<long, long>.Create(LongKeyComparer.Instance),
            (allocatorSettings, storeFunctions) => new(allocatorSettings, storeFunctions));
        return store;
    }

    // Generate a large amount of data
    private static async Task CreateLargeData()
    {
        Console.WriteLine($"Creating large data: size:{DataSize} ...");

        // Create Tsavorite instance
        var store = CreateStore();
        using var session = store.NewSession<long, long, Empty, SimpleSimpleFunctions<long, long>>(new SimpleSimpleFunctions<long, long>());

        // Write data
        var sw = Stopwatch.StartNew();
        var lastShowProgress = 0;
        for (long i = 0; i < DataSize; i++)
        {
            //session.Upsert(i, i);
            session.BasicContext.Upsert(ref i, ref i);
            var totalSeconds = (int)sw.Elapsed.TotalSeconds;
            if (totalSeconds - lastShowProgress > 5)
            {
                // Display progress
                lastShowProgress = totalSeconds;
                var currentSpeed = i / sw.Elapsed.TotalSeconds;
                Console.WriteLine($"  - Creating progress: {i}/{DataSize} ({i * 100.0 / DataSize:f2}%) (Elapse: {totalSeconds}, Speed: {currentSpeed:f2} ops/s) ...");
            }
        }

        // Write checkpoint
        var writeCheckpointSw = Stopwatch.StartNew();
        Console.WriteLine("  - Writing checkpoint ...");
        await store.TakeFullCheckpointAsync(CheckpointType.Snapshot);
        await session.BasicContext.CompletePendingAsync();
        // store.Log.Flush(true);
        writeCheckpointSw.Stop();
        Console.WriteLine($"    - Writing checkpoint done. (Elapsed: {writeCheckpointSw.Elapsed.TotalSeconds:f2}s)");

        ShowStoreInfo(store);

        // Dispose resources
        session.Dispose();
        store.Dispose();

        var speed = DataSize / sw.Elapsed.TotalSeconds;
        Console.WriteLine($"  - All done. (Elapsed: {sw.Elapsed.TotalSeconds:f2}s, Speed: {speed:f2} ops/s)");
    }

    static async Task LoadDataAndVerify()
    {
        Console.WriteLine($"Loading data and verify: size:{DataSize} ...");

        var loadSw = Stopwatch.StartNew();
        var store = CreateStore(tryRecoverLatest: true);
        loadSw.Stop();
        Console.WriteLine($"  - Loading data done. (Elapsed: {loadSw.Elapsed.TotalSeconds:f2}s)");
        ShowStoreInfo(store);

        using var session = store.NewSession<long, long, Empty, SimpleSimpleFunctions<long, long>>(new SimpleSimpleFunctions<long, long>());
        
        // Read & verify data
        var sw = Stopwatch.StartNew();
        var lastShowProgressTime = 0;
        var lastShowErrorTime = -100;
        var errorCount = 0;
        for (long i = 0; i < DataSize; i++)
        {
            var (status, output) = session.BasicContext.Read(i);
            if (status.IsPending) 
            {
                session.BasicContext.CompletePendingWithOutputs(out var completedOutputs, true);
                // 等待结果
                for (; completedOutputs.Next(); )
                {
                    if (completedOutputs.Current.Key.Equals(i))
                    {
                        status = completedOutputs.Current.Status;
                        output = completedOutputs.Current.Output;
                        break;
                    }
                }
                completedOutputs.Dispose();
            }
            if (!status.Found)
            {
                if (sw.Elapsed.TotalSeconds - lastShowErrorTime > 5)
                {
                    lastShowErrorTime = (int)sw.Elapsed.TotalSeconds;
                    Console.WriteLine($"  - Error: key {i} not found. (Status: {status})  (ErrorCount: {errorCount})");
                }
                errorCount++;
                continue;
            }

            if (output != i)
            {
                if (sw.Elapsed.TotalSeconds - lastShowErrorTime > 5)
                {
                    lastShowErrorTime = (int)sw.Elapsed.TotalSeconds;
                    Console.WriteLine($"  - Error: key {i} value is {output}, but expect is {i}.  (ErrorCount: {errorCount})");
                }
                errorCount++;
            }
            
            var totalSeconds = (int)sw.Elapsed.TotalSeconds;
            if (totalSeconds - lastShowProgressTime > 5)
            {
                // Display progress
                lastShowProgressTime = totalSeconds;
                var currentSpeed = i / sw.Elapsed.TotalSeconds;
                Console.WriteLine($"  - Creating progress: {i}/{DataSize} ({i * 100.0 / DataSize:f2}%) (Elapse: {totalSeconds}, Speed: {currentSpeed:f2} ops/s) ...");
            }
        }

        // Write checkpoint
        await store.TakeFullCheckpointAsync(CheckpointType.Snapshot);
        await session.BasicContext.CompletePendingAsync();

        ShowStoreInfo(store);

        // Dispose resources
        session.Dispose();
        store.Dispose();

        var speed = DataSize / sw.Elapsed.TotalSeconds;
        Console.WriteLine($"  - All done. (ErrorCount: {errorCount}, Elapsed: {sw.Elapsed.TotalSeconds:f2}s, Speed: {speed:f2} ops/s)");
    }

    static void ShowStoreInfo(TsavoriteKV<long, long, LongStoreFunctions, LongAllocator> store)
    {
        var sw = Stopwatch.StartNew();

        // Get store info
        var entryCount = store.EntryCount;
        var indexSize = store.IndexSize;
        var overflowBucketCount = store.OverflowBucketCount;
        var memorySizeBytes = store.Log.MemorySizeBytes;
        sw.Stop();
        Console.WriteLine(
            $"  - Store info: EntryCount: {entryCount}, IndexSize: {indexSize}, overflowBucketCount: {overflowBucketCount}, "
            + $"memorySizeBytes: {memorySizeBytes}, (Get info elapse: {sw.Elapsed.TotalSeconds:f2}s)"
        );

    }
}

Run result:

Cleaning data ...
  - Cleaning data done. (Elapsed: 2.66s)
Creating large data: size:300000000 ...
  - Creating progress: 8255420/300000000 (2.75%) (Elapse: 6, Speed: 1375903.22 ops/s) ...
   ...
  - Creating progress: 299164185/300000000 (99.72%) (Elapse: 624, Speed: 479427.80 ops/s) ...
  - Writing checkpoint ...
    - Writing checkpoint done. (Elapsed: 25.75s)
  - Store info: EntryCount: 300000000, IndexSize: 1048576, overflowBucketCount: 42247625, memorySizeBytes: 1073741824, (Get info elapse: 12.38s)
  - All done. (Elapsed: 665.00s, Speed: 451129.16 ops/s)
Loading data and verify: size:300000000 ...
  - Loading data done. (Elapsed: 0.84s)
  - Store info: EntryCount: 7340032, IndexSize: 1048576, overflowBucketCount: 42247625, memorySizeBytes: 2097152, (Get info elapse: 0.04s)
  - Error: key 0 not found. (Status: NotFound)  (ErrorCount: 0)
Unhandled exception. System.NullReferenceException: Object reference not set to an instance of an object.
   at large_tsavority_test.Program.LoadDataAndVerify() in /data/jeffreylu/large_tsavorite_test/Program.cs:line 113
   at large_tsavority_test.Program.Main() in /data/jeffreylu/large_tsavorite_test/Program.cs:line 18
   at large_tsavority_test.Program.<Main>()

Note:

1. After recovering the data, the EntryCount is noticeably much lower, and all keys cannot be found.
2. If DataSize = 200000000, then it is normal, with no errors.

The same error also exists in FasterKV (see also microsoft/FASTER#924).

Using the Docker version of Garnet, after writing a large amount of data and restarting the service to recover the data, the same issue occurred.

Example:

docker run --rm --network=host --name garnet -v /data/garnet:/data --ulimit memlock=-1 ghcr.io/microsoft/garnet -r --storage-tier -c /data/checkpoint -l /data/log

In summary, can we consider this a bug in FasterKV and Tsavorite?