mysql2@2.3.2 seems to run CPU to 100%

[stavert]

We deployed some new code a couple of days ago into our AWS infrastructure and within a few hours we began receiving alarms of our CPUs running at 100% across our instances.

Our node/express server runs as a cluster across 8 CPUs on mulitiple instances. As the problem continues, more and more of the CPUs get bound to 100%. We've been able to prove that by locking mysql2@2.3.0 the problem doesn't exist. However, with the new 2.3.2, the problem occurs.

The following image shows the instance on the left (in top command output) is running 2.3.0 mysql2 whereas the instance on the right is running 2.3.2.

Eventually, all CPUs will become 100% in the failing case.

Thank you.

[sidorares]

that's concerning, thanks for the report @stavert .

How easy is to replicate the issue? Do you have any automated integration / perf test that can show it? If it does not require much time ideally would be great to bisect to a single commit

Can you also share your setup ( server version, node version, OS ). Do you use this module directly or from ORM/query builder?

[stavert]

Hey @sidorares!

Thanks for getting back to me!

For us, turns out it's very easy by swapping the version back and forth. As this was our prod environment, we really didn't have the luxury of debugging further once we realized this package was the culprit. So unfortunately I can't really tell you how to recreate in a small test case yet. Unfortunately, we never really observed it in our QA environment but our QA machine is an "all-in-one" environment with only a couple of processors.

Here's some additional info...

We run nodeJS v12.14.1,

Installed sequelize:

jubi.api@3.11.4 /var/www/jubi.api
└── sequelize@5.22.4

We have a ticket to move sequelize to v6 but haven't had a chance to do it yet.

OS:

NAME="Ubuntu"
VERSION="18.04.6 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.6 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic

Linux ip-172-31-46-194 4.15.0-161-generic #169-Ubuntu SMP Fri Oct 15 13:41:54 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

package.json dependencies (with exception of mysql2 locked at 2.3.0):

"@okta/jwt-verifier": "^2.3.0",
"@rali/lx-data-models": "1.0.55",
"async": "~0.9.0",
"atob": "^2.1.2",
"aws-sdk": "^2.814.0",
"bcrypt-nodejs": "~0.0.3",
"body-parser": "^1.18.2",
"btoa": "^1.2.1",
"compression": "^1.6.2",
"cookie-parser": "~1.3.3",
"csv": "^5.0.0",
"debug": "^2.6.9",
"ejs": "^3.1.6",
"email-validator": "~2.0.3",
"express": "^4.16.0",
"express-subdomain": "~1.0.2",
"fluent-ffmpeg": "~2.1.2",
"formidable": "~1.0.17",
"glob": "^5.0.15",
"gm": "^1.23.1",
"helmet": "^3.23.3",
"https": "^1.0.0",
"juice": "^8.0.0",
"less-middleware": "^3.1.0",
"log4js": "^6.3.0",
"mime": "^1.4.1",
"moment": "^2.29.1",
"mysql": "^2.18.1",
"mysql2": "2.3.0",
"node-cache": "^5.1.2",
"paralleljs": "^0.2.1",
"passport": "~0.2.0",
"passport-http": "~0.2.2",
"passport-http-bearer": "~1.0.1",
"passport-jwt": "^4.0.0",
"passport-saml": "^2.1.0",
"q": "~1.1.2",
"request": "^2.88.2",
"sequelize": "^5.22.3",
"sequelize-fixtures": "^0.8.0",
"serve-favicon": "^2.4.5",
"umzug": "^1.12.0",
"underscore": "^1.12.1",
"uuid": "^3.4.0",
"valid-url": "^1.0.9",
"xml2js": "^0.4.19"

Our sequelize connection pool config:

  pool: {
    max: 30,
    min: 5,
    idle: 1000000,
    acquire: 100000
  },

Our DB is AWS RDS MySQL, v5.7.33.

We have a lot of complicated SQL, some stored procedures and even some raw inline SQL but all called through sequelize.

Please let me know what else I can provide you.

Thanks very much!!

[stavert]

Oh, one other thing to mention... while I'm not a node deadlock/debugging expert, I did try to attach the inspector before working on the potential package changes during deployment. When I typed "pause", nothing showed up...no stack backtrace was observed.

[sidorares]

one more question - once appear, does 100% cpu load continue when you turn off the traffic? e.i is this a severe regression in performance or a bug where it completely hangs in a loop

[stavert]

For the most part yes. If I remember correctly, as I de-registered one of the instances from the load balancer, the CPUs stayed at 100%. And come to think of it, we use forever to keep the node processes running, forever stopall orphaned all the processes which were running at 100% CPU and I had to kill them manually.

We did originally think that somehow forever was causing us the problem, then we also realized we had a package inclusion of a 10 year old cluster npm instead of just relying on the nodeJS built-in. We removed that from package.json but the problem persisted and that's when I focused on DB connection stuff and got to mysql2.

[stavert]

Oh, to comment on performance, weirdly enough, our site was still relatively stable from an end user perspective. Fortunately, our load was a little low. I was able to interact with our site with no observable difference. However, we have times where we would have hundreds of users on the site and I can imagine that if this had happened during that time, we would have a significant problem on our hands.

It's still a little tough to say overall though because watching logs through all this seemed as if everything was running fine.

[sidorares]

I did a simple load test ( http server returning 4 users row, model from https://sequelize.org/master/manual/model-basics.html ) and bottleneck is mysql on my laptop.

6 cores, wrk -t 10 -c 20 -d 1m http://localhost:3000/ load test command

Running 1m test @ http://localhost:3000/
  10 threads and 20 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     7.26ms    2.46ms 104.72ms   97.39%
    Req/Sec   279.11     31.18   360.00     76.75%
  166942 requests in 1.00m, 109.22MB read
Requests/sec:   2778.66
Transfer/sec:      1.82MB

using the driver directly results in 50% better performance - 3906.30 req/sec

[ddolcimascolo]

Hi everyone,

I'm in the same boat after having reported #1418 and upgraded to 2.3.2.
My APM charts are self-explaining, showing both increased CPU usage and increased memory usage. I can also confirm node processes bumping to 100% CPU for 5 or 10 minutes, then getting back to normal. We also deploy a lot, so making node processes restart using pm2-managed rolling restarts.

The service is still given, we're just seeing higher loads and memory usage

[ddolcimascolo]

@stavert Do you use JSON columns in MySQL ?
@sidorares Do you need any help ? This problem is concerning for production services relying on your driver :)

[stavert]

HI, Not generally as far as I can tell. I'm traveling on business through Thursday this week and might not get much chance to perform further debuggimg/isolation. I will try to collect more info first chance I get.. On October 25, 2021 5:15:47 AM David DOLCIMASCOLO ***@***.***> wrote: @stavert<https://github.com/stavert> Do you use JSON columns in MySQL ? @sidorares<https://github.com/sidorares> Do you need any help ? This problem is concerning for production services relying on your driver :) — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#1432 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AM2OMTTAEGOKBEUF4YP5WJDUIUN37ANCNFSM5GQZY2PA>. Triage notifications on the go with GitHub Mobile for iOS<https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android<https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

[sidorares]

@sidorares Do you need any help ?

@ddolcimascolo yes, I need help replicating the issue. My simple initial tests were unsuccessful in finding a regression. it might be the issue is specific to a type or typeCast configuration or driver + sequelize combo, not sure yet. Once I can replicate it would be much easier for me to help finding and fixing root cause

[stavert]

Hi All, I made a little progress, with limited time today, in recreating on a smaller unused environment (non production). This was a t2 instance with just 4 cpus and I was able to get one cpu to spin. I'm hoping I can find more time tomorrow in this environment to begin to isolate further.

[sidorares]

many thanks @stavert , appreciate the effort

[stavert]

Hey All,

So I can recreate this issue at will on this test machine. It's very very easy. I just start the service, get on my site, jump a few pages and at least one cpu 100%. I've been playing with trying to connect to the node inspector remotely, tick log processing, core dumps, etc, but just haven't gotten the "secret sauce" yet to getting a good debugging experience that will give me confidence that I've narrowed down the problem (or recreation) for you. Each page on our site performs a lot of SQL via sequelize so it's just difficult to narrow down.

@sidorares what advice could you give me to debug this further? Perhaps we can jump on a call together to try to figure it out?

Let me know how you want to proceed.
Thanks.

[sidorares]

@stavert can you start with node --prof , recreate 100% cpu , wait for maybe half a minute and then run node --prof-process to process profiler log and post results here ( please make sure there is no sensitive information in the log before posting - function names etc )