lambda - extremely long running time fix

[dacz]

I'm working on mid size project project with graphQL and we are working toward being fully on aws and where applicable on lambdas.

When adopting the codebase for lambda I saw strange issue. Init phase (schema parsing, db connecting etc.) of lambda was done within 400ms, the request itself was done in 400ms approx (this leaves response time for repeated requests to approx 400ms.

But I constantly saw around 11 seconds response and billed time.

I XRayed lambda, I added time logging everywhere (even in the apollo-lambda code) and everything looks like the request is processed in the supposed time but... replies were coming after 11 sec.

I mocked up lambda handler locally and - everything was fast as expected.

Out of endless experiments (with lambda these are slightly difficult because of repeated deploying and testing) I figured out the important setting:

const conn = connFactory();
const authFromHeaders = authFactory(conn);
const schema = makeExecutableSchema({ typeDefs: printableSchema, resolvers });

export default graphqlLambda(async (event, ctx) => {
  ctx.callbackWaitsForEmptyEventLoop = false; // <<<<< THIS IS IT!

  return {
    schema,
    context: {
      conn: { mysql: conn },
      viewer: await authFromHeaders(event.headers),
      ctx,
    },
  };
});

For some reason the event loop is not empty after calling lambda callback and it takes 10+ sec to be emptied (or killed by lambda, I do not know, so far).

The setting is just telling lambda to freeze the processing after calling the callback. I tested and everything is working fine with this setting, with subsequent requests etc.

I suspect the (recommended impelmentation even by awslabs) of kind of running https server (apollo-base) that responds to the request but (maybe) keeping event loop not empty. On the other side - the errors to graphql requests are returning fast.

I'm really not sure and therefore I consider to write this issue to discuss if anyone else experiences such problem and if the solution is appropriate. As I wrote - the same codebase just wrapped in slightly different wrapper to be run as node via apollo-graphql-server is running smooth and fast.

The wrap up:

• is using this setting ok?
• should we consider to add this setting to the examples
• why is this happening
• should we reimplement internal graphql lambda code not to go via httpserver path but just as a function that gets the data and returning the result?

[mklopets]

Is there any reason against using the context methods (context.succeed and context.fail) instead of the callback in apollo-server-lambda? Probably just because the callback is the newer API? Ending execution using the context methods doesn't wait for the event loop to be empty.

But, to try and fix the root problem:

You mentioned running of a http server on the Lambda... I'm not familiar with Apollo's Lambda implementation but from quick glance at the source and docs, I couldn't understand what server you're talking about. Can you elaborate? @dacz

[soda0289]

One more thing to add. If you use Lambda and a database connection or redis connection that doesn't close that might cuase the lambda function to not respond.

In the Lambda Context object there is a property callbackWaitsForEmptyEventLoop that can be used to respond right away when using a callback to respond.

More info here: http://docs.aws.amazon.com/lambda/latest/dg/nodejs-prog-model-context.html

Hope that helps

[dacz]

@soda0289 thank for your comment. I'm aware that db connection may be the problem, but because of common usage, I do not think this is the case. Even when I'll run lambda with direct SQL command, lambda finishes immediately.

I'm aware about the callbackWaitsForEmptyEventLoop as you may see in my issue and it was generally important part of the question/issue here (if this should not be documented here etc., please review my initial issue text).

[dacz]

@mklopets Thank for your questions. As you can see I do not use context.succeed or callback. I set up lambda handler exactly how recommended by apollo-server-lambda and I do not directly call callback or context methods. If calling the context methods instead of callback should finish execution, it should be probably used in the lambda lib.

According to httpServer - I came very shortly through this lib and saw there runHttpRequest, and because sometimes one may see lambda recommendations how to run existing app as lambda that uses even express :-O, I was wondering if something like this is not used. I now came more thoroughly across this lib code and apollo-server-code and I see that this is not the case (fortunately).

So from my summary questions I'm still not sure about the first three.

[Siyfion]

@soda0289 is there a recommended place to close my DB connection, as I'd like to try this method first.

EDIT: Interestingly, this article (http://blog.rowanudell.com/database-connections-in-lambda/) seems to suggest leaving long-running db connections around on purpose, for efficiency. So perhaps changing the callbackWaitsForEmptyEventLoop is actually a better way!?

[soda0289]

@Siyfion I think we should change the Lambda server to set callbackWaitsForEmptyEventLoop to true. In all my lambda functions I setup the database in the outer/global scope and let a connection pool handle timed out or closed connections. This way we do not have to wait for a database connection to initialize per request and can instead have connections ready to go.

[Siyfion]

@soda0289 agreed. In addition to this, it's also worth noting that adding as much of your schema generation code in the outer/global scope also will lead to much faster warm-start response times.

[dacz]

Exactly as @soda0289 wrote - leaving connection open will significantly decrease lambda processing time (because if lambda stays warn the connection will be open between calls) especially if your lambda runs in VPC. For me works best the callbackWaitsForEmptyEventLoop I proposed in the question. It should be set on by default - or - should be documented in the readme.

[soda0289]

@dacz I think callbackWaitsForEmptyEventLoop should be enabled by default to eliminate confusion by users and should be documented in the README as well.

[Siyfion]

Agreed, I mean for general purpose Lambda functions I can see why it's off. But this is going to almost certainly contain DB calls for all users, at which point it'll just cause confusion and delay. Document it for certain, and make sure there's a way to override, but I think having it on by default is the safest course of action.

[abernix]

This issue hasn't seen much in the way of reactions or additional feedback recently and there have been a number of releases in Apollo Server since this was opened, including many updates to apollo-server-lambda. If this problem persists, please feel free to open a new issue with a reproduction. (For what it's worth, there was this recent blog post on the Apollo blog about using apollo-server-lambda through Netlify functions (which deploys to AWS), so perhaps that might be helpful to anyone getting started).

Thanks for reporting this originally!

[sanket-work]

Exactly as @soda0289 wrote - leaving connection open will significantly decrease lambda processing time (because if lambda stays warn the connection will be open between calls) especially if your lambda runs in VPC. For me works best the callbackWaitsForEmptyEventLoop I proposed in the question. It should be set on by default - or - should be documented in the readme.

Hello @dacz
What do you mean when you say callbackWaitsForEmptyEventLoop should be set on by default?
Do you mean it should be kept true or false?

I am facing similar issue as yours I would like understand this better.

If I keep callbackWaitsForEmptyEventLoop to false will I face other issues with my actual response?

Thank You.

[seawatts]

I am also seeing this same behavior. I have set callbackWaitsForEmptyEventLoop to false however, it still takes about 11 seconds to respond. My code runs and finishes in about 1 second and then it waits for 10 seconds to actually respond after that.