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 ***@***.***> 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 <#35 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ACMeAyPq6OVUz3tZO0xFksZ3wt7VjAmPks5tHMlJgaJpZM4M8Yj3> .