5

I'm using Cloud Functions for Firebase to:

  1. Receive parameters from api.ai
  2. Make a call to a third-party API and
  3. Respond back to api.ai.

My call to the third-party API uses the request Node.js module and is wrapped within a function (getInfoFromApi()) in index.js.

The problem I'm having is that the execution of the secondary function call is consistently taking between 15-20 seconds. Note: The cloud function itself completes its execution consistently in the 400 ms range.

By logging simple comments to the console I can see when the function starts, when the secondary function is being called and when it receives a response from the third party, so I think I can see what's happening.

Roughly, the timings look like this:

  • 0: cloud function initialises
  • 400 ms: cloud function completes
  • 16 s: getInfoFromApi() function is called (!)
  • 17 s: third-party API returns results

My questions:

  • Is there an obvious reason for the delay in calling the secondary function? This doesn't seem to be caused by the cold start issue since the cloud function springs to life quickly and the delay is consistent even after repeated calls.
  • Is the use of the 'request' node module causing the issue? Is there a better module for creating/managing http requests from cloud functions?

You can see a simplified Gist of the index.js here: https://gist.github.com/anonymous/7e00420cf2623b33b80d88880be04f65

Here is a grab of the Firebase console showing example timings. Note: the output is slightly different from the above code as I simplified the above code to help understanding. enter image description here

Community
  • 1
  • 1
James
  • 1,292
  • 1
  • 14
  • 29
  • Can you share a code snippet of what you're actually doing? – Michael Bleigh Mar 21 '17 at 18:59
  • @MichaelBleigh I've tidied up the index.js and put it in a gist here: https://gist.github.com/anonymous/7e00420cf2623b33b80d88880be04f65/revisions - it's obviously a WIP but will hopefully show you what's being called from api.ai. – James Mar 21 '17 at 19:57
  • Could you possibly share your output from a sample run of the program? The timings order that you have in your question doesn't match up with the code (i.e. the "getInfoFrom3rdParty() called" **must** be printed before http response is sent from the code written as that function is directly invoked, which appears to contradict your timing.) – Andrew Stirling Mar 21 '17 at 23:25
  • @AndrewStirling I've added console output to the original question. – James Mar 21 '17 at 23:45
  • This post might be useful. A Firebase employee clarifies how a "cold start" influences cloud function run time. http://stackoverflow.com/questions/42726870/firebase-cloud-functions-is-very-slow – Brock Klein Apr 05 '17 at 00:26
  • @BrockKlein - thanks. I did have references to the other SO answers that added some context to my question (inc. that one) but another user edited them out of my question. I thought they were helpful to others searching later but he obviously disagreed. – James Apr 06 '17 at 20:06
  • Please include the code in your question according to Stack Overflow policy. See [how to ask](http://stackoverflow.com/help/how-to-ask) and [creating an mcve](http://stackoverflow.com/help/mcve). – Kato Apr 13 '17 at 17:30

2 Answers2

1

The getInfoFrom3rdParty() call is an asynchronous event. However, you haven't returned a promise from your function, so Functions is not waiting for the async event to complete.

It looks to me like, since you are returning undefined, the Function also assumes that it failed and retries. At some point in the retry process, the async event is probably completing before the function exits (i.e. unintentional success due to race conditions). I've seen similar outcomes in other cases where users don't return a promise or value in their functions.

I can't tell from the gist what you're trying to do--it doesn't appear to actually do anything with the third party results and probably isn't a realistic mcve of your use case. But something like this is probably what you want:

exports.getInfo = functions.https.onRequest((request, response) => {
  // ....

  // NOTE THE RETURN; MOST IMPORTANT PART OF THIS SAMPLE
  return getInfoFromThirdParty(...).then(() => {
    response.writeHead(200, {"Content-Type": "application/json"});
    response.end(JSON.stringify(payload));
  }).catch(e => /* write error to response */);
});

function getInfoFrom3rdParty(food) {
  reqObj.body = '{"query": "'+food+'"}';

  return new Promise((resolve, reject) => {
       mainRequest(reqObj, function (error, response, body) {
          // ....
          if( error ) reject(error);
          else resolve(...);
          // ....
       });
  });
}
Kato
  • 40,352
  • 6
  • 119
  • 149
0

From my experience with cloud functions, once the "execution finish" flag completes, it will then cause a delay (from 3s up to 15s). This blocks the remaining execution and increases your total response time.

To overcome this, you could try placing a Promise to your 3rd party call, once it completes, then do the "response.send()" which ends the function.