Firestore simple "get" query takes 10 seconds within cloud function

Question

I have a cloud function that runs a simple firestore query by doc ID. The function logs show a ~7 second delay around running the query. Here's the function code:

 exports.cancelUnpaidOrder = functions.https.onCall(async (orderId, context) => {
  console.log("in cancelUnpaidOrder");
  const uid = context.auth.uid;

  console.log("awaiting get order doc");
  const orderSnap = await admin
    .firestore()
    .collection("order")
    .doc(orderId)
    .get();
  console.log("getting order doc data");
  const order = orderSnap.data();
  console.log("asserting");
  assert.ok(order.userId == uid && !order.paid);
  console.log("awaiting update order doc");
  await admin.firestore().collection("order").doc(orderId).update({
    canceled: true,
    cancelMsg: "canceled by user before pay",
    open: false,
  });
  console.log("finished cancelUnpaidOrder");
});

Here are the logs, notice the very long query time between 9:52:29 and 9:52:36:

9:52:37.003 Function execution took 9292 ms, finished with status code: 200
9:52:37.001  finished cancelUnpaidOrder
9:52:36.487  awaiting update order doc
9:52:36.487  asserting
9:52:36.486  getting order doc data
9:52:29.558  awaiting get order doc
9:52:29.558  in cancelUnpaidOrder
9:52:29.558  Callable request verification passed
9:52:27.712  Function execution started

Function zone: us-central1. Firestore zone: nam5 (us-central)

Thanks.

EDIT: Firestore document size is 6.57K

Answer 1

Note that, like a Cloud Functions instance, the Admin SDK, experiences a cold-start. While your code may be just a simple query, the first API request also triggers an exchange of authentication tokens between the service account client and the authentication server before your query is executed. For any given functions instance, this performance hit should only happen once, unless that particular instance manages to stay alive for long enough (usually an hour) where it will reauthenticate. If multiple instances are fired up to soak up demand, they will each have this hit to performance just once.

Minimal data transfer

You can help your function's performance by using a field mask on the returned data. For the Admin SDK, this is done using select(). Using a field mask for your document drops its size down from 6.57KB to just 51B.

exports.cancelUnpaidOrder = functions.https.onCall(async (orderId, context) => {
  console.log("in cancelUnpaidOrder");
  const uid = context.auth.uid;

  const orderRef = admin.firestore() // <- new: store reference in variable
    .collection("order")
    .doc(orderId);

  console.log("awaiting get order doc");
  console.time("getDoc");
  const orderSnap = await orderRef
    .select('userId', 'paid') // <- new: only fetch userId and paid, ignore other fields
    .get();
  console.timeEnd("getDoc"); // <-- new: calculate timings locally

  console.log("getting order doc data");
  const order = orderSnap.data();
  console.log("asserting");
  assert.ok(order.userId === uid && !order.paid); // <- new: use === for user ID checks!
  console.log("awaiting update order doc");
  console.time("setDoc");
  await orderRef.update({
    canceled: true,
    cancelMsg: "canceled by user before pay",
    open: false,
  });
  console.timeEnd("setDoc"); // <-- new: calculate timings locally
  console.log("finished cancelUnpaidOrder");
});

Note: canceled should probably be corrected to cancelled.

Handling errors

Rather than use assert.ok, you should use a helper function that does the same job, but throws a HttpsError instead so that your front end can receive a meaningful error instead of one with a error code of "internal". In a similar fashion, converting the Firestore calls to throw a HttpsError as well may also be desirable.

These helper functions would look like:

// Typescript: function assertOk(condition: unknown, message?: string): asserts condition {
function assertOk(condition, message = undefined) {
  if (!condition) {
    throw new functions.https.HttpsError(
      "failed-precondition",
      message || "failed-precondition"
    );
  }
}

function throwAsHttpsError(error, message = undefined) {
  let err, errCode = (!!error && typeof error === "object" && error.code) || "internal";
  try {
    // attempt to use original error's code
    err = new functions.https.HttpsError(
      errCode,
      message || "INTERNAL"
    );
  } catch {
    // unexpected error code, use fallback code of "internal"
    err = new functions.https.HttpsError(
      "internal",
      message || errCode || "INTERNAL"
    );
  }
  throw err;
}

Applying them gives:

exports.cancelUnpaidOrder = functions.https.onCall(async (orderId, context) => {
  console.log("in cancelUnpaidOrder");
  const uid = context.auth.uid;

  const orderRef = admin.firestore()
    .collection("order")
    .doc(orderId);

  console.log("awaiting get order doc");
  console.time("getDoc");
  const orderSnap = await orderRef
    .select('userId', 'paid')
    .get()
    .catch(e => throwAsHttpsError(e, "failed to read order"));
  console.timeEnd("getDoc");

  console.log("getting order doc data");
  const order = orderSnap.data();

  console.log("asserting");
  assertOk(order.userId === uid, "User mismatch");
  assertOk(!order.paid, "Order already paid");

  console.log("awaiting update order doc");
  console.time("setDoc");
  await orderRef
    .update({
      canceled: true,
      cancelMsg: "canceled by user before pay",
      open: false,
    })
    .catch(e => throwAsHttpsError(e, "failed to cancel order"));
  console.timeEnd("setDoc");

  console.log("finished cancelUnpaidOrder");
});

Testing timings

When testing Cloud Function timings, you should make sure to test calling the function twice. The first time is to test cold-start performance of spinning up a new Cloud Function instance. The second time is to attempt to reuse the same instance used by the first call once it has gone idle. Either call may or may not experience a cold-start.

const cancelUnpaidOrder = firebase.functions().httpsCallable('cancelUnpaidOrder');

function testCall(orderId) {
  const tag = "Call for Order #" + orderId;
  console.time(tag);
  return cancelUnpaidOrder(orderId1)
    .then(() => {
      console.timeEnd(tag);
      console.log(tag + ": success");
    }, (err) => {
      console.timeEnd(tag);
      console.error(tag + ": error -> ", err);
    });
}

const orderId1 = /* first test ID to be cancelled */;
const orderId2 = /* second test ID to be cancelled */;

// attempt to invoke a cold-start
testCall(orderId1);

// attempt to catch the cooled down instance, timings may need adjustment
setTimeout(() => testCall(orderId2), 15000);