Spikes in execution time for cloud functions?

Question

I have a pretty dead simple cloud function that writes a single value to my real-time database. The code is at the bottom of this post.

Watching the logs, I'm finding that the execution time is highly inconsistent. Here's a screenshot:

You can see that it's as low as 3ms (great!) and as high as 579ms (very bad-- and I've seen it reach 1000ms). The result is very noticeable delays in my chatroom implementation, with messages sometimes being appended out of order from how they were sent. (i.e. "1" "2" "3" is being received as "2" "3" "1")

Why might execution time vary this wildly? Cold start vs warm start doesn't seem to apply since you can see these calls happened directly one after the other. I also can't find any documented limits on writes/sec for real-time db, unlike the 1 write/sec limit on firestore documents.

Here's the code:

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

admin.initializeApp();

const messagesRef = admin.database().ref('/messages/general');

export const sendMessageToChannel = functions.https.onCall(async (data, context) => {
  if (!context.auth) {
    throw new functions.https.HttpsError(
      'failed-precondition', 
      'User must be logged-in.'
    );
  }

  try {
    await messagesRef.push({
      uid: context.auth.uid,
      displayName: data.displayName,
      body: data.body
    });
  } catch (error) {
    throw new functions.https.HttpsError('aborted', error);
  }
});

Edit: I've seen this similar question from two years ago, where the responder indicates that the tasks themselves have variable execution time.

Is that the case here? Does the real-time database have wildly variable write times (varying by ~330x, from 3ms to 1000ms!)?

user_12701848 · Answer

That's something quite hard to control based on the code.
You have a lot of steps going on there: \

verifying the user authentication
send his message to the collection
trying to catch any possible errors

So you can't rely simply on response time to organize the messaging order.
You should be setting a serverside timestamp from within the client side to trace that.

You can achieve this with the following explained piece of code:

try {
    message.createdAt = firebase.firestore.FieldValue.serverTimestamp() // server-side timestamp
    ... // calls to functions
} catch(err) {
    console.log("Couldn't set timestamp or send to functions")
}

This way you would set a server side timestamp for your message before sending it to be saved, so your users would see whenever a message is being registered (timestamp), saved (functions call) and confirmed (200 when sent).

Spikes in execution time for cloud functions?

1 Answers