timeout reading & writing data in firebase firestore

Question

i'm encountering a Google::Cloud::DeadlineExceededError error when creating a document in Firebase Cloud Firestore using the ruby client.

Similar code has been working flawlessly up to this point. I've never seen a timeout before today, so i'm quite confused what could be going wrong.

other troubleshooting i've done:

1. i've updated to a pay-as-you-go Firestore plan, and i have verified that I am not exceeding any quotas. (So if this is rate-limiting it's some limit which isn't readily visible.)
2. the status page doesn't show any issues with Firestore currently. (10/24/2019)

has anyone run into similar behavior - an app is working fine, and then suddenly Firestore begins timing out?

i have a guess that perhaps i've triggered some rate-limiting, because this has only begun today when i've started hitting firestore with increased amounts of traffic. (trying to load test as i get closer to launching the app in production.) But I have zero actual evidence that this is the reason.

# bin/load-test
require "thor"

class LoadTest < Thor
  desc "setup", "set up a game for load testing"
  method_option :game, type: :string, required: true, aliases: '-g'
  method_option :player_count, type: :numeric, required: true, aliases: '-c'
  def setup
    log = Logger.new($stdout, level: Logger::DEBUG)
    root_dir = Pathname.new(File.expand_path('../..', __FILE__))
    Google::Cloud::Firestore.configure do |config|
      config.credentials = root_dir.join('firebase-credentials.json').to_s
    end

    game = db.doc("games/#{options[:game]}")

    options[:player_count].times do
      player_id = SecureRandom.hex
      log.debug "creating player #{player_id}"

      # =====> this is line 47 in the actual file. this is where the timeout happens.
      game.collection('players').doc(player_id).set({is_active: true})

    end

    log.info "created #{options[:player_count]} player records."
  end
end

LoadTest.start

$ bin/load-test setup --game 20191014-test-game --player-count 200
D, [2019-10-14T12:49:07.562328 #85721] DEBUG -- : creating player 10d81b445239d94e9d9f047ae3eee952
Traceback (most recent call last):
    23: from bin/load-test:129:in `<main>'
    22: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/base.rb:466:in `start'
    21: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
    20: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
    19: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
    18: from bin/load-test:44:in `setup'
    17: from bin/load-test:44:in `times'
    16: from bin/load-test:47:in `block in setup'
    15: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/document_reference.rb:322:in `set'
    14: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/client.rb:582:in `batch'
    13: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/batch.rb:403:in `commit'
    12: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:159:in `commit'
    11: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:208:in `execute'
    10: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:160:in `block in commit'
     9: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/v1/firestore_client.rb:846:in `commit'
     8: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-gax-1.7.1/lib/google/gax/api_callable.rb:260:in `block in create_api_call'
     7: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-gax-1.7.1/lib/google/gax/api_callable.rb:230:in `block in create_api_call'
     6: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-gax-1.7.1/lib/google/gax/api_callable.rb:401:in `block in add_timeout_arg'
     5: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/grpc-1.24.0-universal-darwin/src/ruby/lib/grpc/generic/client_stub.rb:171:in `block in request_response'
     4: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/grpc-1.24.0-universal-darwin/src/ruby/lib/grpc/generic/interceptors.rb:170:in `intercept!'
     3: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/grpc-1.24.0-universal-darwin/src/ruby/lib/grpc/generic/client_stub.rb:172:in `block (2 levels) in request_response'
     2: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/grpc-1.24.0-universal-darwin/src/ruby/lib/grpc/generic/active_call.rb:377:in `request_response'
     1: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/grpc-1.24.0-universal-darwin/src/ruby/lib/grpc/generic/active_call.rb:181:in `attach_status_results_and_complete_call'
/Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/grpc-1.24.0-universal-darwin/src/ruby/lib/grpc/generic/active_call.rb:31:in `check_status': 4:Deadline Exceeded (GRPC::DeadlineExceeded)
    16: from bin/load-test:129:in `<main>'
    15: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/base.rb:466:in `start'
    14: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
    13: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
    12: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
    11: from bin/load-test:44:in `setup'
    10: from bin/load-test:44:in `times'
     9: from bin/load-test:47:in `block in setup'
     8: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/document_reference.rb:322:in `set'
     7: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/client.rb:582:in `batch'
     6: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/batch.rb:403:in `commit'
     5: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:159:in `commit'
     4: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:208:in `execute'
     3: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:160:in `block in commit'
     2: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/v1/firestore_client.rb:846:in `commit'
     1: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-gax-1.7.1/lib/google/gax/api_callable.rb:259:in `block in create_api_call'
/Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-gax-1.7.1/lib/google/gax/api_callable.rb:264:in `rescue in block in create_api_call': GaxError RPC failed, caused by 4:Deadline Exceeded (Google::Gax::DeadlineExceededError)
    13: from bin/load-test:129:in `<main>'
    12: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/base.rb:466:in `start'
    11: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
    10: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
     9: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
     8: from bin/load-test:44:in `setup'
     7: from bin/load-test:44:in `times'
     6: from bin/load-test:47:in `block in setup'
     5: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/document_reference.rb:322:in `set'
     4: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/client.rb:582:in `batch'
     3: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/batch.rb:403:in `commit'
     2: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:159:in `commit'
     1: from /Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:207:in `execute'
/Users/alex/.rvm/rubies/ruby-2.6.3/lib/ruby/gems/2.6.0/gems/google-cloud-firestore-1.1.0/lib/google/cloud/firestore/service.rb:211:in `rescue in execute': 4:Deadline Exceeded (Google::Cloud::DeadlineExceededError)

Answer 1

i believe the issue was writing much too frequently to a single document. i ended up deleting the containing collection and re-creating it. i've been following the "max 1 update/sec" rule since then and haven't had further problems.

https://cloud.google.com/firestore/docs/best-practices#updates_to_a_single_document