Node.js 100% CPU – appel gettimeofday

J’ai un long processus node.js qui passe parfois à 100% du processeur et cesse de répondre aux requêtes. La dernière fois que cela a été fait, j’ai attaché strace d’importance au processus et voici ce que j’ai vu:

 Process 19523 attached - interrupt to quit gettimeofday({1394558574, 234192}, NULL) = 0 gettimeofday({1394558574, 235381}, NULL) = 0 gettimeofday({1394558574, 306460}, NULL) = 0 mmap(0x3edab823a000, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x3edab823a000 munmap(0x3edab823a000, 811008) = 0 munmap(0x3edab8400000, 237568) = 0 mmap(0x3edab8300000, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3edab8300000 gettimeofday({1394558574, 316435}, NULL) = 0 gettimeofday({1394558574, 316576}, NULL) = 0 gettimeofday({1394558574, 316677}, NULL) = 0 gettimeofday({1394558574, 316775}, NULL) = 0 gettimeofday({1394558574, 316879}, NULL) = 0 gettimeofday({1394558574, 316978}, NULL) = 0 gettimeofday({1394558574, 317439}, NULL) = 0 gettimeofday({1394558574, 317537}, NULL) = 0 gettimeofday({1394558574, 318139}, NULL) = 0 gettimeofday({1394558574, 318234}, NULL) = 0 gettimeofday({1394558574, 318343}, NULL) = 0 gettimeofday({1394558574, 318437}, NULL) = 0 gettimeofday({1394558574, 318530}, NULL) = 0 gettimeofday({1394558574, 318624}, NULL) = 0 gettimeofday({1394558574, 319135}, NULL) = 0 gettimeofday({1394558574, 319648}, NULL) = 0 gettimeofday({1394558574, 319769}, NULL) = 0 gettimeofday({1394558574, 319975}, NULL) = 0 futex(0x7f5b380008c8, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1394558574, 322266}, NULL) = 0 gettimeofday({1394558574, 322426}, NULL) = 0 gettimeofday({1394558574, 322520}, NULL) = 0 gettimeofday({1394558574, 322759}, NULL) = 0 gettimeofday({1394558574, 322853}, NULL) = 0 gettimeofday({1394558574, 322995}, NULL) = 0 futex(0x7f5b380008c8, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1394558574, 417614}, NULL) = 0 gettimeofday({1394558575, 386566}, NULL) = 0 gettimeofday({1394558575, 387704}, NULL) = 0 gettimeofday({1394558575, 463410}, NULL) = 0 mmap(0x24cfd260f000, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x24cfd260f000 munmap(0x24cfd260f000, 987136) = 0 munmap(0x24cfd2800000, 61440) = 0 mmap(0x24cfd2700000, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x24cfd2700000 

Cela fait beaucoup d’appels gettimeofday , et pas grand chose d’autre! Qu’est-ce qui pourrait faire en sorte que node.js rest bloqué comme ça?

MISE À JOUR : Je suis passé d’une ancienne version de node.js à 10.29 (je pense) et c’est parti. Je viens de passer à 10.33 et le problème est revenu. J’ai fait un peu plus de progrès sur le débogage cette fois-ci. Première étape:

 $ sudo strace -p 11812 -c Process 11812 attached - interrupt to quit Process 11812 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000192 0 2780 gettimeofday 0.00 0.000000 0 1390 getrusage 0.00 0.000000 0 31 futex 0.00 0.000000 0 1390 clock_gettime ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000192 5591 total 

De Node.js: Comment se connecter à un processus en cours d’exécution et déboguer le serveur avec une console? J’ai découvert comment attacher le débogueur de noeud à un processus en cours d’exécution, et voici où je suis arrivé avec ça:

 $ sudo kill -s SIGUSR1 11812 $ sudo node debug -p 11812 connecting... ok break in timers.js:79 77 } 78 79 function listOnTimeout() { 80 var msecs = this.msecs; 81 var list = this; debug> bt #0 timers.js:79:23 

Donc, il semble que ce soit définitivement lié à une timer, mais je ne sais pas comment aller plus loin dans la stack pour savoir dans quel code le problème est déclenché.

Je suppose que quelqu’un a implémenté manuellement un “setTimeout” bloquant. Cela pourrait se produire si quelqu’un ne veut pas libérer le contrôle du thread JS principal dans le but d’empêcher une situation de course potentielle.

Pour des raisons évidentes, ceci est une mauvaise pratique pour le code de production, mais je l’ai utilisé à l’occasion dans le débogage pour forcer l’exécution de processus asynchrones dans un ordre spécifique.

Vous pourriez chercher quelque chose d’idiot comme ceci:

 var mockAsyncFunction = function (cb) { setTimeout(function () { cb(null, 'dummy_result') }, 5000); }; var myResult = null; mockAsyncFunction(function (err, result) { myResult = result; }); var timeOut = 10000; // timeout in 10 sec. var timeStart = new Date().getTime(); while (1) { if (new Date().getTime() - timeStart > 10000) { break; } } console.log('DONE'); 

ou quelque chose de plus néfaste avec la récursion nextTick comme:

 var timeStart = new Date().getTime(); var recurseUntilDone = function () { if (new Date().getTime() - timeStart < 10000) { process.nextTick(recurseUntilDone); } else { console.log('Done recursing'); } }; recurseUntilDone(); 

Utilisez node-inspector pour pouvoir suspendre votre code lorsque le processeur est à 100% – mon pari est également sur un état de vérification de boucle mal implémenté jusqu’à ce qu’un certain temps soit écoulé, mais ils peuvent être difficiles à trouver.

Attachez le débogueur avec –debug lors du démarrage de node (ie. node index.js --debug ) et dans une fenêtre distincte exécutez node-inspector . Utilisez Chrome pour vous connecter à votre session de débogage (l’url est généré à partir de la commande node-inspector) et attendez que le problème survienne et suspendez l’exécution et vous devriez pouvoir le trouver.

Nous l’avons vu aussi, tant dans la production que dans le développement. Aussi à la recherche d’une réponse. Nous avons commencé à examiner le temps d’exécution du noeud, mais le problème est si rare qu’il ne reçoit aucune priorité. Parce qu’il est complètement lié au processeur, aucun appel système, c’est une capture difficile avec une strace.

Ce ne sera pas un état de vérification de boucle temporisé, car une nouvelle boucle Date (). GetTime () ne fait aucun appel à gettimeofday (dans le noeud v0.10.29; elle effectue simplement une longue série de nanosleeps dans un pid et seulement des appels futex) dans l’autre, malin, en fait). Même chose pour Date.now ().

Je ne sais pas si c’est lié, mais voici un moyen simple d’écraser un processus de noeud: utiliser un tableau en tant que queue lorsqu’il contient des données. Les symptômes sont un taux de traitement très très lent et une utilisation à 100% du processeur.

 //a = []; a = new Array(); for (i=0; i<87370; i++) a.push({}); for (i=0; i<1000000; i++) { a.shift(); a.push({}); if (i%1000 === 0) { process.stdout.write("."); //global.gc(); } } // node v0.10.29: 10k: 0.15 sec // 80k: 0.17 sec // 87369: 0.17 sec // 87370: instant 41k, then .9k per second // 87400: Array: instant 41k, then .9k per second // 87400: []: instant 28k, then .9k per second // 87400: Array, pushing 1 or 'x': .9k per second from the start // node v0.11.13: 10k: 1.94 sec // 16683: 3.87 sec // 16884: uniform 237.16 sec 

J'ai exécuté un perf record -F 997 -g node-v0.11.13 --perf-basic-prof script.js mais à peu près tout le temps est atsortingbué à Builtin_ArrayShift (5-6 emplacements hexadécimaux différents appelés de ~)

Notez que le comportement a un sharepoint basculement, en dessous duquel il est rapide, au-dessus il est lent. Le comportement 0.10 et 0.11 est différent; 0.11 semble avoir deux points de bascule (3 vitesses de points différentes). Les points de bascule ne semblent pas restr les mêmes entre les groupes de courses.

Peu importe si global.gc () est appelé ou non (avec le commutateur --expose_gc ). Peu importe si le push / shift est dans une boucle continue ou dans une boucle bloquante comme ci-dessus.

Edit: ce qui est bizarre, c’est qu’il s’agit à la fois du nombre de données et du nombre de boucles. Les boucles plus courtes sont plus rapides (même si elles sont découpées en lots de 1k).

De plus, lorsque cette condition existe, le décalage / push vers d'autres listes (vides) est également ralenti aux mêmes opérations de 0,9 ko / s (noeud v0.10.29), mais curieusement, elles peuvent se chevaucher: 10 boucles de décalage / ajout simultanées seront insérées. .9k objects / s, soit un total de 9k / sec. (Il y a donc des ressources pour 10 fois plus de débit - une manette interne alors?)

Edit: pas une manette interne; le thread lent utilise un bloc solide de 0,8 à 1,2 ms de processeur, et tous les autres threads sont bloqués jusqu'à la fin. Comme les threads concurrents doivent céder périodiquement (j'ai utilisé setImmediate), ils restnt bloqués derrière le cpu hog et ralentissent en conséquence.

La delete explicite de hachages ou de tableaux plus importants, comme le nettoyage d’un conteneur de données interne, peut également provoquer des symptômes de ce type. L’opération de noeud inhérente peut être extrêmement lente:

 h = {} for (i=0; i<200000; i++) h[i] = i; // 25,000,000 / sec for (i=0; i<1000; i++) delete h[i]; // 11,000 / sec for (i=0; i<200000; i++) delete h[i]; // 7,700 / sec a = new Array(); for (i=0; i<200000; i++) a[i] = i; // 50,000,000 / sec for (i=0; i<1000; i++) delete a[i]; // 10,000 / sec for (i=0; i<200000; i++) delete a[i]; // 8,000 / sec // and out of curiousity... for (i=0; i<200000; i++) a[i]; // 250,000,000 / sec for (i=1; i<200000; i++) a[i-1] = a[i]; // 180,000,000 / sec 

supprimer de l'arrière vers l'avant est 2x plus rapide, mais c'est toujours très lent. (note: l'affectation dans un nouveau tableau est de 50 m / s, mais dans [] c'est seulement 25 m / s)

Le ralentissement est O (n ^ 2): doubler la taille du tableau à 400k multiplie par quatre le temps d'exécution. Chaque opération de suppression est O (n) de la taille du tableau de hachage / tableau.

Le strace d'un cycle de 400k (100 secondes) ne montre aucun appel système à proprement parler et ne correspond pas au modèle gettimeofday () ci-dessus.

 ... 14:08:36.327886 munmap(0x44200000, 802816) = 0 14:08:36.328145 munmap(0xf7100000, 1183744) = 0 14:08:36.328483 clock_gettime(CLOCK_REALTIME, {1418584116, 328495018}) = 0 14:08:36.328540 clock_gettime(CLOCK_REALTIME, {1418584116, 328551680}) = 0 14:08:36.328581 clock_gettime(CLOCK_REALTIME, {1418584116, 328592628}) = 0 14:08:36.328633 futex(0x8e79a7c, FUTEX_WAKE_PRIVATE, 1) = 1 14:09:03.130336 clock_gettime(CLOCK_REALTIME, {1418584143, 130406483}) = 0 14:09:03.130479 clock_gettime(CLOCK_REALTIME, {1418584143, 130503357}) = 0 14:09:03.130560 futex(0x8e79a7c, FUTEX_WAKE_PRIVATE, 1) = 1 14:09:37.090127 clock_gettime(CLOCK_REALTIME, {1418584177, 90195108}) = 0 14:09:37.090271 clock_gettime(CLOCK_REALTIME, {1418584177, 90296760}) = 0 14:09:37.090355 futex(0x8e79a7c, FUTEX_WAKE_PRIVATE, 1) = 1 14:10:17.588552 mmap2(0x3f302000, 4231168, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x3f302000 14:10:17.588694 munmap(0x3f302000, 1040384) = 0 14:10:17.588768 munmap(0x3f709000, 8192) = 0 ...