We have an issue where a serverless function duration is much longer then the actual execution time of the code.
Code
It’s a Next.js app, using the older pages router. The api endpoint is a trpc endpoint bound to an api route according to the docs, initialized as such:
const handler: NextApiHandler = async (...args) => {
const start = moment();
console.log("Function execution start:", start.format("YYYY-MM-DD HH:mm:ss.SSS"));
const trpcHandler = trpcNext.createNextApiHandler({
router: appRouter,
createContext,
});
const result = await trpcHandler(...args);
const end = moment();
const diff = end.diff(start, "milliseconds");
console.log(`Function execution end: ${end.format("YYYY-MM-DD HH:mm:ss.SSS")} [${diff} miliseconds]`);
return result;
}
export default handler;
When this function is called, it randomly (around 50% of the time) takes upwards of 7 seconds to execute, whereas the other times it executes in the timespan of miliseconds.
Here is a function log from a specific function call, which does the following: check the credentials, and if they are valid query a mongo database with prisma, close the connection and return the data from mongo.
As seen in the logs below, the difference between ‘Function execution start’ and ‘Function execution end’ is a couple milliseconds (how these timers are called can be seen in the code snippet above). Yet the duration of the function is more than 8 seconds, which corresponds to the request duration we experience in the frontend.
Logs:
Jul 13, 12:55:12 PM: 6983c2f9 INFO Function execution start: 2023-07-13 10:55:21.843
Jul 13, 12:55:12 PM: 6983c2f9 INFO Context Start: 2023-07-13 10:55:21.847
Jul 13, 12:55:12 PM: 6983c2f9 INFO Procedure Start: 2023-07-13 10:55:21.848
Jul 13, 12:55:12 PM: 6983c2f9 INFO Session Start: 2023-07-13 10:55:21.849
Jul 13, 12:55:12 PM: 6983c2f9 INFO aborting, unauthorized
Jul 13, 12:55:12 PM: 6983c2f9 INFO [OK] Procedure End: 2023-07-13 10:55:21.849 [1 miliseconds]
Jul 13, 12:55:12 PM: 6983c2f9 INFO Disconnected from prisma at 2023-07-13 10:55:21.850
Jul 13, 12:55:12 PM: 6983c2f9 INFO Function execution end: 2023-07-13 10:55:21.863 [20 miliseconds]
Jul 13, 12:55:12 PM: 6983c2f9 INFO [GET] /api/trpc/auth.session (SSR)
Jul 13, 12:55:21 PM: 6983c2f9 Duration: 8188.52 ms Memory Usage: 316 MB Init Duration: 482.87 ms
I have no idea what and why keeps the function executing even after it is finished. My first guess was it is prisma, so I tried keeping the connection open, closing the connection, running it with and without Prisma Data Proxy and all the possible combinations. This reduced the function size a little bit, but it still takes way more time tan it needs to.
Thanks for any help.
Site name: consolafi.netlify.app