tutorial node instalar ejemplos cli javascript linux node.js strace

javascript - instalar - node js install



Node.js 100% CPU-llamada gettimeofday (5)

Mi conjetura es que alguien implementó manualmente un bloqueo "setTimeout". Esto podría suceder si alguien no quiere liberar el control del hilo JS principal en un esfuerzo por evitar una posible condición de carrera.

Por razones obvias, esta es una mala práctica para el código de producción, pero en ocasiones la he usado en la depuración para forzar que los procesos asíncronos se ejecuten en un orden específico.

Podrías buscar algo tonto como este:

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'');

o algo más nefasto con la siguiente recursión de Tick como:

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

Tengo un proceso node.js de larga ejecución que a veces salta al 100% de la CPU y deja de responder a las solicitudes. La última vez que hizo esto strace una strace al proceso, y esto es lo que vi:

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

Eso es un montón de llamadas de gettimeofday , y no mucho más! ¿Qué podría hacer que node.js se atasque de esta manera?

ACTUALIZACIÓN : Actualicé de una versión anterior de node.js a 10.29 (creo) y esto desapareció. Acabo de actualizar a 10.33 y el problema ha regresado. He hecho un poco más de progreso en la depuración esta vez. Primera strace:

$ 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: ¿Cómo adjuntar a un proceso en ejecución y depurar el servidor con una consola? Descubrí cómo adjuntar el depurador de nodo a un proceso en ejecución, y aquí es donde llegué con eso:

$ 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

Así que parece que definitivamente está relacionado con un temporizador, pero no sé cómo avanzar más en la pila para descubrir en qué parte del código se está activando el problema.

Use node-inspector para poder pausar su código cuando la CPU está al 100%. Mi apuesta también se encuentra en un estado de verificación de bucle mal implementado hasta que haya transcurrido cierto tiempo, pero pueden ser difíciles de encontrar.

Adjunte el depurador con --debug al iniciar el nodo (es decir, node index.js --debug ) y en una ventana separada, ejecute node-inspector . Use Chrome para conectarse a su sesión de depuración (la url se envía desde el comando node-inspector) y espere hasta que ocurra el problema y pause la ejecución para que pueda encontrarlo.

Vimos esto también, tanto en producción como en desarrollo. También buscando una respuesta. Comenzamos a investigar el tiempo de ejecución del nodo, pero el problema es tan poco frecuente que no tiene ninguna prioridad. Debido a que está completamente vinculado a la CPU, no hay llamadas al sistema, es difícil de capturar con una strace.

No será un estado de comprobación de bucle temporizado, porque un nuevo bucle Date (). GetTime () no realiza ninguna llamada a gettimeofday (en el nodo v0.10.29; solo hace una larga serie de nanosleeps en una llamada pid y futex) en el otro. Inteligente, en realidad). Lo mismo para Date.now ().

la delete explícita de hashes o matrices más grandes, como la limpieza de un contenedor de datos interno, también podría causar síntomas como este. La operación del nodo inherente puede ser abismalmente lenta:

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

borrar de atrás hacia delante es 2 veces más rápido, pero sigue siendo muy lento. (nota: la asignación a una nueva matriz es de 50 m / s, pero en [] solo 25 m / s)

La ralentización es O (n ^ 2): duplicar el tamaño del arreglo a 400k cuadruplica el tiempo de ejecución. Cada operación de eliminación es O (n) del tamaño del hash / array.

La carrera de una carrera de 400k (100 segundos) no muestra ninguna llamada de sistema, y ​​no coincide con el patrón gettimeofday () que se vio anteriormente.

... 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 ...

no sé si está relacionado, pero aquí hay una manera simple de aplastar un proceso de nodo: use una matriz como una cola cuando contiene datos. Los síntomas son una tasa de procesamiento muy lenta y un 100% de uso de la CPU.

//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

perf record -F 997 -g node-v0.11.13 --perf-basic-prof script.js pero casi todo el tiempo se atribuye a Builtin_ArrayShift (5-6 ubicaciones hexadecimales diferentes llamadas desde ~)

Tenga en cuenta que el comportamiento tiene un punto de conmutación, por debajo del cual es rápido, por encima de es lento. El comportamiento 0.10 y 0.11 es diferente; 0.11 parece tener dos puntos de alternancia (3 velocidades diferentes de puntos). Los puntos de alternancia no parecen permanecer iguales entre grupos de carreras.

No importa si se invoca global.gc () o no (con el interruptor --expose_gc ). No importa si el empuje / cambio está en un circuito continuo o en un bucle de bloqueo como el de arriba.

Edición: lo extraño es que esto depende tanto del recuento de datos como del bucle. Los bucles más cortos se ejecutan más rápido (aunque se dividen en lotes de 1k).

Además, cuando existe esta condición, el desplazamiento / empuje a otras listas (vacías) también se ralentiza a la misma .9k ops / sec (nodo v0.10.29), pero, curiosamente, se pueden superponer: se insertarán 10 bucles de cambio concurrente / adjunto al mismo tiempo .9k elementos / seg, es decir, un total de 9k / seg. (Entonces, hay recursos para 10 veces más rendimiento, ¿un acelerador interno, entonces?)

Edición: no es un acelerador interno; el subproceso lento está utilizando un fragmento sólido de 0,8 - 1,2 ms de CPU, y todos los demás subprocesos se bloquean hasta que finaliza. Dado que los subprocesos simultáneos deben producirse periódicamente (usé setImmediate), siguen siendo bloqueados detrás de la CPU cpu y hacen un progreso correspondientemente lento.