Node process does not end and but CPU utilization at 100%

[nachogiljaldo]

I have been investigating a problem that is causing trouble on our test suite and I managed to trace it to mysql2. This script allows reproducing it:

Reproduction instructions

// create database test;
// create table test(id int(10) unsigned not null auto_increment, primary key (`id`));
// insert into test(id) values(1);
const mysql = require('mysql2/promise');
async function main() {
    console.log("===========================>", "foo");
    const connection = await mysql.createConnection({
        host: 'localhost',
        user: 'root',
        database: 'test',
        password: 'rootpass',
        connectionLimit: 1234,
    });
    for (let ix = 0; ix < 157; ix++) {
        await basicHanging3(connection);
    }
    connection.destroy();
    console.log('=========================>', 'Done');
}


async function basicHanging3(connection) {
    let query = 'SELECT ';
    let limit = 1000;
    for (let i = 0; i < limit; i++) {
      query += `t.id AS t_id_${i},`;
    }
    query += `t.id AS t_id_${limit}`;
    query += ' FROM test as t';
    const [rows] = await connection.query(
      query,
    );
    return rows;
}

main();

{
  "name": "reproducer",
  "version": "1.0.0",
  "main": "index.js",
  "license": "MIT",
  "dependencies": {
    "mysql2": "^3.4.2",
    "yarn": "^1.22.19"
  }
}

It happens with multiple node versions (v16.14.0, v18.16.0 are some of those I tested). For node 20.3.1 it happens, but you need to raise the 157 iterations.

In our tests we run thousands of DB queries which seems to be reaching this threshold and causing the process to "hung" (it eventually exits, but it takes a few minutes). As you can imagine this is a huge pain on CI because the "exit" takes as much as the test suite itself.

2 other interesting things to note:

• the CPU for the node process stays at 100% even though nothing is supposedly being done (we checked to see if it is gc using --trace-gc but no traces are output after "Done")
• if no data is returned (you can delete the insert statement on index.js) it seems to be ok (at least I raised the number of iterations to 10k and it finished just fine)
• if you have less columns then you require more iterations to achieve the effect

Netstat shows the DB connection is closed while the process is waiting:

$ sudo netstat -alpW | grep -i <my_pid> 

shows no output.

[nachogiljaldo]

Sorry, I just noticed #2080 and I believe they could be related, my reproduction seems to work correctly with 2.3.0 (which is the one that @rogerho1224 was using and worked for them).

[sidorares]

thanks @nachogiljaldo I can reproduce the issue

[nachogiljaldo]

No worries @sidorares if it helps, it might be intimately related to #2080 since I can confirm that using 2.3.0 fixed the issue for me.

[sidorares]

What is strange is that process hangs with 100% cpu just before exit. I suspect some combination of GC and large number of objects with large number of fields. Profiler does not pick that and shows a very small number of ticks in the main code and in the GC, the ticks during the "frozen" part are in "unaccounted" section

The difference with 2.3.0 is highlighted in #2055, I'll try to see if changing that part only helps.

[sidorares]

@nachogiljaldo what is your os / architecture? Not sure if that matters, I'm seeing the issue on m1 mac

[nachogiljaldo]

I'm not sure if it's GC related, (not a node internals expert,but) I ran my reproduction with --trace-gc and the gc logs stop right with the "Done" message.

[nachogiljaldo]

Mine is Ubuntu x86_64. But a colleague of mine has the same issue with similar effects with M1.

[sidorares]

typically GC related performance problems are visible in the profiler log, maybe we see a bug in GC
The script works fine even with large number of repeats and only shows problem just before the exit

[sidorares]

@nachogiljaldo I reduced script to a version with no external dependencies, could you try to run first file from https://gist.github.com/sidorares/128160e6b3dea1da3ad45cd672651d2d ? Still not sure what's going on, but switching to setting fields in the constructor hides the issue ( repro2.js )

cc @testn

[sidorares]

Actually it does finish, eventually. First script from gist finishes in about 5 minutes time
I think we are hitting some V8 edge case where performance is not great ( o(n^2) for the number of fields? )

[sidorares]

I think I'll try to file this to the core node

[sidorares]

nodejs/node#48581

[sidorares]

since there is reliable repro without dependency on mysql2 I'll try to "fix" the issue by converting parser to add fields in the constructor

Actually, I think the better solution would be to cap the number of fields in dynamically compiled parser, if the number is over the limit use "interpreting" parser instead ( e.g in each row iterate over every column and read the code based on the column type ). We used to have "interpreting" parser a while ago -

node-mysql2/lib/commands/query.js

Lines 59 to 69 in 04f07f8

	var row = Packets.TextRow.fromPacket(packet);
	// TODO: here we'll have dynamically pre-compiled and cached row parser
	if (true) // TODO: think of API to store raw copulns array (most probably connection options flags)
	{
	var r = {};
	for (var i = 0; i < row.columns.length; ++i)
	{
	var name = this.fields[i].name;
	r[name] = row.columns[i];
	}