onWrite function takes 15 seconds to begin

[OxyFlax]

Version info

firebase-functions: "^0.5"

firebase-admin: "^4.1.2"

Test case

const functions = require('firebase-functions');
const admin = require('firebase-admin');
admin.initializeApp(functions.config().firebase);

exports.functionName = functions.database.ref('/Something/{somethingId}').onWrite(event => {
    const snapshot = event.data;
    const something = snapshot.val();

    if (something) {
        console.log('Cloud function executing...');
    }
});

Steps to reproduce

Add object under "Something" reference and look at the console when the message "Cloud function executing...".

Were you able to successfully deploy your functions?

No error message when I deployed the function.

Expected behavior

The message should appear directly when the object is added to the database.

Actual behavior

The message is appearing 15s after the object appear in database.

[laurenzlong]

Thanks for the report @OxyFlax, and thanks for using the template. We refer to what you're experiencing as "cold start latency" and it's something that we're keenly aware of and are working to reduce. However 15s is longer than we've been seeing, are you experiencing this regularly?

[OxyFlax]

It depends, sometimes I don't have any and sometimes it's long. But most of the time it's between 10 and 15 seconds.

[katowulf]

Similar discussions: http://stackoverflow.com/questions/42726870/firebase-cloud-functions-is-very-slow http://stackoverflow.com/questions/40165122/why-does-the-first-firebase-call-from-the-server-take-much-longer-to-return-than

[SamMatthewsIsACommonName]

Is it possible to take 20-25 seconds? All my other functions start from 'cold' and take nowhere near that: http://stackoverflow.com/questions/43637519/why-is-firebase-cloud-function-taking-25-seconds

EDIT: Sorry solved, I wasn't 'returning' the update...

[yos1p]

Someone please get this issue fixed. It's so terrible that we have to wait even until 10-15 seconds just to start up one function.

I know that you might have to put it into fewer resources. But it feels like you shutdown the whole server for me. And then restarting up again.

You have to set boundary as to how low you will put us in fewer resiurces. Especially for paying users. If a user paid, you should make sure that their code always run smoothly.

[SamMatthewsIsACommonName]

@iamyaoxi are you making sure to return something at the end of the function? I know you may be but this is what was causing particularly long times for me. I haven't seen anything close to that long since making sure all aspects of my functions were returning something rather than just doing something.

[jofftiquez]

Dec 19, 2017 we are still experiencing this.

[justinrosenthal]

As mentioned previously, it's expected for there to be some variability in function start time that's dependent on a number of factors (particularly while Google Cloud Functions is in beta).

However, if you're observing latencies that are unacceptably high or you feel the product is misbehaving, please file a support ticket so it can be properly investigated.

If you think you've identified a bug in the firebase-functions library, please open a new Issue with repro steps. Thanks!

[Liron-K]

@justinrosenthal is there a way to add some logging information about the actual runtime of the functions?

I'm going through my logs to see if there are any particular functions that need to be optimized, but it's hard to tell when the reported runtime is mostly due to the startup time.

Is there also something that can be done to keep functions "warm" so there isn't a cold startup time?

[inlined]

We're working on adding some tracing that will help you figure out what is causing so much latency. The cold-start is a part of life with auto-scaling services, though 15s is very abnormal, esp for JavaScript.

Also, out of random curiosity, it sounds like you saying that the logs appear 15s after the database write? It would be helpful to distinguish between logging delays and cold start latency. Here's roughly what we used in the early days to measure e2e latency:

// Heartbeat is triggered by timestamps to 'syn' and writes 'ack'. In both cases, timestamps are
// written using ServerValues so they can be trusted to be on the same clock and accurate.
exports.heartbeat = functions.database.ref('pings/{id}/syn').onWrite(event => {
  let ref = event.data.ref
  let ack = ref.parent.child('ack');
  return ack.set(admin.database.ServerValue.TIMESTAMP);
});

Trigger the function with this CURL command:

curl -X POST \
 -H 'Content-Type: application/json' \
 -d '{".sv": "timestamp"}' \
 https://<yourfirebasedatabase>/pings.json

If you really want to aggressively test cold-start behavior, you can prevent the instance from being reused between requests by failing afterwards:

  return ack.set(admin.database.ServerValue.TIMESTAMP).then(() => {
    return Promise.reject(new Error('Forcing a cold start'));
  });

[Liron-K]

So there are two issues that I was noticing: 1) Each function has an id, but if the same function is called multiple times, there's no way from the logs to know which is which. It would be good if the id was printed with each log line. 2) The time between the call to "function start executing" and the first log was high, but more importantly, the timestamp on "function completed executing" was including the cold startup time. I want to know the time from when the cold start is completed (and my code starts running) until the time my code completes.

Also, from looking at my logs, 15 seconds or more wasn't abnormal at all - it seemed to be happening a lot.

[merlinnot]

@Liron-K here you go:

[Liron-K]

Not what I mean :) I know you can get it from there.

I mean if I do an export of the logs to look at all the data on my computer, then there's no indication about which function call each log came from, and when it says "Function execution took __ms" that's from the start of the function launch and not from when my code started running.

On Thu, Jan 4, 2018 at 2:51 PM Natan Sągol notifications@github.com wrote:

@Liron-K https://github.com/liron-k here you go:

[image: execution] https://user-images.githubusercontent.com/10390061/34564237-2e707f92-f156-11e7-9a5e-cb5e8be4e571.gif

— You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub https://github.com/firebase/firebase-functions/issues/35#issuecomment-355274579, or mute the thread https://github.com/notifications/unsubscribe-auth/ACMeAyPq6OVUz3tZO0xFksZ3wt7VjAmPks5tHMlJgaJpZM4M8Yj3 .

[moneal]

@Liron-K I've submitted a feature request to update the logs to be something like this. Maybe you could make a similar request also.

[jofftiquez]

@Liron-K I like it.

[Liron-K]

Interesting. It would also be helpful to have the function id in the command line logs that you can request from the cli On Tue, Jan 30, 2018 at 8:23 PM Jofferson Ramirez Tiquez < notifications@github.com> wrote:

@Liron-K https://github.com/liron-k I like it.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/firebase/firebase-functions/issues/35#issuecomment-361686903, or mute the thread https://github.com/notifications/unsubscribe-auth/ACMeA_3K43JwYDxRTQE6E2Vkj3CDD7jcks5tP14RgaJpZM4M8Yj3 .

[yusuftor]

10 months later and the issues are still here. Any update on this??

[trekze]

Just to share some more data from a random FB user. It usually takes 4-5 calls for my functions to warm up. I would be happy to pay to have more consistent response times. Otherwise I will need to introduce a pinger of sorts to prevent cold starts. Surely it would not be a good end-result for you guys if everyone starts doing the same and drowning your infrastructure with dummy requests!

Note that the above are execution times only. Response times are slower. I would double those numbers on average I'd say.

[laurenzlong]

Here are some tips for reducing warm up time: https://firebase.google.com/docs/functions/tips#performance

[itaydr]

I'm experiencing the same issue.

• I only have 2 dependencies in my function (firebase-functions and firebase-admin).
• The cold start latencies are ~12 secs.
• All I'm doing is reading a small object from the firestore DB and returning it via an onCall.
• When warm the function usually takes ~50 ms.

As mentioned, it's an onCall function, not a background function. I need the data it returns in order to display it to the waiting user. It's not acceptable to wait 12 secs.

Is there really no fix for this currently? It's been a year and a half since the issue was posted. I cannot use cloud functions if this is the case (It's a shame cause I really want to keep using them).

[Liron-K]

One thing you could do, if it's a very common request, is to keep the function "warm", by setting up a periodic job to call it regularly. On Tue, 12 Jun 2018 at 9:18 itaydr notifications@github.com wrote:

I'm experiencing the same issue.

• I only have 2 dependencies in my function (firebase-functions and firebase-admin).
• The cold start latencies are ~12 secs.
• All I'm doing is reading a small object from the firestore DB and returning it via an onCall.
• When warm the function usually takes ~50 ms.

As mentioned, it's an onCall function, not a background function. I need the data it returns in order to display it to the waiting user. It's not acceptable to wait 12 secs.

Is there really no fix for this currently? It's been a year and a half since the issue was posted. I cannot use cloud functions if this is the case (It's a shame cause I really want to keep using them).

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/firebase/firebase-functions/issues/35#issuecomment-396477976, or mute the thread https://github.com/notifications/unsubscribe-auth/ACMeA6win2zRW8ZfhRMlbdxJnPW3p-Eqks5t710_gaJpZM4M8Yj3 .

[itaydr]

@Liron-K Thanks! How frequently do you call functions to keep them warm? Once every how many hours?

It honestly feels a bit ridiculous to do it, is it common these days?

[Liron-K]

I'm not sure - I just got that advice someone once but never implemented it.

I heard this is necessary with AWS lamdba functions too - so at least there's that.

Here's a little info that I found on the general issue - https://stackoverflow.com/questions/42726870/firebase-cloud-functions-is-very-slow A few more tips directly from Firebase here: https://cloud.google.com/functions/docs/bestpractices/tips

On Tue, Jun 12, 2018 at 2:21 PM itaydr notifications@github.com wrote:

@Liron-K https://github.com/Liron-K Thanks! How frequently do you call functions to keep them warm? Once every how many hours?

It honestly feels a bit ridiculous to do it, is it common these days?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/firebase/firebase-functions/issues/35#issuecomment-396555327, or mute the thread https://github.com/notifications/unsubscribe-auth/ACMeA-nM4JPEQVUgY6GKIDYFEIOfFiyPks5t76QtgaJpZM4M8Yj3 .

-- Liron Kopinsky liron.kopinsky@gmail.com

[SamMatthewsIsACommonName]

I'm about to implement a single function that goes off of a once per minute cron job to a pub-sub topic 'minute_tick' and calls all the 'critical' functions at once. For us this is the ones that contact payment apis etc, as the user experience at this point is very critical and to have the customer waiting 5-10 seconds is just unacceptable ux for us. So basically we're jsut going to call all of these functions in such a way that they trigger the 'return null' catch at the beginning of the function and so dont need to do the actual service they are designed to do. I hope this has the same effect of keeping them warm. E.g:

if (newData === null || newData === false) {
return null
}

with the cron job function calling them all in such a way that they trigger that clause

[itaydr]

@SamMatthewsIsACommonName Thanks for the reply.

I'm still hoping of finding a simpler solution for this issue :) .

I'll be willing to hack it like this only if I'll get an understanding that they will solve it soon. Did you guys get a sense of whether they are working on solving this? I talked with them on a support ticket and got the sense that they thought this was ok. If this is the case then they are not aiming this product for start-ups which start out with a small traction and cannot accept these delays.

Are you experiencing these cold starts when using firebase-admin with firestore? Or even without using firebase-admin?

P.S. I tried warming up a function which uses firestore, but it only gets warm when I actually use firestore and not when I return null at the beginning of my function. (it seems to be lazily loaded in firebase-admin).

[tomlarkworthy]

If the function is part of a broader flow, ping the function earlier in the flow. E.g. if its for payment processing, ping the processor function at the shipping basket screen. Then you are not warming a function when no-one is around.

[Liron-K]

It's fundamental to how cloud functions work on all platforms including lambda and Google cloud. You have to spawn an instance of the function to respond to input, and that takes time.

Keeping it perpetually warm or warming it a little earlier in the flow is the easiest way to deal with this. On Wed, 13 Jun 2018 at 20:39 Tom Larkworthy notifications@github.com wrote:

If the function is part of a broader flow, ping the function earlier in the flow. E.g. if its for payment processing, ping the processor function at the shipping basket screen. Then you are not warming a function when no-one is around.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/firebase/firebase-functions/issues/35#issuecomment-397023583, or mute the thread https://github.com/notifications/unsubscribe-auth/ACMeA3l5b8yK0w_eYb2eHcXJ0wmsDi2yks5t8U5LgaJpZM4M8Yj3 .

[inlined]

@itaydr We've done some research and noticed that initializing the Firestore SDK can take several seconds, especially on Cloud Functions. Though we've made several updates to our SDKs to avoid ever hitting this slow path, actually reading from or writing to Firestore in the Cloud Function will always hit it. Unfortunately the repo for @google-cloud/firestore is a better place to file bugs & get +1s so we can get the attention this issue needs.

[itaydr]

@inlined Thanks! Yes, I've also noticed this issue happens only (or more severely) when using firestore. I'll file a new report there.

I ended up making the client fetch the firestore document and pass it to the cloud function to do some processing. As strange as it sounds it about 2X faster. Do you have any idea why does it take so much time to initialize the firestore lib on a cloud function but it's a lot faster to do it on the client side?

I love using these two products, but this issue is a huge pain for me.

[inlined]

Unfortunately the Firestore clients are pretty far outside my area of expertise, so I can't say.

[grosniko]

@itaydr may be on to something here, because from client side Firebase works how it should for me too - really fast. When things are cloud only its ultra slow. I keep a cron job activating all my functions every minute but I can't do that with a function triggered on user creation (unless I create users constantly which is just stupid). For startups, forcing a user to wait 15 seconds for something to happen after signing up is suicide. Would be good if Firebase team figures out why requests from client side work great and cloud operations are really slow.

[coolhand79]

@itaydr Did you end up creating an issue in the firestore sdk repo? I'm looking for updates. Maybe you can link it here?

[itaydressler]

@coolhand79 I did not file an issue there yet.