Node эхо-сервер деградирует 10 раз, когда потоковые каналы используются для буферизации

В node v8.1.4 и v6.11.1

Я начал со следующей реализации эхо-сервера, которую я буду называть pipe.js или pipe.

const http = require('http');

const handler = (req, res) => req.pipe(res);
http.createServer(handler).listen(3001);

И я сравнил его с wrk и следующим lua script (сокращенный для краткости), который отправит небольшое тело в качестве полезной нагрузки.

wrk.method = "POST"
wrk.body   = string.rep("a", 10)

При 2k запросах в секунду и средней задержке 44 мс производительность невелика.

Итак, я написал другую реализацию, которая использует промежуточные буферы, пока запрос завершен, а затем записывает эти буферы. Я буду называть это buffer.js или buffer.

const http = require('http');

const handler = (req, res) => {
  let buffs = [];
  req.on('data', (chunk) => {
    buffs.push(chunk);
  });
  req.on('end', () => {
    res.write(Buffer.concat(buffs));
    res.end();
  });
};
http.createServer(handler).listen(3001);

Производительность резко изменилась с помощью buffer.js, обслуживающего 20 тыс. запросов на второй при 4 мс средней латентности.

Визуально на приведенном ниже графике изображено среднее число запросов, обслуживаемых более чем 5 тиражами и различными процентилями латентности (p50 - медиана).

Таким образом, буфер на порядок лучше во всех категориях. Мой вопрос: почему?

Далее следуют мои заметки о расследовании, надеюсь, они, по крайней мере, образовательны.

Реакция

Обе реализации были созданы так, что они будут давать точные точные ответ, возвращаемый curl -D - --raw. Если дано тело 10 д'ев, то оба будут верните тот же самый ответ (с измененным временем, конечно):

HTTP/1.1 200 OK
Date: Thu, 20 Jul 2017 18:33:47 GMT
Connection: keep-alive
Transfer-Encoding: chunked

a
dddddddddd
0

Оба выводят 128 байтов (помните об этом).

Простой факт буферизации

Семантически, единственное различие между двумя реализациями состоит в том, что pipe.js записывает данные, пока запрос не закончился. Это может сделать один что в buffer.js может быть несколько событий data. Это не правда.

req.on('data', (chunk) => {
  console.log(`chunk length: ${chunk.length}`);
  buffs.push(chunk);
});
req.on('end', () => {
  console.log(`buffs length: ${buffs.length}`);
  res.write(Buffer.concat(buffs));
  res.end();
});

Эмпирически:

• Длина фрагмента всегда будет 10
• Длина буфера всегда будет 1

Поскольку будет только один кусок, что произойдет, если мы удалим буферизацию и реализуем трубу бедного человека:

const http = require('http');

const handler = (req, res) => {
  req.on('data', (chunk) => res.write(chunk));
  req.on('end', () => res.end());
};
http.createServer(handler).listen(3001);

Оказывается, это имеет ужасную производительность, как pipe.js. Я нахожу это Интересно, потому что выполнено столько же вызовов res.write и res.end с теми же параметрами. До сих пор я догадываюсь, что производительность различия связаны с отправкой данных ответа после завершения данных запроса.

Профилирование

Я профилировал оба приложения с помощью простого руководства по профилированию (--prof).

Я включил только соответствующие строки:

pipe.js

 [Summary]:
   ticks  total  nonlib   name
   2043   11.3%   14.1%  JavaScript
  11656   64.7%   80.7%  C++
     77    0.4%    0.5%  GC
   3568   19.8%          Shared libraries
    740    4.1%          Unaccounted

 [C++]:
   ticks  total  nonlib   name
   6374   35.4%   44.1%  syscall
   2589   14.4%   17.9%  writev

buffer.js

 [Summary]:
   ticks  total  nonlib   name
   2512    9.0%   16.0%  JavaScript
  11989   42.7%   76.2%  C++
    419    1.5%    2.7%  GC
  12319   43.9%          Shared libraries
   1228    4.4%          Unaccounted

 [C++]:
   ticks  total  nonlib   name
   8293   29.6%   52.7%  writev
    253    0.9%    1.6%  syscall

Мы видим, что в обеих реализациях С++ доминирует во времени; однако функции которые доминируют, меняются местами. Почти два раза на труба, но только 1% для буфера (простите мое округление). Следующий шаг, который syscalls являются виновниками?

Strace Here We Come

Вызов strace like strace -c node pipe.js даст нам краткое изложение системных вызовов. Вот главные системные вызовы:

pipe.js

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 43.91    0.014974           2      9492           epoll_wait
 25.57    0.008720           0    405693           clock_gettime
 20.09    0.006851           0     61748           writev
  6.11    0.002082           0     61803       106 write

buffer.js

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 42.56    0.007379           0    121374           writev
 32.73    0.005674           0    617056           clock_gettime
 12.26    0.002125           0    121579           epoll_ctl
 11.72    0.002032           0    121492           read
  0.62    0.000108           0      1217           epoll_wait

Верхний столбец для трубы (epoll_wait) с 44% времени составляет всего 0,6% время для буфера (увеличение 140x). Хотя существует большое время несоответствие, количество раз epoll_wait вызывается менее однообразно с трубкой, вызывающей epoll_wait ~ 8x чаще. Мы можем получить пару бит полезную информацию из этого утверждения, так что pipe вызывает epoll_wait постоянно и в среднем, эти вызовы тяжелее, чем epoll_wait для буфер.

Для буфера верхний syscall - writev, который ожидается с учетом большинства времени должно быть потрачено на запись данных в сокет.

Логически следующий шаг - взглянуть на эти операторы epoll_wait с регулярным strace, который показал буфер всегда содержал epoll_wait с 100 событий (представляющих сто соединений, используемых с wrk) и трубкой было менее 100 в большинстве случаев. Например:

pipe.js

epoll_wait(5, [.16 snip.], 1024, 0) = 16

buffer.js

epoll_wait(5, [.100 snip.], 1024, 0) = 100

Графически:

Это объясняет, почему в трубе больше epoll_wait, так как epoll_wait не обслуживает все соединения в одном цикле событий. epoll_wait для нулевые события делают его похожим на то, что цикл событий простаивает! Все это не объясняет почему epoll_wait занимает больше времени для трубы, так как с man-страницы она заявляет что epoll_wait должен немедленно вернуться:

с указанием тайм-аута, равного нулю, вызывает epoll_wait() для немедленного возврата, даже если события не доступны.

Пока справочная страница говорит, что функция немедленно возвращается, можем ли мы подтвердить это? strace -T на помощь:

Помимо поддержки того, что буфер имеет меньше вызовов, мы также видим, что почти все звонки заняли менее 100 нс. Труба имеет гораздо более интересное распределение показывая, что, хотя большинство вызовов занимает менее 100 нс, дольше и приземляться в микросекунду.

Strace нашел другую странность, а с помощью writev. Возвращаемое значение количество записанных байтов.

pipe.js

writev(11, [{"HTTP/1.1 200 OK\r\nDate: Thu, 20 J"..., 109},
  {"\r\n", 2}, {"dddddddddd", 10}, {"\r\n", 2}], 4) = 123

buffer.js

writev(11, [{"HTTP/1.1 200 OK\r\nDate: Thu, 20 J"..., 109},
  {"\r\n", 2}, {"dddddddddd", 10}, {"\r\n", 2}, {"0\r\n\r\n", 5}], 5) = 128

Помните, когда я сказал, что оба выхода 128 байтов? Ну, writev вернулся 123 байтов для канала и 128 для буфера. Разница в пяти байтах для трубы сверяется в следующем вызове write для каждого writev.

write(44, "0\r\n\r\n", 5)

И если я не ошибаюсь, блокировки write блокируются.

Заключение

Если мне нужно сделать обоснованное предположение, я бы сказал, что трубопровод, когда запрос не завершено вызывает вызовы write. Эти блокирующие вызовы значительно сокращают пропускная способность частично за счет более частых операторов epoll_wait. Зачем write вызывается вместо одного writev, который отображается в буфере, за мной. Может кто-нибудь объяснить, почему все, что я видел, происходит?

Кикер? В официальном Node.js руководство вы можете увидеть, как руководство начинается с реализации буфера, а затем перемещается трубить! Если реализация трубы в официальном руководстве не должна быть такой удар производительности, правильно?

Кроме того: последствия реального мира в этом вопросе должны быть минимальными, поскольку вопрос достаточно надуман, особенно в отношении функциональности и стороны тела, хотя это не означает, что это менее полезный вопрос. Гипотетически, ответ может выглядеть так: "Node.js использует write, чтобы обеспечить лучшую производительность в ситуациях x (где x - более реальный случай использования в мире)"

^{Раскрытие: вопрос скопирован и слегка изменен из мой пост в блоге в надежде, что это лучший способ ответить на этот вопрос}

31 июля 2017 года EDIT

Моя первоначальная гипотеза о том, что запись эхо-объекта после завершения потока запросов завершилась, повышает производительность, была опровергнута @robertklep с его readable.js(или читаемой) реализацией:

const http   = require('http');
const BUFSIZ = 2048;

const handler = (req, res) => {
  req.on('readable', _ => {
    let chunk;
    while (null !== (chunk = req.read(BUFSIZ))) {
      res.write(chunk);
    }
  });
  req.on('end', () => {
    res.end();
  });
};
http.createServer(handler).listen(3001);

Чтение выполняется на том же уровне, что и буфер при записи данных перед событием end. Если что-нибудь, это меня смущает, потому что единственная разница между прочитанной и моей начальной бедной трубой - это разница между событиями data и readable, и все же это привело к увеличению производительности 10 раз. Но мы знаем, что событие data не является по сути медленным, потому что мы использовали его в нашем буферном коде.

Для любознательных, strace на читаемых сообщениях writev выводит все выходные данные из 128 байтов, такие как buffer

Это вызывает недоумение!

Ответы

let chunk;
req.on('data', (dt) => {
    chunk=dt
});
req.on('end', () => {
    res.write(chunk);
    res.end();
});

let chunk;
req.on('data', (dt) => {
    chunk=dt;
    res.write(chunk);
    res.end();
});
req.on('end', () => {
});

let chunk;
req.on('data', (dt) => {
    chunk=dt
    res.write(chunk);
});
req.on('end', () => {
    res.end();
});

msg.connection.cork();
process.nextTick(connectionCorkNT, msg.connection);

req.on('readable',()=> {
    let chunk2;
    while (null !== (chunk2 = req.read(5))) {
        res.write(chunk2);
    }
});

1 / .05 = 20.  2000/20 = 100

1 / .005 = 200.  20000/200 = 100.