Lazy Firestore initialization using Firebase admin is extremely slow in Firebase function compared to direct Firestore object init

[hakimio]

Lazy initialization of Firestore using the code below results in cold start of ~5 seconds (256MB function):

import * as firebase from 'firebase-admin';
import {Firestore} from '@google-cloud/firestore';

const getApp = (): firebase.app.App => {
    if (!firebase.apps?.length) {
        firebase.initializeApp();
    }

    return firebase.apps[0];
};

let database: Firestore;

const getDatabase = (): Firestore => {
    if (!datatabase) {
        database = getApp().firestore();
    }

    return database;
};

While the following code only takes ~2 seconds (256MB function cold start):

import {Firestore} from '@google-cloud/firestore';

let database: Firestore;

const getDatabase = (): Firestore => {
    if (!datatabase) {
        database = new Firestore();
    }

    return database;
};

Is it because of firebase admin package size or initializeApp() doing some heavy lifting?

Environment

• Firebase SDK version: 8.1.1
• Firebase Product: function, firestore, firebase admin
• Node.js version: 12
• "firebase": "8.1.1",
  "firebase-admin": "9.4.1",
  "firebase-functions": "3.12.0",
  "firebase-tools": "^8.16.2"
  "@google-cloud/firestore": "4.7.1"

[google-oss-bot]

I found a few problems with this issue:

• I couldn't figure out how to label this issue, so I've labeled it for a human to triage. Hang tight.
• This issue does not seem to follow the issue template. Make sure you provide all the required information.

[hiranya911]

initializeApp() doesn't do any expensive work. It's just setting up some in-memory structures (no rpc or file system access). I don't see any timing instrumentation in the above code samples. How did you determine the cold start latencies?

Update: Actually, initializeApp() may be accessing file system in the Cloud Functions environment due to the Functions SDK setting the FIREBASE_CONFIG environment variable. But a ~3s extra overhead is still quite egregious.

[hiranya911]

Tested your code samples locally with some added timing instrumentation (also corrected some typos in your code). Here are the running times from several runs:

Running time in milliseconds for 3 runs each:

func1 (fireabse-admin + firestore): 190.71, 188.49, 195.69
func2 (firestore): 177.21, 176.95, 183.07

The extra overhead is about 10-20ms which is perfectly reasonable. Here are my test programs:

// func1.ts
import * as firebase from 'firebase-admin';

import { timeit } from './timeit';

const getApp = (): firebase.app.App => {
  if (firebase.apps.length === 0) {
    firebase.initializeApp();
  }

  return firebase.apps[0];
};

let database: firebase.firestore.Firestore;

const getDatabase = (): firebase.firestore.Firestore => {
  if (!database) {
    database = getApp().firestore();
  }

  return database;
};

const millis = timeit(getDatabase);
console.log(`Time elapsed: ${millis} ms`);

// func2.ts
import { Firestore } from '@google-cloud/firestore';

import { timeit } from './timeit';

let database: Firestore;

const getDatabase = (): Firestore => {
  // Lazy load the Firestore module here so we have a better comparison with firebase-admin.
  const _Firestore = require('@google-cloud/firestore');
  if (!database) {
    database = new _Firestore();
  }

  return database;
};

const millis = timeit(getDatabase);
console.log(`Time elapsed: ${millis} ms`);

// timeit.ts
export function timeit(fn: () => any): number {
  const hrstart = process.hrtime();
  fn();
  const hrend = process.hrtime(hrstart);
  return hrend[0] * 1000.0 + hrend[1] / 1000000.0
}

I'd recommend adding some similar instrumentation to your functions, and try to ascertain where the extra overhead is.

[hakimio]

@hiranya911 There are no issues when running locally on an emulator. The issue is when running the code on actual Firebase function and doing cold start.
Anyway, I'll test it tomorrow with timing functions.

[hiranya911]

There are no issues when running locally on an emulator. The issue is when running the code on actual Firebase function and doing cold start.

I understand. But if there is a fundamental performance issue in the SDK, I'd expect the numbers to reflect it regardless of the runtime environment.

I also just tested the following function in the prod GCF environment:

import * as functions from 'firebase-functions';
import * as admin from 'firebase-admin';

import { timeit } from './timeit';

const init = timeit(() => admin.initializeApp());

export const firestoreTimer = functions.https.onRequest((request, response) => {
  const db = timeit(() => admin.firestore());
  response.send(`Init: ${init} ms; Firestore: ${db} ms`);
});

Here are some cold start times I observed when invoking the above via curl (total time measured using the time utility on the client):

Init: 4.647919 ms; Firestore: 838.837888 ms (3.165s total)
Init: 5.3486 ms; Firestore: 1117.770407 ms (3.455s total)
Init: 2.048936 ms; Firestore: 984.955321 ms (4.582s total)

According to this initializeApp() is quite fast, with the Firestore initialization taking around 1 second in each case.

[hiranya911]

I've also tested the following function in GCF:

import * as functions from 'firebase-functions';

import { timeit } from './timeit';

export const directFirestoreTimer = functions.https.onRequest((request, response) => {
  const db = timeit(() => loadFirestore());
  response.send(`Load Firestore: ${db} ms`);
});

function loadFirestore() {
  const Firestore = require('@google-cloud/firestore');
  return new Firestore();
}

Cold start latencies:

Load Firestore: 2670.608427 ms (3.169s total)
Load Firestore: 639.81416 ms (2.520s total)
Load Firestore: 1217.440628 ms (3.541s total)

Here the actual Firestore load times are quite variable (and high), but the total response times aren't that different from the results observed with firebase-admin earlier.

[hakimio]

Ok, made some simple tests on local emulator and on Firebase function.

Code tested:

import * as admin from 'firebase-admin';
import * as functions from 'firebase-functions';

const timeit = async (fn: () => any): Promise<number> => {
    const hrstart = process.hrtime();
    await Promise.resolve(fn());
    const hrend = process.hrtime(hrstart);

    return hrend[0] * 1000.0 + hrend[1] / 1000000.0;
};

export const adminFirestoreTest = functions.region('europe-west3').https.onRequest(
    async (request, response) => {
        const init = await timeit(() => admin.initializeApp());
        const db = await timeit(() => admin.firestore());

        response.send(`Init: ${init} ms; Firestore: ${db} ms`);
    }
);

const loadFirestore = async () => {
    const {Firestore} = await import('@google-cloud/firestore');

    return new Firestore();
};

export const firestoreTest = functions.region('europe-west3').https.onRequest(
    async (request, response) => {
        const db = await timeit(() => loadFirestore());

        response.send(`Load Firestore: ${db} ms`);
    }
);

Local emulator results:

==== Admin ====

~1.7s total

Init: 69.893499 ms; Firestore: 4.468499 ms
Init: 66.3188 ms; Firestore: 5.535301 ms
Init: 67.734801 ms; Firestore: 4.5722 ms
Init: 64.162401 ms; Firestore: 3.9332 ms
Init: 62.119601 ms; Firestore: 4.8441 ms
Init: 64.4821 ms; Firestore: 3.939701 ms

==== Firestore ====

~1.6s total

Load Firestore: 1.805 ms
Load Firestore: 1.446899 ms
Load Firestore: 1.72 ms
Load Firestore: 1.7332 ms
Load Firestore: 1.3122 ms

Firebase 256MB function cold start (function region: europe-west3, I am located in Denmark):

==== Admin ====

Total time varies a lot from ~80ms to ~200ms

Init: 2.348946 ms; Firestore: 79.578141 ms
Init: 2.20023 ms; Firestore: 5.142579 ms
Init: 2.01853 ms; Firestore: 4.475827 ms
Init: 2.177506 ms; Firestore: 4.712966 ms
Init: 2.248021 ms; Firestore: 88.080317 ms
Init: 88.321087 ms; Firestore: 4.799155 ms
Init: 2.509588 ms; Firestore: 5.65283 ms

==== Firestore ====

Total response time from ~60ms to ~200ms

Load Firestore: 1.323738 ms
Load Firestore: 1.204957 ms
Load Firestore: 1.248251 ms
Load Firestore: 1.252465 ms
Load Firestore: 1.301454 ms
Load Firestore: 0.992063 ms
Load Firestore: 1.088223 ms

While the difference is not 3s it still shows that ES6 dynamic import performs much better compared to loading Firestore using Firebase admin.

[hiranya911]

Are you sure that above numbers reflect cold start latencies? They look a lot like what you'd see after a cold start event. From my test cloud functions (256 MB, us-central-1):

==== Admin ====

Firestore: 815.90312 ms <<-- Cold start
Firestore: 0.090398 ms
Firestore: 0.050633 ms
Firestore: 0.045826 ms

==== Firestore ====

Load Firestore: 1030.398159 ms <<-- Cold start
Load Firestore: 0.187291 ms
Load Firestore: 0.088692 ms
Load Firestore: 0.090446 ms

Notice that your numbers are closer to my non-cold start readings than the cold start readings.

Assuming your test methodology is correct, I still don't see a cause to be concerned. Even if the individual components take slightly different times, the total response time seems to be in the same range regardless of the choice of API. Of course firebase-admin will register slightly higher latencies (10s of ms) due to the overhead of loading one additional package.

Quite an interesting observation with await import(). Chances are that is actually a more efficient way of loading dependencies, but not by much. In most cases the speed up seems to be only 3-4 ms (perhaps you can also test with require() for comparison). Also, unfortunately our admin.firestore() and App.firestore() APIs are intended to be blocking, so we cannot use this feature in the SDK.

All things considered I don't see any immediate action items for our implementation. Unless you have any more test results to the contrary, I'll close this issue.

[hakimio]

You are right - the numbers do look strange for cold starts. I was redeploying the functions between invocations which I assumed would cause cold starts, but maybe something was still cached. On Monday I will test it again by deleting the functions, redeploying and then invoking them again.

If you can see measurable performance difference between ES asynchronous await import() and synchronous Node require(), I would suggest introducing new methods like initializeAppAsync() and loadFirestoreAsync() which would return Promise. Since minimum node requirement for the admin library is v10, using await import() shouldn't be an issue.

[hakimio]

Ok, I have repeated my test. Now I can say with 100% certainty that the following are cold start times.

Results for previously posted code:

==== Firestore ====

Load Firestore: 1.218105 ms
Total request time: 359 ms

==== Admin ====

Init: 93.49407 ms; Firestore: 3.944983 ms
Total request time: 406 ms

I have also tested a slightly updated version of the code to make it a bit more realistic. This time it also retrieves a single Firestore document by uid.

import * as admin from 'firebase-admin';
import * as functions from 'firebase-functions';

const timeit = async (fn: () => any): Promise<number> => {
    const hrstart = process.hrtime();
    await Promise.resolve(fn());
    const hrend = process.hrtime(hrstart);

    return hrend[0] * 1000.0 + hrend[1] / 1000000.0;
};

export const adminFirestoreTest = functions.region('europe-west3').https.onRequest(
    async (request, response) => {
        let firestore;

        const init = await timeit(() => admin.initializeApp());
        const db = await timeit(() => firestore = admin.firestore());
        const user = await timeit(() => getUser(firestore));

        response.send(`Init: ${init} ms; Firestore: ${db} ms; Get user: ${user} ms`);
    }
);

const loadFirestore = async () => {
    const {Firestore} = await import('@google-cloud/firestore');

    return new Firestore();
};

const getUser = async (firestore) => {
    await firestore.collection('users')
        .doc('some-user-uid')
        .get();
};

export const firestoreTest = functions.region('europe-west3').https.onRequest(
    async (request, response) => {
        let firestore;

        const db = await timeit(async () => firestore = await loadFirestore());
        const user = await timeit(() => getUser(firestore));

        response.send(`Load Firestore: ${db} ms; Get user: ${user} ms`);
    }
);

RESULTS

==== Admin ====

Init: 2.142496 ms;    Firestore: 87.567422 ms;   Get user: 1609.4270000000001 ms   Total: 1.953 s
Init: 2.015701 ms;    Firestore: 86.302078 ms;   Get user: 1510.718366 ms          Total: 1.813 s
Init: 2.38145 ms;     Firestore: 35.476006 ms;   Get user: 1509.5808200000001 ms   Total: 1.766 s
Init: 2.36691 ms;     Firestore: 4.504131 ms;    Get user: 1594.135167 ms          Total: 1.891 s
Init: 2.236674 ms;    Firestore: 89.869081 ms;   Get user: 1513.9385889999999 ms   Total: 1.984 s

==== Firestore ====

Load Firestore:   1.465087 ms;   Get user: 1502.35546 ms    Total: 1.828 s
Load Firestore:   1.083618 ms;   Get user: 1428.580823 ms   Total: 1.672 s
Load Firestore:   88.41267 ms;   Get user: 1801.048798 ms   Total: 2.203 s
Load Firestore:   1.221764 ms;   Get user: 1795.698855 ms   Total: 2.359 s
Load Firestore:   1.405072 ms;   Get user: 1603.95193 ms    Total: 1.875 s

EDIT: on unrelated note, following are timings of the same Firestore get user request using REST API and googleapis client library:

== Cold start ==
Get user: 252.090024 ms  Total: 703 ms

== Warm start ==
Get user: 97.380099 ms   Total: 344 ms

Code tested:

import {firestore_v1, google} from 'googleapis';
import {GaxiosResponse} from 'gaxios';
import {convert} from 'firestore-adapter';
import Schema$Document = firestore_v1.Schema$Document;

export const googleApiFirestoreTest = functions.region('europe-west3').https.onRequest(
    async (request, response) => {
        const auth = new google.auth.GoogleAuth({
            scopes: ['https://www.googleapis.com/auth/cloud-platform']
        });
        const authClient = await auth.getClient(),
            path = `projects/${process.env.GCLOUD_PROJECT}/databases/(default)/documents/users/{some-user-uid}`,
            firestore = new firestore_v1.Firestore({
                auth: authClient
            });

        let result: GaxiosResponse<Schema$Document>;

        const time = await timeit(async () => result = await firestore.projects.databases.documents.get({
            name: path
        }));

        const doc = result.data,
            idRegex = /([^/]+$)/g,
            id = doc.name.match(idRegex)[0],
            fields = doc.fields;

        response.send({
            id,
            data: convert.docToData(fields),
            time
        });
    }
);

[hiranya911]

Thanks for the thorough test results @hakimio. These numbers are pretty insightful. As expected, I don't see a noteworthy difference in performance when using firebase-admin vs @google-cloud/firestore. The total observed latency in your tests seem to be in the same range regardless of the library used. Total latency numbers posted above average to 1.87ms (firebase-admin) and 1.98ms (firestore) respectively.

The difference in performance when using async import() is interesting. But note that even that hasn't really made a big difference when it comes to total latency. Overall, the performance gain of async imports seem to be in the order of 10's of milliseconds, which is not worth building a whole new set of APIs.

I also suspect that the timeit helper function doesn't correctly handle async functions. I have a suspicion that is why you're seeing very small values for loadFirestore. But nevertheless, the total response times are quite helpful and decisive.

Based on these observations I'm inclined to closing this issue off as everything seems to be working as expected. I'll do some more tests around async import() to see if it's worth evaluating more.

[hakimio]

Thank you for investigating the issue and feel free to close it.