apollo-server-lambda require taking seconds to finish

[luanmuniz]

This piece of code in my structure is taking several seconds in some cases:

console.log('require apollo-server-lambda start');
const { ApolloServer, AuthenticationError } = require('apollo-server-lambda');
console.log('require apollo-server-lambda end');

...Code related to Graphql
const ApolloServerInit = new ApolloServer({
	schema: new GraphQLSchema({
		query: new GraphQLObjectType({
			name: 'RootQueryType',
			fields: schemaObject
		})
	}),
	context: async ({ event, context }) => {
		if(event.source === 'serverless-plugin-warmup') {
			throw new AuthenticationError('Warmup Complete');
		}


		return {
			headers: event.headers,
			functionName: context.functionName,
			event,
			context
		};
	},
	tracing: true,
	engine: { apiKey: process.env.APOLLO_ENGINE_KEY },
	formatError: error => {
		delete error.extensions;
		delete error.path;

		return error;
	},
	playground: process.env.NODE_ENV !== 'production'
});

console.log('Starting ApolloServer');
const apolloServer = ApolloServerInit.createHandler({
	cors: {
		origin: '*',
		credentials: true
	}
});
console.log('Starting ApolloServer');
module.exports = apolloServer

Log from this piece code:

2019-05-24T17:56:26.620Z	a81bfad3-dc95-4f43-ab06-0d7e05a66b68	require apollo-server-lambda start
2019-05-24T17:56:29.744Z	a81bfad3-dc95-4f43-ab06-0d7e05a66b68	require apollo-server-lambda end
...More Logs
2019-05-24T17:56:33.205Z	a81bfad3-dc95-4f43-ab06-0d7e05a66b68	Starting ApolloServer
2019-05-24T17:56:45.305Z	a81bfad3-dc95-4f43-ab06-0d7e05a66b68	End  ApolloServer

I'm using:

• lambda v8.10
• apollo-server-lambda v2.5.0
• graphql v14.3.1
• graphql-relay v0.6.0

honestly, I have no clue of what can be happening because the issue is not regular. It happens sometimes. The same code some times takes ~400ms sometimes several seconds.

I've tried apollo-server-lambda@2.4.8, but the issue remains

[abernix]

Two things to try:

1. Could you actually try the latest alpha of 2.6.0? I'm curious if Defer and cache calculation of Engine reporting signature. #2670 has helped at all. You can install with npm install apollo-server-lambda@next.

2. If that doesn't work (I'd really like to know if it helps, at all), can you try enabling sendReportsImmediately: true inside the engine options? e.g. :

     engine: {
       apiKey: ...,
       sendReportsImmediately: true,  // 👈
     },

   The code might help explain, but it's only documented in the code, unfortunately:

   apollo-server/packages/apollo-engine-reporting/src/agent.ts

   Lines 103 to 106 in d1a0d16

   	/**
   	* Sends the trace report immediately. This options is useful for stateless environments
   	*/
   	sendReportsImmediately?: boolean;

Also, do note that you do not need tracing: true with Engine. That not only makes the response much larger, but it also doubles the amount of metric instrumentation that Engine reporting already does and sends asynchronously after the response callback is invoked.

[luanmuniz]

@abernix Thanks for the response.

I tried to update, but then I'm getting CORS errors.
I tried a few things, but nothing worked.

I tried the sendReportsImmediately: true and it didn't help.
I also removed the tracing. Thanks.

[abernix]

Can you investigate the cause of the CORs errors and provide the errors here so we can help debug?

If you could try apollo-server-lambda@2.6.0-alpha.5 as well, I'm curious if #2674 may have broken something.

[luanmuniz]

@abernix Just to give you an update. Indeed apollo-server-lambda@2.6.0-alpha.5 doesn't give me cors problems out of the blue. But I'm still having the original problems with this version

I'm still debugging what's happening. I will get to you as soon as I have any news! I will try to have something this week

Thanks for the clues!

[abernix]

@luanmuniz Ok, that seems to narrow it down to #2674 then! Thanks for the confirmation! What are the specific CORS errors?

It's possible that this is either a new bug introduced by that PR, or that previously misconfigured CORS settings on that server are now being respected properly. I'm curious if @dsanders11, who originally introduced #2597, has any thoughts (or is able to reproduce a regression themselves?)

[dsanders11]

honestly, I have no clue of what can be happening because the issue is not regular. It happens sometimes. The same code some times takes ~400ms sometimes several seconds.

@abernix, isn't this just describing AWS Lambda cold-start behavior? Sounds like what one would expect with Lambda, it's not a constant performance kind of thing. @luanmuniz, I think this is expected behavior. Look into Lambda "cold starts". Execution can be quite slow when it hasn't been used in a while.

Regarding #2674, yes, there's a regression. I'll comment on that PR.

[luanmuniz]

@dsanders11 I would agree with you if it was always the case. But the problem doesn't happen every time the cold-start it's triggered. It'just some times. Which is very weird.

I'm tracking it down at the moment. Maybe it's related to the Lambda Runtime and not this module,
when i changed the version of the aws-sdk module I was using the problem happen a lot less often, but I would like to investigate a little further before bothering you guys again.

The timeouts are keeping us from releasing our product so I have a deadline to solve the issue. This week without a fault I will have a more detailed report to give you guys.

Thanks for all the help so far!

[abernix]

As @dsanders11 has noted, there are certainly some properties of AWS Lambda that require longer cold-start times, but I was under the impression that you were saying that it was the finishing of the request that took longer. Though, looking at the code, I don't see where and how the End ApolloServer is being printed. Your continued investigation is very much appreciated since I'm not able to dig into those sorts of specifics without setting up the same environment, etc.

That said, the CORS errors should be fixed thanks to 7e78a23 and the latest -alpha.8 version.

[luanmuniz]

Hello Everyone! An Update:

@abernix The response time was not affected. But the cold-started request sometimes took a lot, but it was because of the code start (requires, instances and so on).

Together with an AWS representative, we tracked down the issue.
It turns out that I was using a module called MJML and the initial load for it is VERY HEAVY, in some cases, it was taking more than 15 seconds just to load the module.

When the memory of the functions was not high (128~256) the MJML module was basically consuming all the vCPU available for the container and because of that when it comes times for GraphQL to run, it didn't have enough CPU to make the initial load so it was waiting for the MJML module to free the CPU, that's why the delay in the load. According to AWS, with 1792MB of memory we have the equivalent of 1 vCPU and linearly going up and down from there.

After I removed the MJML module, the GraphQL still took a little bit of time, but not as much as before.

I'm going to test out the CORS problem this week and get back to you.

Thank you guys again for all the help, it was SUPER helpful when debugging the problem.

[abernix]

That's really great findings, @luanmuniz! Glad you got to the bottom of it. I'm going to close this, as it sounds like the original issue is actually resolved. If the CORS thing is still an issue, I suspect that is either a separate issue (or even a known, separate issue).

Thanks for filing this originally!