Horrible performance when upgrading from node v6.7.0 to v8.11.1

Question

I have been spending the past few days investigating poor performance for an websocket graphql api application when upgrading node from v6.x to v8.x.

I have taken lots of flame graphs but I cannot figure out where the bottleneck is. Does anyone know what ___kdebug_trace_string (in c++) is? It appears to be taking significantly more time in my application after the upgrade.

Check out this flame graph:

Also check out these profile logs:

node v8.x profile log (slow): https://pastebin.com/2W65BZC8

node v6.x profile log: https://pastebin.com/BL4kM7B7

Thanks ahead!

Answer 1

kdebug_trace_string is a syscall that has been added to XNU in october 2015 for iOS 9 and OS X 10.11.

It's part of kdebug, the main XNU built-in debugging facility. When reading kdebug_trace.c, I found the following note in the comments :

Note that the userspace API is chosing to optimize fastpath, non-error performance by eliding validation of each debugid. This means that error cases which could have been caught in userspace will make a syscall before returning with the correct error code. This tradeoff in performance is intentional.

It explains why ___kdebug_trace_string is taking so much place on your flame graph.

---

This is just a guess and all of this is wrong if you're not using an Apple computer, but then, if it's wrong, I really want to know what's causing this mess.

---

Assuming I'm right, if kdebug_trace_string is called, so it means that node runs some kind of debugging utility. I downloaded node-v8.11.1-darwin-x64, and found the following line in node/config.gypi :

 'node_use_dtrace': 'true',

So node v8.11.1 uses dtrace.
Then, looking at this line in osx/src/dtrace/libdtrace/dt_open.c, we can assume that dtrace uses kdebug_trace_string

So to fix this, one would want to prevent node from using dtrace. According to this answer, " When Node starts up, the .gypi is loaded like any other settings file.". So maybe you should juste set node_use_dtrace to false

BUT

I don't understand why you didn't face the same problem with node v6.7.0 :

• In node-v6.7.0-darwin-x64, node_use_dtrace is set to true too
• Node v6.7 approx. release date : 2016-09-28
• OS X 10.11 approx release date : 2015-09-06

Could you tell me the value of node_use_dtrace for your two versions of node ?

Hope it helps, and hope I'm right,
Best regards