Function execution duration

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

Try adding similar logs in your _app.js and _document.js.

I added similar logs to the beginning and end of _app.ts and _document.ts. The logs are not present in the function log most of the time, and if they are, the time differences are normal and not in the order of seconds.

Sorry for the delay. Do you think you can share your repo to check? I don’t see any other way we can possibly debug this.