С++ версия сервера. Не полностью отдаёт HTML для IFRAME..

[degtyaryov]

Здравствуйте, Дмитрий!

Perl версия не справляется с рассылками в канал ограниченному списку пользователей, упирается в процессор и в результате принимает от PHP каждую команду за 5-8 секунд, что приводит к неработоспособности сайта. Если делать все каналы уникальными и не делать массовых рассылок, то пока справляется, но тоже близок к 100% ЦПУ.

Решил попробовать C++ версию. Протестировал на тестовом сервере, никаких проблем не обнаружил. Все прекрасно работало. А на боевом сервере возникла проблема.

Если на самом сервере выполнить:

telnet comet.site.ru 80

get /multiplexor/?identifier=IFRAME&HOST=site.ru&version=1.32.3

Здесь всё не влазит, поэтому концовка здесь: http://forum.dklab.ru/viewtopic.php?p=196870#196870

[dimikot]

Давайте, наверное, все же лучше тут переписываться.

Вопрос у вас был такой:

Если на самом сервере выполнить:
telnet comet.site.ru 80
get /multiplexor/?identifier=IFRAME&HOST=site.ru&version=1.32.3
получаем все ОК.
А если тоже самое выполнить с сети интернет или с др. сервера того дата центра, то получаем не всё.
tcpdump говорит что именно dklab_realplexor закрывает соединение.
Файл Realplexor/Common.h строка 99:
fh->write(content);
Вывел перед ней содержимое content - не обрезано, содержит всё, а fh->write в сокет выдает не всё.
Почему так происходит? Как это можно исправить? Заранее спасибо..

Я было подумал вначале, что write мог не весь контент за раз отдавать. Но потом освежил память и понял, что write как раз нормально написан:

int write(const char* buf, size_t len)
{
    while (true) {
        int n = ::write(fh, buf, len);
        if (n < 0) return -1;
        if (n == (int)len) return 1;
        len -= n;
        buf += n;
    }
}

Видите, он просто не выйдет из цикла до тех пор, пока не скормит ядру все данные, какими бы порциями оно их ни принимало. Сокет создается unbuffered, так что никакого flush для него делать не нужно, по идее.

Может быть, происходит вылет по ошибке, возвращаемой write? Вы можете это проверить у себя, вставив там вместе с return -1 отладочную печать? (Или просто приведите логи realplexor-а - там должен писаться статус вроде как, если VERBOSITY=3.)

[dimikot]

Думаю, кстати, что дело может быть в следующем:

EAGAIN or EWOULDBLOCK
The socket is marked nonblocking and the requested operation would block. POSIX.1-2001 allows either error to be returned for this case, and does not require these constants to have the same value, so a portable application should check for both possibilities.

Там как раз неблокирующий режим устанавливается для сокета, и он может вылетать по EAGAIN, если в системе не хватает буферов для приема данных.

Попробуйте, пожалуйста, эксперимент с диагностикой, который я выше описал. Заодно там и errno тоже выведите.

[degtyaryov]

strace:

clock_gettime(CLOCK_MONOTONIC, {634478, 882726474}) = 0
clock_gettime(CLOCK_MONOTONIC, {634478, 882834288}) = 0
epoll_wait(4, {{EPOLLIN, {u32=3, u64=4294967299}}}, 64, 59743) = 1
clock_gettime(CLOCK_MONOTONIC, {634485, 293758263}) = 0
accept(3, {sa_family=AF_INET, sin_port=htons(12450), sin_addr=inet_addr("94.50.180.233")}, [16]) = 10
fcntl(10, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK) = 0
write(1, "[Thu Feb 2 15:19:03 2012] WAIT:"..., 173) = 173
epoll_ctl(4, EPOLL_CTL_ADD, 10, {EPOLLIN, {u32=10, u64=1043677052938}}) = 0
clock_gettime(CLOCK_MONOTONIC, {634485, 294843386}) = 0
epoll_wait(4, {{EPOLLIN, {u32=10, u64=1043677052938}}}, 64, 57250) = 1
clock_gettime(CLOCK_MONOTONIC, {634489, 734513645}) = 0
read(10, "get /multiplexor/?identifier=IFR"..., 32768) = 67
write(1, "[Thu Feb 2 15:19:08 2012] WAIT:"..., 169) = 169
write(1, "[Thu Feb 2 15:19:08 2012] WAIT:"..., 195) = 195
write(1, "[Thu Feb 2 15:19:08 2012] WAIT:"..., 4096) = 4096
write(1, "d on response arrival.\n \t_onr"..., 4096) = 4096
write(1, "mlhttp) {\n\t\t\tvar xhr = this._las"..., 788) = 788
write(10, "HTTP/1.1 200 OK\r\n", 17) = 17
write(10, "Connection: close\r\n", 19) = 19
write(10, "Content-Type: text/html; charset"..., 40) = 40
write(10, "Last-Modified: Thu, 12 Jan 2012 "..., 46) = 46
write(10, "Expires: Wed, 08 Jul 2037 22:53:"..., 40) = 40
write(10, "Cache-Control: public\r\n", 23) = 23
write(10, "\r\n", 2) = 2
write(10, "\n\n<script language=""..., 8827) = 6730
write(10, "(always trail\n\t\t\t// the data wit"..., 2097) = -1 EAGAIN (Resource temporarily unavailable)
shutdown(10, SHUT_RDWR) = 0
clock_gettime(CLOCK_MONOTONIC, {634489, 736886657}) = 0
epoll_wait(4, {{EPOLLIN|EPOLLHUP, {u32=10, u64=1043677052938}}}, 64, 52808) = 1
epoll_ctl(4, EPOLL_CTL_MOD, 10, {EPOLLIN, {u32=10, u64=1043677052938}}) = 0
clock_gettime(CLOCK_MONOTONIC, {634489, 737057458}) = 0
read(10, "", 32768) = 0
write(1, "[Thu Feb 2 15:19:08 2012] WAIT:"..., 173) = 173
close(10) = 0
clock_gettime(CLOCK_MONOTONIC, {634489, 737372868}) = 0
epoll_wait(4, <unfinished ...>

[degtyaryov]

log:
Feb 2 19:19:03 titan realplexor/dklab_realplexor.conf: [Thu Feb 2 15:19:03 2012] WAIT: 94.50.180.233:41520: DEBUG: connection opened
Feb 2 19:19:03 titan realplexor/dklab_realplexor.conf: [pairs_by_fhs=0 data_to_send=0 connected_fhs=0 online_timers=0 cleanup_timers=0 events=201]
Feb 2 19:19:08 titan realplexor/dklab_realplexor.conf: [Thu Feb 2 15:19:08 2012] WAIT: 94.50.180.233:41520: DEBUG: read 67 bytes
Feb 2 19:19:08 titan realplexor/dklab_realplexor.conf: [pairs_by_fhs=0 data_to_send=0 connected_fhs=0 online_timers=0 cleanup_timers=0 events=201]
Feb 2 19:19:08 titan realplexor/dklab_realplexor.conf: [Thu Feb 2 15:19:08 2012] WAIT: 94.50.180.233:41520: DEBUG: IFRAME marker received, sending content
Feb 2 19:19:08 titan realplexor/dklab_realplexor.conf: [pairs_by_fhs=0 data_to_send=0 connected_fhs=0 online_timers=0 cleanup_timers=0 events=201]
Feb 2 19:19:08 titan realplexor/dklab_realplexor.conf: [pairs_by_fhs=0 data_to_send=0 connected_fhs=0 online_timers=0 cleanup_timers=0 events=201]
Feb 2 19:19:08 titan realplexor/dklab_realplexor.conf: [Thu Feb 2 15:19:08 2012] WAIT: 94.50.180.233:41520: DEBUG: connection closed
Feb 2 19:19:08 titan realplexor/dklab_realplexor.conf: [pairs_by_fhs=0 data_to_send=0 connected_fhs=0 online_timers=0 cleanup_timers=0 events=201]

[degtyaryov]

согласно http://pubs.opengroup.org/onlinepubs/009695399/functions/write.html
переписал write следующим образом:
int write(const char* buf, size_t len)
{
while (true) {
int n = ::write(fh, buf, len);
if (n == (int)len) return 1;
if (n<0)
{
if (errno != EAGAIN) return -1;
}
else
{
len -= n;
buf += n;
}
}
}
сейчас как бы "ЗАРАБОТАЛО"

Хотелось бы Ваш вердикт, т.к. на c++ я давно ничего не писал и с сокетами дел не имел.

[dimikot]

Ну вы этим как бы busy wait устроили, это не очень хорошо - нагрузка значительно увеличивается. Того же можно было добиться, убрав неблокирующий режим с сокета, да только неправильно это - устраивать блокировки в event-driven программах (т.к. пока крутится этот цикл с EAGAIN, остальные соединения будут ждать, т.е. вся работа, фактически, встает).

Спасибо за ваше исследование, причины теперь ясны. Исправить, правда, проблему "чисто" довольно сложно будет. Я попробую на досуге.

[ZooKeeper]

Что-то удалось придумать по поводу данного бага?

Появляется спонтанно, только у некоторых клиентов, поэтому отловить получилось не сразу

[degtyaryov]

Я пустил всё через nginx с буферизцией(perl версия от этого тоже сильно расслабляется), а так как nginx и dklab_realplexor на одной машине, то такая проблема не возникает. Ну и для надёжности я вставил свой код который предлагал если вдруг служится EAGAIN, то контент отдастся полностью.

Так же чтобы не упираться в процессор, я запустил 2 dklab_realplexor чтобы работали 2 ядра процессора. Всё это позволило даже при большом онлайн иметь загруженность процессора не более 10%.

[ZooKeeper]

Проблема воспроизводится очень непредсказуемо и отловить гарантированно не получилось. Через какое-то время пропадало само.
Решил подменой статичной html страницы nginx-ом, не доходя до плексера.
Далеко не самое лучшее решение, но дело своё делает. Фикс проблемы в коде был бы очень кстати, хочется верить что это временый костыль

[degtyaryov]

Решил подменой статичной html страницы nginx-ом, не доходя до плексера.

контент который вы, например из php, отправляете клиенту так же приходит не полностью если отправлять несколько КБ, я проверял. между клиентом и realplexor лучше вставить nginx с буферизацией. это решает сразу 2 проблемы описанные выше.

[ZooKeeper]

Если плексер не целиком отправляет данные, как описано выше, то буферизация здесь не поможет.
О каких именно директивах nginx Вы говорите?

[dimikot]

Как я выше писал, исправить данный баг довольно сложно. В realplexor-е событийно-ориентированное программирование на основании libev применяется только при обработки операций чтения, но НЕ при обработке операций ЗАПИСИ. Т.е. если при чтении данные пришли не все, то они накапливаются в буфере до тех пор, пока не будет все прочитано. А вот запись делается по принципу "писать по максимуму сразу", в 1 операцию. Поэтому если вдруг во время записи половина буфера запишется, а половина выдаст EAGAIN (такое бывает, когда в системе кончается память буферов записи TCP, в openvz это параметр tcpsndbuf, кажется), то все, данные потеряются.

По-хорошему надо этот буфер хранить где-то и писать тоже через механизм libev: записал кусочек, подождал события "случилось окончание записи", записал оставшийся кусочек и т.д. (а если вдруг пришло событие "соединение разорвано", то буфер уничтожить). Но данного механизма сейчас нет.

Быстрое лечение проблемы - увеличение буферов записи TCP и/или установка перед realplexor-ом nginx с большим буфером.

[insbrook]

Столкнулся с похожей проблемой. Сервер не отправляет больше ~7КБ. Так как такой размер ответа был только с dklab_realplexor.html , сжал файл JS minifier'ом до 4999 байт и больше проблема не беспокоила.

[degtyaryov]

diff -Naur ../DmitryKoterov-dklab_realplexor-0fdae1e-orig/cpp/src/utils/Socket.h ./cpp/src/utils/Socket.h
--- ../DmitryKoterov-dklab_realplexor-0fdae1e-orig/cpp/src/utils/Socket.h   2013-03-31 22:04:42.000000000 +0600
+++ ./cpp/src/utils/Socket.h    2013-04-05 12:23:52.996919302 +0600
@@ -101,12 +101,18 @@
     int write(const char* buf, size_t len)
     {
         while (true) {
-            int n = ::write(fh, buf, len);
-            if (n < 0) return -1;
-            if (n == (int)len) return 1;
-            len -= n;
-            buf += n;
-        }
+           int n = ::write(fh, buf, len);
+           if (n == (int)len) return 1;
+           if (n<0)
+           {
+               if (errno != EAGAIN) return -1;
+           }
+           else
+           {
+               len -= n;
+               buf += n;
+           }
+       }
     }

     int write(const string& s)

Два года работает с патчем, контент отдаёт полностью.

[dimikot]

Вы этим устроили busy wait. Т.е. на время, пока система не будет готова принять новую порцию данных, процесс будет полностью заблокирован, крутясь в цикле и получая EAGAIN миллион раз, загружая ядро на 100% и не давая другим клиентам работать. И длиться это может несколько секунд.

Нужно делать полноценную буферизацию потоков отвачи через libev, я даже начал какое-то время назад, но пока подзавяз. Сейчас самый простой обходной способ - поставить перед realplexor-ом nginx с достаточными буферами (proxy_buffers), который будет принимать все, что ему скармливают, и уже дальше сам буферизировать.