CODEWITHSUNDEEP
javascriptnode.jsfirebasegoogle-cloud-firestoregoogle-cloud-functions
Amy
Amy

Reputation: 419

Firestore in cloud function takes a few minutes to initialize and make first requests

For this simple Firestore query run on Cloud Function, it always takes a long time if we haven't call it for a while and need to create a new client connection (longest ever been was 100+ seconds)

Below is the minimum reproducible index.ts and detailed log. I tried using both admin.firestore() and new Firestore({ grpc }) and got similar result. 

import {https, config} from 'firebase-functions';
import * as admin from "firebase-admin";
const { Firestore } = require('@google-cloud/firestore');
const grpc = require('@grpc/grpc-js');

let initialized = false;

exports.timeQuery = https.onRequest(async (req:any, res) => {
        res.json({received: true});

    if (!initialized) {
      admin.initializeApp(config().firebase);
      admin.firestore.setLogFunction(console.log);
      initialized = true;
    }
    // using gRPC
    console.log('using gRPC via @google-cloud/firestore')
    const db = new Firestore({ grpc });
    // using admin node SDK
    // const db = admin.firestore();

    await db.collection("debugCollection")
        .doc("debug")
        .get();
    }
  );

I enabled debug logging in Firestore and found it took 47 seconds to initialized Firestore GAPIC Client. 

Firestore (3.7.5) 2020-05-04T20:37:23.541Z ##### [Firestore]: Initialized Firestore GAPIC Client
  1:36:36.054 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:36:36.054Z peRnr [ClientPool.acquire]: Creating a new client

and between sending requests and receiving query response, it took another 35 seconds.

Firestore (3.7.5) 2020-05-04T20:38:00.139Z peRnr [Firestore.requestStream]: Received response: {"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1588624676","nanos":86619000},"missing":"projects/xxxxxxxx-my-project-id/databases/(default)/documents/debugCollection/debug","result":"missing"}
  1:37:25.141 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:37:25.141Z peRnr [Firestore.requestStream]: Sending request: {"database":"projects/xxxxxxxx-my-project-id/databases/(default)","documents":["projects/xxxxxxxx-my-project-id/databases/(default)/documents/debugCollection/debug"]}

Here is the details logs.


  1:38:05.440 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:38:05.440Z peRnr [Firestore.getAll_]: Received 1 results
  1:38:05.240 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:38:05.240Z peRnr [Firestore._initializeStream]: Received stream end
  1:38:00.340 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:38:00.340Z peRnr [Firestore.getAll_]: Document missing: projects/xxxxxxxx-my-project-id/databases/(default)/documents/debugCollection/debug
  1:38:00.141 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:38:00.140Z peRnr [Firestore._initializeStream]: Releasing stream
  1:38:00.141 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:38:00.139Z peRnr [Firestore.requestStream]: Received response: {"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1588624676","nanos":86619000},"missing":"projects/lovecaster-staging/databases/(default)/documents/debugCollection/debug","result":"missing"}
  1:37:25.141 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:37:25.141Z peRnr [Firestore.requestStream]: Sending request: {"database":"projects/xxxxxxxx-my-project-id/databases/(default)","documents":["projects/xxxxxxxx-my-project-id/databases/(default)/documents/debugCollection/debug"]}
  1:37:25.140 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:37:25.140Z peRnr [ClientPool.acquire]: Re-using existing client with 100 remaining operations
  1:37:24.440 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:37:24.440Z ##### [Firestore.initializeIfNeeded]: Detected project ID: xxxxxxxxxxx-my-projectID
  1:37:23.541 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:37:23.541Z ##### [Firestore]: Initialized Firestore GAPIC Client
  1:36:36.054 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:36:36.054Z peRnr [ClientPool.acquire]: Creating a new client
  1:36:36.052 PM
  timeQuery
  Firestore (3.7.5) 2020-05-04T20:36:36.051Z ##### [Firestore]: Initialized Firestore
  1:36:36.050 PM
  timeQuery
  using gRPC via @google-cloud/firestore
  1:36:36.043 PM
  timeQuery
  Function execution took 54 ms, finished with status code: 200
  1:36:35.989 PM
  timeQuery
  Function execution started

And node package versions: "firebase-admin": "^8.11.0", "@grpc/grpc-js": "0.8.1", "@google-cloud/firestore": "3.7.5",

Upvotes: 1

Views: 799

Answers (1)

Doug Stevenson
Doug Stevenson

Reputation: 317828

Your function is behaving this way because you're sending the response before all the work is complete. According to the documentation, the function is terminated immediately after the response is sent. Any other work after that might not finish correctly. So, your call to res.json({received: true}); should be the very last thing in the function.

If you want your function to instead send a response immediately to the client, and continue to do work outside of that, you will not be able to do that with a single HTTP function. You will instead have to offload that work to another service or function. It's common to send a message to a pubsub function to have it pick up in the background where the first function left off.

Upvotes: 1

Related Questions