Node.js 100% CPU - вызов gettimeofday

Ответ 1

Я предполагаю, что кто-то вручную реализовал блокировку "setTimeout". Это может произойти, если кто-то не хочет освобождать контроль над основным потоком JS, чтобы предотвратить потенциальное состояние гонки.

По понятным причинам это плохая практика для производственного кода, но я иногда использовал его для отладки, чтобы заставить асинхронные процессы выполнять в определенном порядке.

Вы можете искать что-то глупое:

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

или что-то более гнусное с рекурсией nextTick вроде:

var timeStart = new Date().getTime();

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

recurseUntilDone();

Ответ 2

Используйте node-inspector, чтобы иметь возможность приостанавливать ваш код, когда процессор равен 100% - моя ставка также относится к некоторой плохо реализованной проверке цикла пока не пройдет определенное время, но их трудно найти.

Прикрепите отладчик с помощью --debug при запуске node (т.е. node index.js --debug) и в отдельном окне запустите node-inspector. Используйте Chrome для подключения к сеансу отладки (url выводится из команды node -indpector) и дождитесь, пока проблема не возникнет, и приостановите выполнение, и вы сможете ее найти.

Ответ 3

Мы это видели и в производстве, и в разработке. Также ищет ответ. Мы начали исследовать время выполнения node, но проблема настолько редка, что не получает никакого приоритета. Поскольку он полностью привязан к CPU, никаких системных вызовов он не фиксирует с помощью strace.

Это не будет синхронизированное состояние проверки цикла, потому что новый цикл Date(). getTime() не делает никаких вызовов gettimeofday (в node v0.10.29; он просто делает длинную серию наноселексов в одном pid и только futex вызывает в другом. Умный, на самом деле). То же самое для Date.now().

Ответ 4

не знаю, связано ли это, но вот простой способ раздавить процесс node: используйте массив как очередь, когда в нем есть данные. Симптомы - очень медленная скорость обработки и 100% -ный процессор.

//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, но в значительной степени все время приписывается Builtin_ArrayShift (5-6 разных гексагонов, вызываемых из ~)

Обратите внимание, что поведение имеет точку переключения, ниже которой она быстро, над ней медленная. Поведение 0.10 и 0.11 отличается; 0.11, кажется, имеет две точки переключения (3 разных скорости точек). Точки переключения не кажутся одинаковыми между группами прогонов.

Не имеет значения, вызывается ли global.gc() или нет (с помощью переключателя --expose_gc). Не имеет значения, находится ли push/shift в непрерывном или в блокирующем цикле, как показано выше.

Редактирование: что странно, так как это зависит как от данных, так и от числа циклов. Более короткие циклы работают быстрее (даже если они разделены на 1 тыс. Партий).

Кроме того, когда это условие существует, сдвиг/нажатие на другие (пустые) списки также замедляется до того же .9k ops/sec (node v0.10.29), но любопытно, что они могут перекрываться: 10 одновременных сдвигов/добавьте петли, каждый из которых будет вставлять .9k items/sec, т.е. в сумме 9k/sec. (Итак, есть ресурсы для 10-кратной пропускной способности - внутренний дроссель?)

Изменить: не внутренний дроссель; медленная нить использует сплошной кусок 0,8 - 1,2 мс процессора, а все остальные потоки блокируются до тех пор, пока он не завершится. Поскольку параллельные потоки должны периодически выдаваться (я использовал setImmediate), они продолжают блокироваться за процессором cpu и соответственно замедляют ход.

Ответ 5

Явный delete из более крупных хэшей или массивов, таких как очистка внутреннего контейнера данных, также может вызывать подобные симптомы. Вложенная операция node может быть ужасно медленной:

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

удаление из спины к фронту в 2 раза быстрее, но это все еще очень медленно. (примечание: назначение в новый массив 50 м/с, но в [] - только 25 м/с)

Замедление - это O (n ^ 2): удвоение размера массива до 400 тыс. умножает время выполнения. Каждая операция удаления представляет собой O (n) размера хэша/массива.

Трассировка 400k (100 секунд) не отображает никаких вызовов sytem, ​​о которых можно говорить, и не соответствует шаблону gettimeofday(), показанному выше.

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