google-cloud-dotnet: Firestore: The datastore operation timed out, or the data was temporarily unavailable

Environment details

OS: Tested on both Linux and Windows 10
.NET version: .Net Core 2.0
Package name and version: Google.Cloud.Firestore, Version 1.1.0 (latest stable release)

Steps to reproduce

Fails to query when the property happens to be boolean, works fine if the property is string for example
Tested on Firestore Emulator with boolean property and it works just fine.
Tested the same code base running on .Net Core in Linux Container in GCP Kubernetes and it timesout. Tried connecting to the GCP Firestore from local debuger (windows 10) as well without much success.

       CollectionReference FoosRef = FirestoreDb.Collection(FooKind);
        Query query = FoosRef.WhereEqualTo("IsGoodFoo", true);
        // QuerySnapshot querySnapshot = await query.Offset(offset).GetSnapshotAsync();
       // Searching for String property works. 
        // Query query = FoosRef.WhereEqualTo("FooName", "p,ezbnR33GU_");
        QuerySnapshot querySnapshot = await query.GetSnapshotAsync();
        DocumentSnapshot documentSnapshot = querySnapshot.Documents.FirstOrDefault();

In the interim is there any other way to query for Boolean property with Offset to skip, please suggest.

Stack Trace:

Grpc.Core.RpcException: Status(StatusCode=Unavailable, Detail="The datastore operation timed out, or the data was temporarily unavailable.")
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Grpc.Core.Internal.ClientResponseStream`2.<MoveNext>d__5.MoveNext() in T:\src\github\grpc\src\csharp\Grpc.Core\Internal\ClientResponseStream.cs:line 61
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Linq.AsyncEnumerable.<ForEachAsync_>d__174`1.MoveNext() in D:\a\1\s\Ix.NET\Source\System.Interactive.Async\ForEach.cs:line 141
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Google.Cloud.Firestore.Query.<GetSnapshotAsync>d__54.MoveNext() in T:\src\github\google-cloud-dotnet\releasebuild\apis\Google.Cloud.Firestore\Google.Cloud.Firestore\Query.cs:line 619
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at FooLib.Library.FirestoreMappings.FooFirestore.<GetNextUnparsedFooInfo>d__4.MoveNext() in C:\Foo\FooLibFirestore\FooLib.Library\FirestoreMappings\FooFirestore.cs:line 51
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at FooLib.Library.Repositories.FooRepository.<GetNextUnparsedFooInfo>d__9.MoveNext() in C:\Foo\FooLibFirestore\FooLib.Library\Repositories\FooRepository.cs:line 102
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at FooLib.WebApi.Controllers.FoosController.<GetNextUnparsedFooInfo>d__8.MoveNext() in C:\Foo\FooLibFirestore\FooLib.WebApi\Controllers\FoosController.cs:line 83
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at lambda_method(Closure , Object )
   at Microsoft.Extensions.Internal.ObjectMethodExecutorAwaitable.Awaiter.GetResult()
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.<InvokeActionMethodAsync>d__12.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.<InvokeNextActionFilterAsync>d__10.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.Rethrow(ActionExecutedContext context)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.<InvokeInnerFilterAsync>d__14.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.<InvokeNextResourceFilter>d__22.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Rethrow(ResourceExecutedContext context)
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.<InvokeFilterPipelineAsync>d__17.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.<InvokeAsync>d__15.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Builder.RouterMiddleware.<Invoke>d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.<Invoke>d__7.MoveNext()

Making sure to follow these steps will guarantee the quickest resolution possible.

Thanks!

About this issue

Original URL
State: closed
Created 4 years ago
Reactions: 1
Comments: 24

Most upvoted comments

Okay, I’ve now had time to put together a complete program, which is shown below. It shows three ways of fetching the query results:

Using the StreamAsync method. If you’re using C# 8 and can depend on the 2.0.0-beta01 or 2.0.0-beta02 versions, this is the simplest option to use (with caveats)
Executing queries multiple times, using a DocumentSnapshot as a cursor
Executing queries multiple times, using an offset

Results:

StreamAsync worked well to start with, fetching 210K records in just over a minute - but it then timed out. I’m not entirely sure why; I suspect something somewhere is asserting a one minute timeout, but I don’t know what.
Querying with cursors: this worked very well, fetching nearly as fast as streaming, but completing - it counted 910183 items in 330s
Querying with offsets: this slowed down really quickly. I stopped it after a while - after five minutes it had only counted 60,000 items, and was getting slower and slower

Increasing the limit (to perform fewer queries) would no doubt help make the offset approach work better, but using cursors is clearly better. If your code wouldn’t make it easy to use DocumentSnapshot, you can create a cursor in other ways, but it’ll take more work. (You’ll need to specify that you’re ordering by document ID, then specify the document ID as the cursor.)

I’m going to close this issue now as I believe I’ve addressed everything - please add a comment if you need more help though.

using Google.Cloud.Firestore;
using System;
using System.Diagnostics;
using System.Linq;
using System.Threading.Tasks;

class Program
{
    static async Task Main(string[] args)
    {
        var db = FirestoreDb.Create(args[0]);

        // Note: comment this out after the first run! 
        // It actually failed for me due to too much contention, but only after it had written about 900K documents.
        var collection = db.Collection("Issue4561-attempt2");

        await PopulateCollectionAsync(collection);
        await CountViaStreaming(collection);
        await CountViaCursors(collection);
        await CountViaOffsets(collection);
    }

    static async Task CountViaStreaming(CollectionReference collection)
    {
        Console.WriteLine("Counting using query streaming");
        var stopwatch = Stopwatch.StartNew();
        int count = 0;
        var stream = collection.WhereEqualTo("Include", true).StreamAsync();
        await foreach (var item in stream)
        {
            count++;
            MaybeLogCount(count);
        }
        stopwatch.Stop();
        Console.WriteLine($"Counted {count} items in {(int) stopwatch.Elapsed.TotalSeconds}s");
    }

    static async Task CountViaCursors(CollectionReference collection)
    {
        Console.WriteLine("Counting using cursors");
        int limit = 1000;
        var query = collection.WhereEqualTo("Include", true).Limit(limit);
        var stopwatch = Stopwatch.StartNew();
        int count = 0;

        DocumentSnapshot lastDocument = null;
        while (true)
        {
            var queryWithCursor = lastDocument is null ? query : query.StartAfter(lastDocument);
            var querySnapshot = await queryWithCursor.GetSnapshotAsync();
            foreach (var document in querySnapshot)
            {
                count++;
                MaybeLogCount(count);
                lastDocument = document;
            }
            if (querySnapshot.Count != limit)
            {
                break;
            }
        }
        stopwatch.Stop();
        Console.WriteLine($"Counted {count} items in {(int) stopwatch.Elapsed.TotalSeconds}s");
    }

    static async Task CountViaOffsets(CollectionReference collection)
    {
        Console.WriteLine("Counting using offsets");
        int limit = 1000;
        var query = collection.WhereEqualTo("Include", true).Limit(limit);
        var stopwatch = Stopwatch.StartNew();
        int count = 0;

        while (true)
        {
            var queryWithOffset = query.Offset(count);
            var querySnapshot = await queryWithOffset.GetSnapshotAsync();
            foreach (var document in querySnapshot)
            {
                count++;
                MaybeLogCount(count);
            }
            if (querySnapshot.Count != limit)
            {
                break;
            }
        }
        stopwatch.Stop();
        Console.WriteLine($"Counted {count} items in {(int) stopwatch.Elapsed.TotalSeconds}s");
    }

    static void MaybeLogCount(int count)
    {
        if (count % 10000 == 0)
        {
            Console.WriteLine($"{DateTime.UtcNow:HH:mm:ss} Fetched {count} items");
        }
    }

    static async Task PopulateCollectionAsync(CollectionReference collection)
    {
        // Execute 100 parallel threads, each inserting 10,000 items in batches of 100.
        var tasks = Enumerable.Range(0, 100)
            .Select(chunk => InsertChunkAsync(chunk))
            .ToList();

        await Task.WhenAll(tasks);

        async Task InsertChunkAsync(int chunk)
        {
            for (int batch = 0; batch < 100; batch++)
            {
                var writeBatch = collection.Database.StartBatch();
                for (int i = 0; i < 100; i++)
                {
                    var id = i + (batch * 100) + (chunk * 10_000);
                    bool included = id % 1000 != 0;
                    var item = new { Name = $"Entry {i}", ItemId = id, Include = included };
                    writeBatch.Create(collection.Document(), item);
                }
                await writeBatch.CommitAsync();
                Console.WriteLine($"Completed batch {chunk} / {batch}");
            }
        }
    }
}

jskeet on Mar 18, 2020

Note: if your app is something new to help with the impact of the current health emergency, let me know and I’ll try to look tonight. Otherwise, it’ll be tomorrow (UK time).

jskeet on Mar 17, 2020

Thanks for the report - I’ll look into it tomorrow.

jskeet on Mar 16, 2020