Bizarre coldstart performance

[justin-gerhardt]

I've encountered a rather odd performance bug. When using this plugin, some of my functions have a 7+ second coldstart time. When configuring iopipe manually coldstart time is less than 1 second. Subsequent non-coldstart invocations show no performance difference. Times are as reported by cloudwatch to eliminate any measurement difference that might occur due to different load points.

I've distilled the functions down to minimal projects to reproduce the issue.

this is the code used with the plugin:

const google = require("googleapis").google;

exports.Test = async (event, context, callback) => {
  const mark = context.iopipe.mark;
  mark.start("start");
  const client = google.youtube({
    auth: process.env.YOUTUBE_API_KEY,
    version: "v3"
  });
  const res = await client.videos.list({
    id: "YjJ3uXxueeg",
    part: "snippet"
  });
  callback(null, {
    body: JSON.stringify(res.data),
    headers: {
      "Content-Type": "application/json"
    },
    statusCode: 200
  });
  mark.end("start");
}; 

and manually installed:

const google = require("googleapis").google;

const iopipe = require("@iopipe/iopipe")({
  token: process.env.IOPIPE_TOKEN
});

exports.Test = iopipe(async (event, context, callback) => {
  const mark = context.iopipe.mark;
  mark.start("start");
  const client = google.youtube({
    auth: process.env.YOUTUBE_API_KEY,
    version: "v3"
  });
  const res = await client.videos.list({
    id: "YjJ3uXxueeg",
    part: "snippet"
  });
  callback(null, {
    body: JSON.stringify(res.data),
    headers: {
      "Content-Type": "application/json"
    },
    statusCode: 200
  });
  mark.end("start");
});

This is the complete project for the manual install.

This is the complete project using the plugin

To test, you will need to put a iopipe token in config.yml. You will also need a Youtube api key. One can be generated using these instructions or I can provide one over a more private communication method.

Serverless Version: 1.27.3
@iopipe/iopipe: 1.7.0
serverless-plugin-iopipe: latest + #76

[coreylight]

Thank you for the detailed report @justin-gerhardt. I'm currently thinking this may be due to the async handler. If you have a chance to modify to not use async that would be helpful for information gathering on this issue.

[justin-gerhardt]

I removed the async keyword and replaced the await with a then call.

const google = require("googleapis").google;

exports.Test = (event, context, callback) => {
  const mark = context.iopipe.mark;
  mark.start("start");
  const client = google.youtube({
    auth: process.env.YOUTUBE_API_KEY,
    version: "v3"
  });
  client.videos.list({
    id: "YjJ3uXxueeg",
    part: "snippet"
  }).then(res => {
    callback(null, {
      body: JSON.stringify(res.data),
      headers: {
        "Content-Type": "application/json"
      },
      statusCode: 200
    });
    mark.end("start");
  });
};

Coldstart execution took 6874.99 ms.

[coreylight]

@justin-gerhardt I believe this has been fixed and released in a new version of the plugin. Thanks!