3

Beware the performance cost of async_hooks (Node 8)

 2 years ago
source link: https://blog.jakubholy.net/2018/11/01/beware-the-performance-cost-of-async_hooks-node-8/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

Beware the performance cost of async_hooks (Node 8)

November 1, 2018

I was excited about async_hooks having finally landed in Node.js 8, as it would enable me to share important troubleshooting information with all code involved in handling a particular request. However it turned out to have terrible impact of our CPU usage (YMMV):

3jnASSSx-wRJwWyFI6yxYklPZInqHJKuXcKJlIP-UoozB9sHi1bUW_pC5A2_XLWYWzg1AdKQqwGUXaZN9VvTZs8fij-JsefZ4jGWzvUzQA64brNTY0lB4Wp5C497hxP0Da55C6k4qcOmlPTwBr8B4mumQyXhmuYc2Op_Ng2zA1nPqf3ZdcjmhGerqYRTfHiLr5aS7_nB6D2upWAZ3phZm5KgWF4E7VsuRZs5PFuk_NaFjDNIKLx2mkRFee1VbqLxYYlPKaLuTk0_jX7yw0UGHZrCtnk5S5J66IaxT-eAuDG7HEtHe5qtY9N6odD5xaghzKcAGJBAHJHPBdxT8UiEFEEOmo6ES20_KjsJAocFlYir1rLkgbRRBXl96t8gphbo4u1CTxRsYkOcQateop9q1lMgRM3vzBtIkaTi306ey0-wmVMr6nwZKjrqvlOiNVExJCqvCtA8ny3O8gBr57LCEqbsVpd8uDiDarL8xv8jKwqYPlH6w_4Ib-5FsCejrpbxDYWuatW1z43OEHg5gAQbcH8G4e0cckYVS9568HLlwZY-3yzY3bN3bYuU2GqcACjgjWcMN_uoTivgK9_w55fKsW4DmJ6fS6XNsIGAH2JQthCi_pQQBS-_Gw3ZkvaDFeRgGpCqcFu-2_Qi3PzyhXLBVOFj=w524-h221-no

This was quite extreme and is likely related to the way how our application works and uses Promises. Do your own testing to measure the actual impact in your app.

However I am not the only one who has seen some performance hit from async_hooks - see https://github.com/bmeurer/async-hooks-performance-impact, in particular:

Here the results of running the Promise micro benchmarks with and without async_hooks enabled:BenchmarkNode 8.9.4Node 9.4.0Bluebird-doxbee (regular)226 ms189 msBluebird-doxbee (init hook)383 ms341 msBluebird-doxbee (all hooks)440 ms411 msBluebird-parallel (regular)924 ms696 msBluebird-parallel (init hook)1380 ms1050 msBluebird-parallel (all hooks)1488 ms1220 msWikipedia (regular)993 ms804 msWikipedia (init hook)2025 ms1893 msWikipedia (all hooks)2109 ms2124 msTo confirm the impact of async_hook on our app, I have performed 3 performance tests:

CPU usage without async_hooks (Node 8)
It is difficult to see but the mean CPU usage is perhaps around 60% here.

tKVlaTA7MfGOz-vW6DzzkcIgnCg4ufGHX0ozpWo85446LatJ8boXGzQc0qY6hcqep63nS6T38u4oLrZtKi_tlnHgWKzzSHuSjDKYhJfDpOcmbPKNIUIadO7U1QysgrTIJhDtGAr-A3m6MNBxfQeJNe7Yj1mvfqZZg1Rb9i34115Ag_8Ww8A8NU_P5pmuA_5-9oeN5CcANW7A2oVZeSwdEIHJlsAU7360Aqb4pH1Ngk-3X5-lDNlcTe0lm_pMHyvsSlDwPt4uLqZfGeKGKdhQy7y4VKLrJgIZnHkkjk3iDqmAL5CvE6Qf9Au3KwDwqWDcO8r9nBREOaUFyIXcKBr1ujP1rqFmrYk2V-p6Ni2ma2hFZoPprTrsnqdRrmk-8nv9xNFEUBfJx0YmPLp38q2Kg6NldrdaIarrVaTO7wAg7c43XYu1ae79iMmo_rs0PCBgcxSaHB2s0VO-E55EWxF53Us1h4Dm1IC2ktIu14QKRAgYmOjwRLl80hswHLm4NfBWn1VGcNAY1exFvtHwMZMp0N-ELYgcZaF3XgkD-Xu6YLZVAi-kAdZh7ZTZXlXfikdK94mh4OBW8NjnCWrbcuIFockhuLQaDe-h95awlCExdW3TNL3bLDYgViiXAn24w7t0yOVtL8Odk6hQYzirIfLgkDIE=w500-h378-no
CPU usage with "no-op" async_hooks (Node 8)
Here the CPU jumped to 100%.

l_QPdAzalw-dGZpTVVFUgSRE9elcnrP1f3yloVU9tnN182H08p1Wg7WSEjQkOBnKm327XW3IIISUALa84W4pBihWKh6c8-u_az852lrudy6zH3FhAQJKIC6FuUNRPgYC_oNq7VqIHcAfxmkomvY6zH1Dlp2MxS6cMkJo5tE1_mntia-grVlcNezg0DabrefrvTkdzrMZzPDMRxZjF0JxmlfLTKlmiBBdu9mMaBYpmMq0mg8ZCwCV_BngqlHtuGp8N2ZwJjqqOnZe1HzeA_d2FzdKoYBcBaGpO3dX7uEQgZvtZTYucV4G44iwihfLfnDjV6YyiDPTHw2GXIDi-iOLaOasCjkZ0o3TXySnv3hv7z3mWiJDBdCZnKDFJwuWa_w234EChDuMsoG9wxH-1hOdgUkC4SKu06XsUCVPiIZ7_OsbQbPb1q4km8IlaoJ3Rnb6q6HcuKySMij6WAm2oApkHjY42cnZowyi0QthYiJ3FcJx9lgcClHRYIyDxxLtKbIbV85DtbNDR0zjei4acDklZb5x8z12BsjqqCy92JWo_lEgepqVatYGhZiYSwdFGEDQM52sSqgjqrNQr12NLyB1Hsdyj_KzMv4eolHhqvYWXABBS-jFEfJNbmZsW9poau1ZiaAogkQXZaE08rzkUql2DFyr=w500-h378-no
CPU usage with "no-op" async_hooks (Node 11)
The same as above, but using Node 11 for comparison. I recorded it for just a few minutes but the CPU usage is still around 100%:

_5FI-y2oCB9eNmG9f6VhCMJNQW6JeF--H1Qe-gLppBll2E32agzyxBhpp8odQM1-WhSyatvL-StQ-iC4YGfWsPkikzBe19p6g7Hr6toJ5C2zU3dlc-XJJBb14Gpx6JMwQyvXYvjah_rtJT_c0pYnTnJmFypfuRneVi62xHk3W7S39TDqv4FMVY2JNg593alspr8ErCEEDLfAe1I0Kph-TX79i3yMTVzrJyp0Bj6bOutMmNsKnXsimR2PR1LRZD9l2v6sBkcZAebpaXHIz_VmJq6_14Hp8bgoYBPHkGsB74Nj0IPBQ2tHKC8yASOsrHfvZCRssy2FD6AYJHzD2dMlCNGUQODMfmhgp-FyRxQH9HZC1OJ29d7Z8h0o5ksl5wclxlVJacjZ8GD4l-yKVWm_5PMaObz1tYT1-4T3WctSzo6BBDql7Vd8EW4LF1hzuZI93fQQ6ydK20rM4l5RABwP7bQ2Dj72ONqhHMtS24TVTF8kOR1UiKYgMA9xvtZr4qCHr5a9vk4Zh9zQRoaaHCE5YYQXWllC1xDJqYwtDOLrJB6lIFTOtQ_KhEAbMCdTEuhJjZ27NUH2tlej-aRFMsbzYQ0DILHKdwYXCyyV1fRnfCJLHYAr-nykKlk5CLdvp-52TVD94KVdWYLlKC5-NYx6WkEH=w500-h378-no

The code

This is the relevant code:

const asyncHooks = require('async_hooks'); // Node 8.9+const querystring = require('querystring');const crypto = require("crypto");const context = {};function createHooks() { function init(asyncId, type, triggerId, resource) { // if (context[triggerId]) { // context[asyncId] = context[triggerId]; // } } function destroy(asyncId) { // delete context[asyncId]; } const asyncHook = asyncHooks.createHook({ init, destroy }); asyncHook.enable();}createHooks()


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK