Firestore operations in Cloud functions slow compared to web client

Question

I haven't found much information online about that issue, and it feels like I'm the only user experiencing this. I read a few comments about how people measure performance and I’ve included the code and measurements results below.

I'm testing 3 operations to Firestore:

• Read
• Write
• onSnapshot (time between write call and notification of change)

On 3 environments: web client, emulator, cloud functions production (nodejs10).

Performance from a web client is really good, instant. Emulator is great, instant (see results below).

Production is slow, and the numbers are curiously rounded.

• Read: 3700ms
• Write: 2900ms
• Snapshot: 2704ms

And this is after the infamous cold start.

Am I missing something obvious here?

Code:

function epochms() {
  return Math.floor(new Date());
}

async function run10Times() {
  for (var i = 0; i < 10; ++i)
    await updateRecord("Tests/manager/Updates", i.toString().padStart(2, '0'));
}

async function updateRecord(colpath, id) {
  let obj = {id};
  let startRead = epochms();
  await db.collection("Tests").doc("manager").get();
  let startWrite = epochms();
  await db.collection(colpath).doc(obj.id).set({startRead, endRead:startWrite, startWrite});
  let endWrite = epochms();
  await db.collection(colpath).doc(obj.id).update({endWrite});
  db.collection(colpath).doc(obj.id).onSnapshot(async (doc) => {
    log.log(`[${id}] test.onSnapshot`);
    let snapshotReceived = epochms();
    obj = { id:doc.id, ...doc.data() };
    if (obj.snapshotStarted && !obj.snapshotReceived)
      await db.collection(colpath).doc(obj.id).update({snapshotReceived});
    else 
      log.log(`[${id}] test.onSnapshot late, ignore`);
  });
  let snapshotStarted = epochms();
  await db.collection(colpath).doc(obj.id).update({snapshotStarted});
}

exports.emulatorScheduledEventUpdate = functions.https.onCall(() => {
  run10Times();
  return 0;
});

Output in cloud functions

00
Read: 91192ms
Write: 5301ms
Snapshot: 16000ms

01
Read: 12400ms
Write: 2700ms
Snapshot: 4501ms

02
Read: 4201ms
Write: 2700ms
Snapshot: 3901ms

03
Read: 4301ms
Write: 900ms
Snapshot: 3300ms

04
Read: 4599ms
Write: 1901ms
Snapshot: 4901ms

05
Read: 4400ms
Write: 2302ms
Snapshot: 2700ms

06
Read: 4200ms
Write: 900ms
Snapshot: 2396ms

07
Read: 4900ms
Write: 1099ms
Snapshot: 4602ms

08
Read: 2300ms
Write: 1500ms
Snapshot: 2500ms

09
Read: 3300ms
Write: 1900ms
Snapshot: 2400ms

Output in emulator

00
Read: 238ms
Write: 27ms
Snapshot: 18ms

01
Read: 7ms
Write: 13ms
Snapshot: 17ms

02
Read: 5ms
Write: 12ms
Snapshot: 12ms

03
Read: 5ms
Write: 16ms
Snapshot: 16ms

04
Read: 4ms
Write: 24ms
Snapshot: 18ms

05
Read: 4ms
Write: 26ms
Snapshot: 16ms

06
Read: 4ms
Write: 31ms
Snapshot: 20ms

07
Read: 6ms
Write: 28ms
Snapshot: 17ms

08
Read: 5ms
Write: 34ms
Snapshot: 26ms

09
Read: 5ms
Write: 10ms
Snapshot: 18ms

package.json

{
  "name": "functions",
  "description": "Cloud Functions for Firebase",
  "main": "dist/index.js",
  "scripts": {
    "lint": "xo",
    "build": "babel 'src' --out-dir 'dist' --source-maps",
    "watch": "yarn build --watch",
    "serve": "yarn watch & yarn firebase emulators:start --only firestore,functions --inspect-functions",
    "predeploy": "yarn build",
    "deploy": "yarn firebase deploy --only functions",
    "fdeploy": "yarn firebase deploy --only functions:tests-scheduledEventUpdate",
    "fdelete": "firebase functions:delete tests-scheduledEventUpdate",
    "logs": "watch -n 5 firebase functions:log -n 90"
  },
  "engines": {
    "node": "10"
  },
  "dependencies": {
    "@grpc/grpc-js": "^1.0.3",
    "core-js": "^3.6.5",
    "debug": "^4.1.1",
    "firebase": "^7.14.2",
    "firebase-admin": "^8.11.0",
    "firebase-functions": "^3.6.1",
    "google-gax": "^2.3.1",
    "grpc": "^1.24.2",
    "request": "^2.88.2"
  },
  "devDependencies": {
    "@babel/cli": "^7.4.3",
    "@babel/core": "^7.4.3",
    "@babel/preset-env": "^7.4.3",
    "firebase-functions-test": "^0.2.1",
    "firebase-tools": "^8.1.1",
    "xo": "^0.24.0"
  },
  "private": true
}

Thanks,

Answer 1

I read somewhere that resources access are greatly reduced if the code is running outside of the function's scope. So I tried changing this code:

exports.emulatorScheduledEventUpdate = functions.https.onCall(() => {
  run10Times();
  return 0;
});

to

exports.emulatorScheduledEventUpdate = functions.https.onCall(() => {
  return run10Times();
});

The function now returns a promise, and the numbers are very different:

00
Read: 52ms
Write: 75ms
Snapshot: 74ms

01
Read: 35ms
Write: 98ms
Snapshot: 72ms

02
Read: 33ms
Write: 114ms
Snapshot: 68ms

03
Read: 198ms
Write: 37ms
Snapshot: 72ms

04
Read: 37ms
Write: 68ms
Snapshot: 76ms

05
Read: 32ms
Write: 121ms
Snapshot: 74ms

06
Read: 44ms
Write: 54ms
Snapshot: 81ms

07
Read: 35ms
Write: 71ms
Snapshot: 67ms

08
Read: 33ms
Write: 93ms
Snapshot: 71ms

09
Read: 49ms
Write: 103ms
Snapshot: 41ms

Note to firebase team: A warning would be useful (especially in the emulator), and maybe set a hard limit of 1s after execution, instead of a confusing behavior.