prisma.$transaction: Benchmark produces unexpected results

[tonivj5]

Bug description

I have been doing some benchmarks against my project using Prisma. My project uses prisma's transactions and under high load, prisma throws an unmeaningful error

Error
    at Object.transaction (/.../prisma-issue-tx/starter/node_modules/@prisma/client/runtime/index.js:36083:55)
    at async PrismaClient._transactionWithCallback (/.../prisma-issue-tx/starter/node_modules/@prisma/client/runtime/index.js:39451:9) {
  code: 'StringExpected'
}

This error shadows this response from engine (captured from a breakpoint using vscode debugger):

I suspect that StringExpected error comes from these lines https://github.com/prisma/prisma/blob/main/packages/engine-core/src/library/LibraryEngine.ts#L119-L121, where an id is expected to be sent, but undefined is sent really. If engine returns an error here https://github.com/prisma/prisma/blob/main/packages/client/src/runtime/getPrismaClient.ts#L1006, the rest of the code should be avoided? (these lines https://github.com/prisma/prisma/blob/main/packages/client/src/runtime/getPrismaClient.ts#L1008-L1022)

I have been doing some tests with other drivers (mysql2), and there have'nt been problem with pressure, so I don't know if it's other additional issue, prisma should work under that pressure? I'm using https://github.com/mcollina/autocannon and the errors start when I use -p (pipeling). I have not too much experience with benchmarking, so I could be doing some bad assumptions or misunderstanding how I should be doing it. Anyway, that error is a real issue 😅

How to reproduce

• Clone https://github.com/tonivj5/prisma-issue
• npm i
• npm run start
• Once started, npm run benchmark it runs autocannon
• It should produces a ton of errors (StringExpected....)

Expected behavior

Most useful errors, no errors (?)

Prisma information

I have used starter project from Prisma

Environment & setup

• OS: Linux Mint
• Database: SQLite, MariaDB/MySQL
• Node.js version: 17.0.1

Prisma Version

prisma                  : 3.4.2
@prisma/client          : 3.4.2
Current platform        : debian-openssl-1.1.x
Query Engine (Node-API) : libquery-engine 57771c0558568c7d08bd34c7248af5244ae16bd9 (at node_modules/@prisma/engines/libquery_engine-debian-openssl-1.1.x.so.node)
Migration Engine        : migration-engine-cli 57771c0558568c7d08bd34c7248af5244ae16bd9 (at node_modules/@prisma/engines/migration-engine-debian-openssl-1.1.x)
Introspection Engine    : introspection-core 57771c0558568c7d08bd34c7248af5244ae16bd9 (at node_modules/@prisma/engines/introspection-engine-debian-openssl-1.1.x)
Format Binary           : prisma-fmt 57771c0558568c7d08bd34c7248af5244ae16bd9 (at node_modules/@prisma/engines/prisma-fmt-debian-openssl-1.1.x)
Default Engines Hash    : 57771c0558568c7d08bd34c7248af5244ae16bd9
Studio                  : 0.438.0
Preview Features        : interactiveTransactions
Done in 0.84s.

[loclv]

I saw this unmeaningful error too, and don't know how to fix it. :(

[tonivj5]

@loclv if you are using transactions the underlaying error should be this:

{
  "is_panic": false,
  "message": "Transaction API error: Unable to start a transaction in the given time.",
  "meta": {
    "error": "Unable to start a transaction in the given time."
  },
  "error_code": "P2028"
}

[loclv]

@tonivj5 thank you!

[pantharshit00]

Thanks for the clear reproduction. I can reproduce this.

[codazzo]

I am getting the exact error mentioned in #10218 (comment) when using interactive transactions with Prisma 3.10.0 (MacOS 11.6.4 / M1) with PostgresSQL 13 on RDS. Moving back to non-interactive transactions fixes it:

// not working
await prisma.$transaction(async ($prisma) => {
  await $prisma.$executeRaw`SET LOCAL credential.skip_txn_data_calculation='TRUE'`;
  await $prisma.txn.createMany({
    data: newTxns
  });
});

// working
await prisma.$transaction([
  prisma.$executeRaw`SET LOCAL credential.skip_txn_data_calculation='TRUE'`,
  prisma.txn.createMany({
    data: newTxns
  }),
]);

[millsp]

Hey @codazzo, sorry to hear this. Do you perhaps have the time to share a reproduction project (setup, schema, code)?

[codazzo]

Hi @millsp, unfortunately I don't really have a self-contained reproduction example apart from those lines I posted. I understand it's not much to go by, but I just wanted to raise this in case it could help.

[millsp]

@codazzo, have you tried increasing the timeout of the transaction? Interactive transactions are expensive, so they have default timeouts, could you please try overriding the default values? Thanks

await prisma.$transaction(
  async (prisma) => {
    // Code running in a transaction...
  },
  {
    maxWait: 5000, // default: 2000
    timeout: 10000, // default: 5000
  }
)

[codazzo]

Hi @millsp - apologies for the late reply, I had a few GitHub notifications to go through. Thanks for the tip! Frustratingly, I've been unable to reproduce the issue as described since posting the comment. For now I will keep using non-interactive transactions. I will try to post a more detailed reproduction if I run into this again.

[millsp]

This was probably not a bug, but just a timeout on the query because the database sits too far. I'll mark this as closed, but feel free to ask for any help. Thank you.

[avallete]

In addition to this, for anyone interested, I did some benchmarking on transactions on my side as well, when trying to track down connections pools issues prior to 3.13.0.

In my bench, I only tested transactions and their overhead over performances. In two different contexts:
(All done with prisma default connection pool config and timeout times, and basic postgres instance on my dev machine)

1. One transaction performing many inserts (long transaction, one at a time).
2. Many transactions performing 2 inserts each (short transactions, but many at once).

For what I observed, this is my TL;DR:

• The performance cost of using transactions by itself is quite minimal, in fact, when using array transactions to do many inserts inside a single transaction we gain a little on the performance side. With interactive transactions, when they don't fail, the cost is a few milisecs over ~5-6 secs of total time.
• Basically, array transactions can handle twice as much load than "interactives" one in both tests.
• In testing context 1:
  - array transactions (pass in all the bench tests)
  - interactives transactions (fail due to expired/timeout on the last test with 1280 rows inserted at once)
• In texting context 2:
  • array transactions work with up to 640 concurrent requests, then some timeout due to "acquire" transaction time too long.
  • interactives transactions fail between "160" and "320" concurrent requests.

So if you hit performances issues with transactions, it'll be likely due to either:

• Your connexion pool isn't enough to handle the load of concurrent requests on your app. (Transaction acquire timeout error).
• Your transaction itself takes too long to execute and ends up in timeout because of default timeout values. (Transaction expired, timeout error).

You can found the code of the bench here: here it's done with "my code specific" but the logic should apply in every situations.