Unacceptable cold start get() performance

[mbleigh]

Environment details

• OS: Cloud Functions runtime
• Node.js version: all
• npm version: all
• @google-cloud/firestore version: all

Steps to reproduce

The first get() performed against Cloud Firestore may take multiple seconds (5-8s) to return. In a serverless environment with cold starts, this is an introduction of unacceptable latency and is additionally very difficult to mitigate or work around (since cold starts in Cloud Functions cannot be fully prevented).

Perhaps a mechanism should be added to use the REST API for simple calls while the gRPC connection is being established to avoid/mitigate this issue.

/cc @hiranya911 @samcorcos @schmidt-sebastian

[JustinBeckwith]

Greetings! Can you share how you're measuring this? It would be cool to have a consistent benchmark so we can work from the same baseline.

[mbleigh]

Filed this on behalf of @samcorcos who reached out to me -- if he's willing he can maybe share the code that's producing the issue.

[mikelehen]

FWIW- I wouldn't expect gRPC to be slower than REST for get() calls in the nodejs-firestore SDK (it might be slower in the mobile firebase SDK which uses a listener under the covers for get(), but nodejs-firestore should do a direct gRPC call).

5-8s sounds quite slow. Has this been observed recently?

[mbleigh]

Yes, within the last few days (again, @samcorcos shared .an example of this happening with me).

[samcorcos]

@mikelehen @JustinBeckwith I'm happy to share the repo and the logs with you as well :) What's a good email address for you guys?

[samcorcos]

As for the measurement, this is a screenshot from the logs:

Function execution start to first log: 0.2s
First db call start to finish: 7s
second db call start to finish: 0.1s

I initially assumed it was a cold start issue, but it looks like it's actually something to do with the DB. This is above my pay grade, so I don't know the specifics, but the function itself is pretty simple:

const onAssign = async (snap, context) => {
console.log('function start ', Date.now())
  const { userId, contactId } = context.params
  const smallestCadence = 1

  console.log('first db start ', Date.now())
  const doc = await db
    .collection('users')
    .doc(userId)
    .collection('contacts')
    .doc(contactId)
    .get()
  console.log('first db end', Date.now())

  const contact = {
    contactId,
    ...doc.data()
  }

  console.log('second db call ', Date.now())
  if (!contact.lastContact) {
    await db
      .collection('users')
      .doc(userId)
      .collection('contacts')
      .doc(contactId)
      .set({ urgency: 'red' }, { merge: true })
  } else {
    // otherwise, determine the urgency and assign
    const lastContact = moment(contact.lastContact)
    const today = moment()
    const delta = lastContact.diff(today, 'days')
    const urgency = determineUrgency(delta, smallestCadence)

    console.info(`Set urgency of user ${userId} to ${urgency}`)

    await db
      .collection('users')
      .doc(userId)
      .collection('contacts')
      .doc(contactId)
      .set({ urgency }, { merge: true })
  }
  console.log('second db end ', Date.now())
}

Currently running:

    "firebase-admin": "~6.0.0",
    "firebase-functions": "^2.1.0",

On Node 8

I first noticed this on the first call after a deploy, but I imagine it could also be an issue on cold start even if it's not soon after a deploy.

[samcorcos]

At @JustinBeckwith's request, I rewrote the query to use the googleapis node client and the issue went away.

As you can see from the screenshots below, function start to first db end took 0.5 seconds, as opposed to the version that uses the Firebase package which can take 6-10 seconds to execute the first query.

Here's the updated code:

const { google } = require('googleapis')
const firestore = google.firestore('v1beta1')

const myFunction = async (snap, context) => {
  const { userId, contactId } = context.params

  // NOTE need to export these within the function because Firebase Functions does not allow upper-case
  // variable names for some reason?
  // Error: Invalid config name onCadenceAssignToContact.GOOGLE_APPLICATION_CREDENTIALS, cannot use upper case.
  process.env.GOOGLE_APPLICATION_CREDENTIALS = './credentials/myapp-firebase-adminsdk-3jp1h-56c62c3fbd.json'
  process.env.GCLOUD_PROJECT = 'myapp'

  console.log('function start ', Date.now())

  const auth = await google.auth.getClient({
    // Scopes can be specified either as an array or as a single, space-delimited string.
    scopes: [
      'https://www.googleapis.com/auth/cloud-platform',
      'https://www.googleapis.com/auth/datastore'
    ]
  })

  console.log('first db start ', Date.now())
  // https://cloud.google.com/firestore/docs/reference/rest/v1/projects.databases.documents/get
  const name = `projects/myapp/databases/(default)/documents/users/${userId}/contacts/${contactId}`
  const result = await firestore.projects.databases.documents.get({
    name,
    auth
  })
  console.log('first db end ', Date.now())

  console.log(JSON.stringify(result.data))
}

[JustinBeckwith]

Thank you so much for testing this with the googleapis npm module. This gives us a pretty clear picture that it's something in either this module, gax, or grpc :/

[schmidt-sebastian]

We have looked at the cold start performance with the Cloud Functions team before (@laurenzlong and others). One of the changes we made is that we now lazy-load google-gax and grpc. This loading happens just before the first request is sent to the Firestore backend. Back when we did this, we were able to shave off 5-6 seconds in the module initialization time. Instead, this time is now "hidden" in the async request flow.

I don't know if there are a ton of options that we have until we can switch to the pure-JS GRPC client. The GRPC dependency is huge, and rewriting the client using a different network stack is likely out of scope for these server libraries.

[samcorcos]

@schmidt-sebastian What about the possibility of using the REST API as a fallback while gRPC is loading as @mbleigh suggested? The googleapis package doesn't have the same issue.

Perhaps a mechanism should be added to use the REST API for simple calls while the gRPC connection is being established to avoid/mitigate this issue.

[wilhuff]

"Using the REST API as a fallback while gRPC is loading" is "rewriting the client to use a different network stack" and is infeasible. Several of the APIs we expose here are based on streaming RPCs, which don't have an equivalent via REST. The only way to fix this is to make it cheaper to depend upon gRPC from Cloud Functions. That will additionally benefit all One Platform-based APIs, not just Firestore.

It turns out that google-gax has some experimental support for depending on a pure javascript version of gRPC if you set the GOOGLE_CLOUD_USE_GRPC_JS environment variable. This will work under the experimental Node 8 runtime for Cloud Functions (but not Node 6). This could help, but may not help much until google-gax breaks its dependency on the native grpc package.

In any case, the cold start issue isn't anything we have the resources to fix ourselves. The grpc-node project was essentially created to address this problem and we'll let them work through it.

[theacodes]

Hi folks, there is no actionable way this project can resolve this issue. It appears relevant bugs on other projects have been linked, so I'm going to go ahead and close this issue. You're still welcome to discuss workarounds and impact here, but tracking the resolution will happen in the other projects.

Thanks, everyone!

[schmidt-sebastian]

Note that the 1.0.2 release includes support for GRPC JS, which reduces the load time of Firestore on GCF to around 3 seconds. This can be enabled on the Node 8 runtime with the GOOGLE_CLOUD_USE_GRPC_JS flag mentioned above.

[JustinBeckwith]

@schmidt-sebastian would you be willing to post some data here? It would be super helpful.

[schmidt-sebastian]

I am not getting any reproducible results at the moment and see loading time with both GRPC and GRPC JS at around 3 to 4 seconds.

[hitchingsh]

Can someone tell me how to set the GOOGLE_CLOUD_USE_GRPC_JS environment variable in Firestore? I don't see any args for setting environment variables to firebase deploy and I don't see anywhere in the Firestore web console. Your help is very much appreciated.

[mikelehen]

@hitchingsh If you use the latest version of firebase-admin or @google-cloud/firestore, grpc-js will be used automatically. There's no need to set any environment variable.

[wilhuff]

Good news! The latest release uses grpc-js by default now.

[hitchingsh]

@mikelehen, Thanks!

[hitchingsh]

Note, its still getting a 3 second delay on my first call to the admin firestore database in node JS. Is there anyway to speed it up

const admin = require('firebase-admin');
const functions = require('firebase-functions');

var initializedFirestore = false

if (!initializedFirestore) {
  admin.initializeApp();
  initializedFirestore = true
}

const firestore = admin.firestore();

// Note, this is highly abbreviated and my actual code is a lot more 
// complex but I also get a 3 second hit after uploading the function 
// on the first call to Firestore:

firestore.collection('myCollection').doc(docId).get()

[schmidt-sebastian]

@hitchingsh Can you verify the versions that you are using? firebase-functions hasn't yet been updated to require firebase-admin version 8.x, which is the release that pulls in the smaller GRPC core (@grpc/grpc-js instead of grpc). It would help us if you can show us your output of npm list.

[hitchingsh]

With regards to the 3 second delay on my first call to the admin firestore database in node JS 8. Here's my package.json

{
"name": "functions",
"description": "Cloud Functions for Firebase",
"engines": {
"node": "8"
},
"scripts": {
"lint": "eslint .",
"serve": "firebase serve --only functions",
"shell": "firebase functions:shell",
"start": "npm run shell",
"deploy": "firebase deploy --only functions",
"logs": "firebase functions:log"
},
"dependencies": {
"firebase-admin": "^8.0.0",
"firebase-functions": "^2.3.1",
"twilio": "^3.31.1"
},
"devDependencies": {
"eslint": "^5.16.0",
"eslint-plugin-promise": "^4.1.1"
},
"private": true
}

and here's my npm list
npm-list.txt

This did catch my eye but could use your help on it
UNMET PEER DEPENDENCY [email protected]

[jamieomatthews]

I'm having basically the same issue - read to the bottom here with some hope for fix. I've manually specified [email protected] to try to fix - but I'm not sure if it's being used, or if its bundling 7.0, since thats what it seems firebase-functions 2.3.1 requires.

[schmidt-sebastian]

You have the right dependencies locally, so it should be faster than with grpc. One possibility is that the dependencies installed on GCF do not match your local dependencies. To help us look at that, it would help to get the actual version number of the SDK you are using. This is logged when you invoke setLogFunction(console.log).

Note that there might not be too much we can do if you are indeed running on @grpc/grps-js. My hope is that somehow you still are not, and that we can get you on @grpc/grps-js :)

[hitchingsh]

Ok, it says, when I do admin.firestore.setLogFunction(console.log)

Firestore (2.1.1) 2019-06-08T00:23:35.069Z Rgzqk [WriteBatch.commit]: Using transaction for commit

Is Firestore 2.1.1 the correct version of Firestore? Also, note these lines:

Firestore (2.1.1) 2019-06-08T00:23:35.069Z Rgzqk [WriteBatch.commit]: Using transaction for commit
Firestore (2.1.1) 2019-06-08T00:23:37.276Z ##### [Firestore]: Initialized Firestore GAPIC Client

It appears it took over two seconds to initialize the GAPIC Client.

[schmidt-sebastian]

@hitchingsh Thanks for getting back to us! The latest version of @google-cloud/firestore is 2.2, but there are no changes between 2.1.1 and 2.2 that affect the performance. 2.1.1 (and in fact all 2.x releases) already contains the much lighter GRPC JS networking layer. We will look further into improving startup time, but at this point, I unfortunately don't have a short term fix for you.

If you are not already initializing Firestore in the module scope, I would advise you to update your code to follow the pattern here: https://cloud.google.com/functions/docs/bestpractices/tips#performance ("Use global variables to reuse objects in future invocations"). Once a Firestore instance is initialized, you can use it across function invocations.

[joshualyon]

Is there a way to kickoff the gRPC loading without making a .get() call in Firestore?

Since App Engine has support for warmup requests, it would be great to be able to complete the loading/initialization of gRPC and other required modules as part of the warmup. That way when the first .get() call is made, everything would already be loaded and the call would return quickly as expected.

Sure, we can just make a .get() call to an arbitrary document during the warmup, but it's really just the loading/init we're after so I was curious if there was some other way to kick it off.

[mikelehen]

I don't know of one offhand. You could probably get the grpc code loaded into memory by just adding require('gprc-js') or whatever... but doing an actual get() would be a much better warmup, since it would actually start the connection to the backend, etc.

[RWOverdijk]

@transitive-bullshit Thanks for a fast reply I appreciate it!

Do you mean this?

const { Firestore } = require('@google-cloud/firestore')
const grpc = require('@grpc/grpc-js')

console.log('using gRPC via @google-cloud/firestore')
const db = new Firestore({ grpc })

And if so, would that work with updates and such as well?

[transitive-bullshit]

@RWOverdijk yes that should work as a short-term solution. Previous google peeps in this thread created a fix for the normal grpc-js which they're supposed to update this thread once it has propagated to all the node.js sdks.

Note that I'm not affiliated with google in any ways. Just trying to help out.

[RWOverdijk]

@transitive-bullshit And helping out you are! It already helps that I don't feel like an angry old man shouting at a cloud.

A quick try seems to reveal that stuff like FieldValues aren't in there. I'll give this a more serious try tomorrow. Thanks :)

[RWOverdijk]

@transitive-bullshit I got around to giving this a go. In general it appears faster but not always.

Also for some odd reason it's not doing preflight requests anymore which makes a huge difference, but also makes an equal amount of huge no sense to me.

Anyway... It's a workaround that makes things a bit better but the difference isn't always that visible.

[transitive-bullshit]

@RWOverdijk my advice is that you have to make this actionable for the google peeps.

See my previous minimal repro example https://github.com/saasify-sh/google-cloud-grpc-issue

Fork or create your own version of this with reproducible timings. Then we may be able to help figure out what you're seeing.

[xzilja]

@transitive-bullshit you seem to be very familiar with the topic, so I wanted to ask if you could explain if this fix can be somehow tested in firebase cloud functions, if yes, any chance you could provide an example?

[manwithsteelnerves]

Update: so apparently just updating @grpc/grpc-js in my package isn't enough to force google-gax to use it.. Passing the updated @grpc-grpc-js directly to Firestore resolves the issue. (updated verbose logs) 💯

const { Firestore } = require('@google-cloud/firestore')
const grpc = require('@grpc/grpc-js')

console.log('using gRPC via @google-cloud/firestore')
const db = new Firestore({ grpc })

Thank you so much @murgatroid99!

I'm assuming that once this update gets propagated to google-gax and the other Google SDKs, things will just work without having override the grpc constructor option to Firestore and other SDKs?

I tried the mentioned fix. Initially I thought it was working but doesn't seem to be. I see nearly 4secs being taken for loading firestore module alone which doesn't make it fit for a production app :|

[JustinBeckwith]

@manwithsteelnerves how are you generating this trace? I am seeing < 300ms for module load ....

[manwithsteelnerves]

I’m using ‘require-so-slow’ module to capture the trace. The above trace i got it from firebase project without any emulation.

Do you have any other profiler which can be used with functions?

[JustinBeckwith]

Hey wait, I'm the maintainer of that module 😆 That's what I used too! But on my local macbook. Did you run it inside of google cloud functions, or on your local machine?

[manwithsteelnerves]

Hey wait, I'm the maintainer of that module 😆 That's what I used too! But on my local macbook. Did you run it inside of google cloud functions, or on your local machine?

Oh nice :) The above trace one is from firebase functions. This is invoked from 256MB memory cloud function. On local it looks fine < 1sec but on real environment I see such unacceptable performance.

[manwithsteelnerves]

Also can someone suggest what could be the reason for even the function execution start is even delayed a lot? (I see around 5secs before even the exact project module loading starts). I'm using require-in-the-middle module to log the loading of dependencies.

Edit : Anyone can help on this? I see it quite common this kind of behaviour. If it logs its taking time for loading a module, I can be able to fix it. But its just idle for so long and starting which is definitely specific to the core of the product.

[manwithsteelnerves]

Today I saw something which is totally disappointing!
I tested with a very simple subscriber function and saw a delay of nearly 7secs just to start the function.

"Function execution started" message which is added automatically in the logs by the cloud functions took 7 secs.

You can see in the above message that the real function execution started after 6.9secs and then the actual project code starts(require / import code). Here, the function I have is very basic one too which leads to make me worried that I can't go production with these kind of delays.

import * as functions       from 'firebase-functions';

exports.cronTest =  functions.pubsub.topic('CronTest').onPublish(async (message, context) => {
  console.log('This is test function for testing cold start!');
});

[manwithsteelnerves]

Hey wait, I'm the maintainer of that module 😆 That's what I used too! But on my local macbook. Did you run it inside of google cloud functions, or on your local machine?

Did you get a chance to check on production?

[bcoe]

@manwithsteelnerves I could imagine require-in-the-middle and require-so-slow stepping on each other's toes, since they're both overriding require hooks.

Just to eliminate a variable, what happens if you do something like this:

const requireSoSlow = require('require-so-slow');

import * as functions       from 'firebase-functions';

exports.cronTest =  functions.pubsub.topic('CronTest').onPublish(async (message, context) => {
  console.log('This is test function for testing cold start!');
});

---

What are your local require times for firebase-functions vs., cloud functions.

[manwithsteelnerves]

---

import * as functions       from 'firebase-functions';

exports.cronTest =  functions.pubsub.topic('CronTest').onPublish(async (message, context) => {
  //console.log('This is test function for testing cold start!');
});

I tried with the above code and it took 5.6secs to finish

1. 5334.827399 ms just to start execution of function
2. 277ms for exact function code execution.

May I know the average cold start values I can expect If i'm just importing firestore module alone? This can help to decide if I can use firebase in production or not.

[rico-ocepek]

I'm also experiencing this every single day.
I did a short test from the API consumer perspective yesterday - The cold start timings in there are really just unacceptable.

• Wed, 27 May 2020 20:27:30 GMT -> 6920 ms
• Wed, 27 May 2020 20:27:54 GMT -> 348 ms
• Wed, 27 May 2020 20:29:14 GMT -> 498 ms
• Wed, 27 May 2020 20:32:15 GMT -> 519 ms
• Wed, 27 May 2020 20:36:17 GMT -> 473 ms
• Wed, 27 May 2020 20:41:21 GMT -> 707 ms
• Wed, 27 May 2020 20:51:26 GMT -> 555 ms
• Wed, 27 May 2020 21:10:28 GMT -> 5540 ms
• Wed, 27 May 2020 21:11:28 GMT -> 604 ms
• Wed, 27 May 2020 21:13:39 GMT -> 424 ms
• Wed, 27 May 2020 21:29:35 GMT -> 482 ms
• Wed, 27 May 2020 21:36:30 GMT -> 319 ms
• Thu, 28 May 2020 09:33:48 GMT -> 5016 ms

Especially the last timing blows my mind, that's my auth middleware responding with 403 - no Firestore calls whatsoever, just verifying whether the id token is valid and it takes 5 seconds! 🤯

[RWOverdijk]

I don't know if this is useful to anyone, but I'm moving everything to app engine, this gives more control and might help with performance. It doesn't solve the actual issue, of course, but it might be a workaround to get the performance needed.

If this is a dumb/unhelpful comment let me know, I can delete it.

[rico-ocepek]

@RWOverdijk Let me know if that improves anything - I'm also considering just switching to a "dedicated" Node instance that gives me full control

[rico-ocepek]

Here's the log of the function call that took 5016ms from an API consumer perspective.
The log says the execution only took 1073ms so as @manwithsteelnerves pointed out there must be a 4 second delay even before the "Function execution started" message is printed.

1073ms is something I would consider to be ok for a cold start and even that is still far from the warm ~500ms

[bcoe]

I have created the following script for people to test module load times during cold starts:

index.js:

const requireSoSlow = require('require-so-slow');
const shim = require('require-so-slow/build/src/shim')

require('@google-cloud/firestore')

let events;
exports.main = async (req, res) => {
  if (!events) {
    events = shim.getAndClearEvents()
  }
  res.set('Access-Control-Allow-Origin', '*');
  res.status(200).send(events);
}

In my own testing, I found that they're fairly dependent on the amount of memory allocated to the cloud function (which stands to reason):

256MB saw around 1.5 seconds fairly consistently:

512MB ~750ms:

1GB ~400ms

---

I'm pretty sure that the variable times in cold starts are no longer attributable to our client libraries (_the original culprit was the grpc module, which we moved off of earlier this year).

If folks are seeing significant variation in cold start times, I think there's a good chance it's related to bootstrapping in GCF prior to the time that user code executes.

If this is the case, I think we'd do better to open a public issue on the Cloud Function product (which I can help make sure gets to the appropriate folks).

[Lucas-Geitner]

Hello everyone and thank you @bcoe, i’m wondering the timing for a 2GB function and also ask you of you would you recommand as a workaround to set every fonction as 1GB !
Thanks a lots for all you work !

[manwithsteelnerves]

1. 5334.827399 ms just to start execution of function

@bcoe Thanks for the insights. Can you please explain what could be the reason for such a delayed function start? Should I consider 5.3 secs as total time it took for just bootstrapping GCF?

[RWOverdijk]

So, I've successfully moved my stuff to app engine to test and the initial cold boot is still around 4 seconds, but now this only happens once because I've set my min instances to 1, it's a lot faster now. Also because I've limited my max instances and tweaked my target_cpu_utilization and max_concurrent_requests it's a lot faster. It no longer (wrongly) thinks it needs to scale up.

So now my schedulers and triggers are deployed to firebase functions and my api has been deployed to app engine.

Again, not a solution, but for me at least a workaround I can live with.

[bcoe]

Can you please explain what could be the reason for such a delayed function start? Should I consider 5.3 secs as total time it took for just bootstrapping GCF?

I think I will need to open a ticket with the GCF folks (early next week) and start a conversation around this. I'm not sure what's happening in that initial 5 seconds, and I think it's good to put on their radar.

[bcoe]

As promised, I've opened an issue on the Cloud Functions issue tracker:

https://issuetracker.google.com/issues/158014637

I'm closing and locking this issue in favor of this new public thread. If you feel I've missed any pertinent details, please update it accordingly.

I will make sure this new issue is brought to the GCF team's attention.