Provider init very slow during cold start

[acorn1010]

Related issues

I couldn't find any open perf-related issues

[REQUIRED] Version info

node: 10.18.1

firebase-functions: 3.11.0

firebase-tools: 8.7.0

firebase-admin: 9.1.1

[REQUIRED] Test case

import * as functions from 'firebase-functions';

// May need to call admin#initializeApp. I left it out of this example.

const scope = {time: Date.now()};  // Only for logging purposes to help you see where the perf issue is.
const sometimesSlow = functions.firestore.document('foo/{bar}').onWrite(async (change, context) => {
  console.log('COLD STARTS ARE SLOW: ' + (Date.now() + scope.time));
});
const wrappedSometimesSlow = async(input: any, context?: any) => {
  scope.time = Date.now();
  return sometimesSlow(input, context);
};
exports.sometimesSlow = wrappedSometimesSlow;

[REQUIRED] Steps to reproduce

Write something to Firestore that matches foo/{bar} above. The path doesn't matter, and having a wildcard in the path doesn't matter.

[REQUIRED] Expected behavior

Since the above code doesn't require any sort of initialization once wrappedSometimesSlow is called, I'd expect this code to run in < 5ms. In reality, cold starts take between 900–4000+ ms. For most use cases, this initialization is unnecessary unless you need to access something like change.before.ref.firestore (it'd be nice if this returned a promise that could be lazy-loaded).

[REQUIRED] Actual behavior

Cold starts take between 900–4000+ ms. This is because a lot of things are being initialized, such as the Firestore instance (which in my benchmarks takes ~600+ ms to initialize).

I've experienced these very slow cold start times with a lot of the firebase-functions providers for different reasons. For example, the https onCall provider is slow because apps().admin.auth().verifyIdToken can take over a second to run, and the CORS preflight can add an additional 350-1200ms to cold starts.

The CORS preflight delay happens for custom domains because the Authorization header that's used by Firebase isn't one of the allowed simple request headers. The preflight delay can be overcome by monkey patching the firebase.functions(app)._url method in the client, but it'd be nice if there was an official way of doing this (or if Firebase just used simple requests for cloud function calls).

Were you able to successfully deploy your functions?

Yes.

[taeold]

Thanks for a detailed writeup @acornwall.

I'm curious though why you settled expected cold start time on <5ms. While I didn't find any public SLOs on GCF cold start time of nodejs runtime, I found that even the simplest Cloud Functions can to take ~150ms on cold start, e.g.:

exports.helloWorld = (req, res) => {
  res.send("Hello world!");
};

2020-09-09 00:17:15.579 PDT <REDACTED> Function execution started
2020-09-09 00:17:15.624 PDT <REDACTED> Function execution took 146 ms, finished with status code: 200
2020-09-09 00:17:16.864 PDT <REDACTED> Function execution started
2020-09-09 00:17:16.873 PDT <REDACTED> Function execution took 9 ms, finished with status code: 200

900–4000ms+ is a lot larger than ~150ms, but I suspect that's because of the dependency on firebase-functions library (https://cloud.google.com/functions/docs/bestpractices/tips#use_dependencies_wisely), e.g.:

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

exports.helloWorld1 = functions.firestore.document('foo/{bar}').onCreate((snap, doc) => {
  console.log("hello world");
});

2020-09-09 00:36:53.821 PDT <REDACTED> Function execution started
2020-09-09 00:36:57.044 PDT <REDACTED> hello world
2020-09-09 00:36:57.058 PDT <REDACTED> Function execution took 3238 ms, finished with status: 'ok'
2020-09-09 00:37:03.834 PDT <REDACTED> Function execution started
2020-09-09 00:37:03.840 PDT <REDACTED> hello world
2020-09-09 00:37:03.843 PDT <REDACTED> Function execution took 10 ms, finished with status: 'ok'

Again, I don't have any published data on expected cold start time for nodejs functions. Based on few articles I found on the web (https://mikhail.io/serverless/coldstarts/gcp/, https://medium.com/@duhroach/improving-cloud-function-cold-start-time-2eb6f5700f6), cold start times of 1-4 seconds doesn't seem completely out of the norm in Google Cloud Functions platform.

Do you think there are Firebase Functions specific issues that is worth digging into?

[acorn1010]

Hi @taeold, and thanks for the detailed response. The cold-start impact is just the quoted code between Date.now() and (Date.now() + scope.time). It's not for the entire startup time, and it excludes the import cost.

Importing firebase-functions adds a little bit to startup times (from my logging, I see an average of ~83ms). It's not great, but it could be worse.

The much larger low-hanging fruits are the Firebase Functions callbacks. i.e. the code that runs after helloWorld1 is called and before the callback is called in this example:
exports.helloWorld1 = functions.firestore.document('foo/{bar}').onCreate(callback);

You can modify your example by adding logging before and after your import of firebase-functions to confirm this for yourself. Here's a modification of your example to emphasize this:

console.log('Before firebase-functions.', Date.now());
const functions = require('firebase-functions');
console.log('After firebase-functions', Date.now());

const helloWorldSlowColdStart = functions.firestore.document('foo/{bar}').onCreate((snap, doc) => {
  console.log("hello world", Date.now());
});
const wrappedHelloWorld = async(snap, doc) => {
  console.log("before hello world", Date.now());
  return helloWorldSlowColdStart(snap, doc);
};
wrappedHelloWorld.run = helloWorldSlowColdStart.run;
wrappedHelloWorld.__trigger = helloWorldSlowColdStart.__trigger;
exports.helloWorld1 = wrappedHelloWorld;

NB: I haven't tested the above example, so it might need some minor adjustment.

A lot of these Firebase Functions provider cold starts are just very slow. I've taken a look at (and optimized for my own code) providers.https.onRequest and FireStore's onWrite.

I was able to get providers.https.onRequest' cold start to usually be ~15 ms (my mistake on the 5ms—it should've been 15) with a 99th percentile of 95ms by hard-coding the Google certs and updating them as they change (very hacky), but anything under 300ms average is good here since you'll need to query https://www.googleapis.com/robot/v1/metadata/x509/securetoken@system.gserviceaccount.com to get up-to-date certificates.

The line that's slow for providers.https.onRequest.ts is:

const authToken = await apps().admin.auth().verifyIdToken(idToken);

These measurements are in milliseconds and are taken between lines 423-424 and 460-461 of https://github.com/firebase/firebase-functions/blob/84433df63147d61a5330f9b8d3e5c5e4837ad658/src/providers/https.ts
My implementation w/ Google Cert hack (hardcoding certs): 15ms average, 95ms 99th percentile.
My implementation w/o Google Cert hack: 179ms average, 784ms 99th percentile.
Original implementation: 548ms average, 1367ms 99th percentile.

If warm-starts are removed (assuming <10 ms measured, though this may be overly aggressive for the implementation w/ Google Cert hack), this becomes:
My implementation w/ Google Cert hack (hardcoding certs): 23ms average, 95ms 99th percentile.
My implementation w/o Google Cert hack: 288ms average, 784ms 99th percentile.
Original implementation: 922ms average, 1367ms 99th percentile.

For functions.firestore.document('foo/{bar}').onWrite, I was able to eliminate the cold start almost entirely by re-using the Firestore snapshot parsing logic without initializing a Firestore instance. This is particularly useful for the use case where you want to copy data from Firestore events to Firebase realtime database and don't need a Firestore instance anyways.

Please let me know if you'd like me to include benchmarks for the Firestore provider or if you'd like to see how I implemented these.

Google Sheets with benchmarks: https://docs.google.com/spreadsheets/d/1vfIr3Lci3xQhlOJSHnq9ZHAT18Q6qH-HUbKn_Zd329c/edit?usp=sharing

Again, these cold start times are only measuring Firebase Function's impact (excluding the import cost) and are not indicative of the entire cold start time (which is going to be about 150ms+ as you mentioned).

[taeold]

Hey @acornwall. Sorry we'd be laying a bit dormant on this issue.

2021 update: your insights are very informative - thanks for reasoning through them with lots of details. To apply your findings to the SDK, we'll probably have to commit to a major overhaul of the SDK's internals (and a probably a major version bump).

If you are still interested in this topic and would like to help, shoot me a message at danielylee at google dot com. Think performance tuning you've made here could be something a lot of people can be interested in, and maybe we can start by sharing a blog post with the community.

Closing the issue for now since we can't commit to anything immediate to address the issue you raised here. I'll instead file an internal ticket to keep track of this discussion.

[inlined]

Some other readers may have been confused here, but the delay is not at the global scope; providers lazy load their dependencies. Instead, the delay is in the wrapper code we insert around the customer's function. This has its ups and downs. On the negative side, a preemptively warmed instance won't load the dependencies until a request hits. On the positive side, only the executing function's dependencies are loaded.

I don't see a way around the HTTP onCall delay. It's quite intentional that the SDK checks for valid tokens and rejects requests with invalid tokens. Firestore's delay has been something a few of us have wanted to look into but I haven't had the time yet. The delay is coming from the loading of the google-gax library and all the protos. I also suggested internally that not all firebase functions that listen to Firestore need to talk to Firestore and we should lazily initialize. The best way to do this is probably with Object.defineProperty so we can have a get() method that makes something that looks like a flat property actually load the SDK (essential for reverse compatibility).

You refer to "your implementation." Have you already done the work that I haven't been able to prioritize? We could build this fix together.

[taeold]

There are lots of context and history I've missed, and it feel premature for me to close the issue w/o any resolution. I'm re-opening the issue.

[acorn1010]

Hi, inlined. My implementation is pretty hacky—it was implemented just enough for my use case at the time: https://gist.github.com/acornwall/035fd5f529facc7f76996ddaf5449c0a

Example usage:

// Before (normal and slow)
const sometimesSlow = functions.firestore.document('foo/{bar}').onWrite(async (change, context) => {});

// After (fast and hacky)
const notSlow = onWrite(projectId, 'foo/{bar}', async (change, context) => {});

[inlined]

Hah. I love that you reverse engineered the __trigger annotations. Originally I hoped people could use some of these to even make compatibility shims between Google and others.

As an FYI, your code for before vs after is off. Before inherits any value from After that isn't covered by a field mask. See here

Your strategy isn't too far from what I planned. You can create a Snapshot interface (so that a real snapshot can implement it) that is hand-crafted w/o using standard proto libraries. Then the ref is a property accessor that will, on demand, load the old code path.

I'm worried about the Timestamp type that you added though. This might be the ultimate wrinkle. Exposing actual classes means that there's incompatibilities between the two libraries.

[inlined]

So I authored a pull request for a strategy that is mostly reverse compatible. Everything should work, except instanceof breaks. I'm proposing it internally, though it may be rejected. If it's accepted it will still be hidden behind a flag functions.firestore.useExperimentalProxyObjects() because we don't have confidence that it will handle every possible edge case the same as the SDK objects.

If you'd like to give it a shot, either wait for this PR to be merged or check out my branch. You can then run npm run build:pack to get a tarball. Once you have the tarball, put it in your functions directory and run npm install --save <tarball> to get the private version of the SDK and call functions.firestore.useExperimentalProxyObjects() at global scope in your functions code.

Be warned though that this should not be run in production until you can do your own thorough testing. This code is hot off the press and our tests for Firebase Functions isn't designed to test SDK compatibility.

[inlined]

@schmidt-sebastian decided to make relevant changes to the Firestore SDK itself, which means you don't even have to worry about proxy objects. Update to the next-released version of firebase-admin when that change gets upstreamed.