GD Star Rating
loading...

Котаны, помогите!
VDS под FreeBSD9, стоит nginx и uwsgi, крутится проект на питоне. Недавно начал откладывать в логи кирпичи вида:
uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 260]
IOError: write error
Происходит с какой-то периодичностью, в это время приложение начинает тупить и отдаваться по минуте. Такое ощущение, что uwsgi или nginx во что-то упирается. Особого пика запросов я в это время не наблюдаю.

Собственно вопрос – куда копать-то? Что может тупить? Какие лимиты смотреть? Я надоеллся, мужики. 🙁

Ебучее место в core/writer.c line 260:

Tagged with →  

31 Responses to VDS под FreeBSD9, стоит nginx и uwsgi IOError: write error

  1. HseZlo:

    Да, на картинке кусок кода uWSGI, конечно.
    PS: продублирую в nix блогу.

  2. Aktno:

    ну, как предположение, к nginxу прицепился клиент, nginx послал запрос на бэкэнд, потом клиент убился и nginx закрыл соединение с бэкэндом как-то не так. в error логах nginxа что? и можно попробовать backlog увеличить у uwsgi

  3. Aktno:

    или же еще одно предположение, бэкэнд сильно долго отвечает, nginx рвет соединение с бэкэндом, а тому вдруг захотелось что-то записать. это тоже в логах nginxа будет видно.

  4. HseZlo:

    ну, я понимаю, что broken pipe будет в случае если клиент отвалился раньше чем получен ответ. Но не понимаю почему наплывами и так массово.
    В логах nginx’а есть вот такие строки:
    [info] 55343#0: *846 kevent() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client:
    [info] 55343#0: *655 kevent() reported that client 217.118.78.44 closed keepalive connection
    [info] 55343#0: *569 kevent() reported that client 178.64.83.211 closed keepalive connection (54: Connection reset by peer)

  5. HseZlo:

    А как это будет видно? Бэкенд может сильно долго отвечать, но только если во что-то упрется. Вот я пытаюсь найти во что оно упирается. Оно или nginx.

  6. 01pre:

    У нас как-то что-то похожее было с этой поебенью, накрутили каких-то буфферов и стало збс.

  7. HseZlo:

    Может вспомнишь куда и чего накрутили? У меня уже нервный срыв скоро будет от этой хуйни.

  8. 01pre:

    я не уверен, что у нас с тобой похожая проблема, но я погоди пару минут, щас поищу.

  9. HseZlo:

    Я грешил на mysql, заоптимизировал все что можно – ноль реакции. Грешил на сокеты – перевел общение с uwsgi-mysql и nginx-uwsgi с сокетов на TCP – ноль реакции. Точнее немного лучше конечно стало, но всёравно периодически начинается эта хуйня.
    Меня пугает, что в моменты хуйни никакой нагрузки в топах нет. Ну, есть немного, но ничего там в 100% не улетает. Или я не там смотрю? Научите, а?

  10. 01pre:

    buffer-size = 8192 мы ставили, но у нас да, я вспомнил, была другая проблема
    Вообще, начитавшись про uwsgi подобных постов, я пришёл к выводу, что это глючная и сырая поебень, написанная через жопу, поэтому, можно было бы начать с накручивания всех буфферов конфига вверх, если ничего не гуглится.
    Это если у тебя не пиздец хайлоад, конечно.

  11. Aktno:

    видно будет что-то типа

    [error] 20371#0: *523795583 upstream timed out (110: Connection timed out) while reading response header from upstream, client: XXX, server: XXX, request: “POST …”

    у nginx можно увиличить этот таймаут, для uwsgi это вроде uwsgi_read_timeout
    если nginx как-то мониторится (в смыслые через stub_status) то на графике будет видно рост “waiting” (эт я предпологаю, сам такие затыки вижу в апачевском графике).

    ну и плюс тебе когда IOError приходит, то там стек то есть. посмотри какой запрос был (у нас пишутся в sentry все эксепшены), воспроизведи, может там затык.

    у меня нигде в продакшене нету uwsgi, есть mod_wsgi. там я IOError получаю именно тогда, когда nginx уже пошел к следующему бэкэнду запрос обрабатывать, а это соединение закрыл по таймауту.

  12. Aktno:

    тфу не waiting, а writing

  13. HseZlo:

    Спасибо за наводку, буду копать.

  14. LgdAll:

    Напиши в мейлинг лист, Роберто всегда быстро и подробно отвечает

  15. KaeLinux:

    SIGPIPE обычно происходит, если ты пытаешься писать в пайп(сокет), который никто не открыл на чтение (или уже закрыл/отвалился).

  16. HseZlo:

    Ошибок upstream timed out в логах нет (или почти нет).
    Во время этих проблем растёт Writing, статус выглядит примерно так:
    Active connections: 109
    server accepts handled requests
    21669 21669 38689
    Reading: 0 Writing: 51 Waiting: 58

    В uwsgi.log для меня это выглядит вот так:
    uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 260]
    IOError: write error

    Никак не могу понять где оно обламывается. В uwsgi есть py-tracebacker, который показывает трейсбек питона, но там ничего относящегося к проблеме нет.

    Не знаешь, можно ли какой-нибудь более полный трейс в логи получать от какого-либо из участников проблемы?

  17. KaeLinux:

    У тебя на момент отдачи, уже из wsgi_req->socket никто не читает. Подозреваю что этим сокетом является балансер для апстрима (nginx, как я понял). Поснифай tcpdump-ом что реально происходит там.

  18. KaeLinux:

    Можешь еще поймать SIGPIPE и отложить кору – и глянуть что к чему там.

  19. HseZlo:

    Я не настоящий сварщик. Настроить сервер худо бедно я могу, но как поймать корку сигпайпа при куче запросов в секунду я не знаю.
    Дело в том, что эта херня не воспроизводится вот просто так, она начинается в какой-то момент на некоторых запросах.
    Может ткнешь носом меня куда копать? С tcpdumpом тоже фигня, я там потону в куче инфы, может ткнешь где можно почитать?

  20. HseZlo:

    Друзья, пусть это будет пост помощи по uWSGI? 🙂
    Кто знает, в uwsgi есть такие штуки как emperor, zerg mode и broodlord mode.
    Сейчас всё работает в режиме emperor, который держит 5 вассалов. Один нагруженный, остальные так себе.
    Помогите пожалуйста прикрутить к этому сетапу брудлорда?
    В интернетах описана настройка брадлорда на отдельное приложение. А как прикрутить брудлорда к эмперору?

  21. Aktno:

    про полный трейс не знаю, ловить наверное где-то внутри wsgi application надо, да и тут даже не трейс скорее ловить, а сам запрос. можно конечно тупо заснифить весь трафик, а потом уже смотреть запросы.

    Я бы постарался примерно понять когда этот интервал наступает, посмотрел бы логи запросов nginxа, прочитал бы error лог за это время. Потом бы посмотрел бы на предмет тупления все внешние сервисы, которые могут могут блокировать выполнение запроса, типа SQLа и прочей радости. Лучше даже несколько инцидентов сравнить, может там запросы совсем одинаковые.

    Ну и еще странно, что timed out нету. Там должно быть тогда что-то еще. Если timed out нету, то тогда просто мое предположение оно совсем не верно.

    Еще есть вариант не разбираться что же там тупит, а просто тупо увеличить кол-во воркеров в uwsgi, если проблема именно в затупе где-то, то должно спасти. Если же нет.. то всегда можно собрать nginx с дебагом и смотреть что там как, но это кунг-фу уже, там понять что-то только чудом можно.

  22. Aktno:

    ну и еще, как понять timeout этот или нет:
    на такие запросы nginx должен отдавать код >= 500, nginx можно научить писать в лог время выполнения запроса, как-то так https://gist.github.com//e15923c1
    потом в настройке сервера меняешь в access_log формат на main_time
    и получаешь в логе строку вида

    XXX – – [12/Jun/2013:13:05:42 +0400] “POST XXX HTTP/1.1” 200 326 “XX” “XX” “10.0.0.11:8082” “0.087” 0.087

    где последние три колонки это адрес апстрима (если у тебя один апстрим, то можно не писать эту колонку), время выполнения запроса на апстриме и полное время отдачи клиенту.

    теперь задача профигачить весь новый лог, если там есть коды >=500, то выводить эти строчки. смотреть на живом логе можно как-то так:

    tail -f /var/log/nginx/log |awk {if ($9 >= 500) {print $0}}’

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

  23. HseZlo:

    Ох, а вот за идею лога с апстримом и временем спасибо огромное. Мне кажется это поможет.

  24. HseZlo:

    Странные вещи выясняются. Есть куча запросов, в которых в логах nginx $upstream_response_time и $request_time просто астрономические 10-20 сек, но при этом замер внутри uwsgi (от before_request (до подключения к базе) и перед отдачей шаблона) – всегда около 0.3 сек.
    В чем он может тупить?

  25. Aktno:

    это flask что-ли? там же есть какой-то after_request, логичнее будет на него тоже что-то повесить, вдруг у тебя в шаблон передается что-то ленивое, а там исполняется и делает сто тыщ запросов.

    но если там окажется, что всё чисто, то.. даж не знаю. я б попробовал на каком-нить flup’е задеплоится и поглядеть станет лучше или нет. ну или на апаче с mod_wsgi.

  26. HseZlo:

    Да, фласк. В общем между before_request и after_request всегда от 0.05 до 0.6, редко 1 сек.
    В какой-то момент случается что-то и nginx постепенно поднимает время отдачи с 1-2 сек, до 50-60 сек, о чем написано в его логах.
    Куда в этот момент смотреть я не понимаю. Блять. 🙁

  27. Aktno:

    как предположение: может там какой-то супер большой ответ и nginx его пишет в файл, а диск очень медлено работает? 🙂
    в еррор логе тогда будет что-то типа:

    [warn] 28009#0: *621854359 an upstream response is buffered to a temporary file /var/lib/nginx/proxy/2/29/0000830292 while reading upstream, client: XXX, server: XXX, request: “POST XXXHTTP/1.0”, upstream: “XX”, host: “XXX”, referrer: “XXX”

    но вообще надо включать дебаг (http://nginx.org/ru/docs/debugging_log.hhttp://wiki.nginx.org/Debugging) в nginxе и смотреть что происходит

  28. HseZlo:

    Да вот дело в том, что у меня ответы все очень мелкие – или json отдается, или небольшой html, ну и статика.
    Пересобрал сейсас nginx с дебагом, вечером буду смотреть (оно в основном вечером начинается, в пике запросов).
    В логах никаких странных ошибок нету. Есть три вида ошибок:
    [info] 85206#0: *83794 kevent() reported that client 5.45.192.86 closed keepalive connection (54: Connection reset by peer)
    [info] 85206#0: *83529 kevent() reported that client 194.15.147.78 closed keepalive connection
    [info] 85206#0: *83592 kevent() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 46.172.234.19, server: light.ideing.ru, request: “GET /game/5991861/6/1883125 HTTP/1.1”, upstream: “uwsgi://127.0.0.1:3032”, host: “light.ideing.ru”, referrer: “http://light.ideing.ru/newgame/easy/2839… 90″

    Он в пике запросов перестает успевать что-то делать и время ответа начинает расти с 1 секунды до 1 минуты, потом его попускает.
    Я в надежде на io уже отключил всю статистику, графит, мунин, но он всё равно продолжает мне гадить.
    Я не могу понять, чего ему нехватает, т.к. в топе в эти моменты ничего примечательного не висит.
    Сегодня вечером буду опять смотреть в логи, тихо скрипеть зубами и читать бугурт от юзеров.

  29. Aktno:

    io было бы видно по vmstat’у, т.е. wa вырос бы. еще совет погоняй vmstat вечером на пике этом. вдруг там что-то резко вырастет, типа context switches, а от них system нагрузка. удачи с дебаг логом nginx’а, там кунг-фу еще то.

  30. HseZlo:

    Короче, после курения логов nginx’а выяснилось, что тупит всётаки апстрим, поэтому помогло увеличение количества воркеров uWSGI.
    Оказалось, что я проебланил всё самое важное с самого начала – я твёрдо был уверен, что uWSGI в режиме emperor’а это ой как важно и все настройки пытался менять именно у него. Когда понял, что uWSGI в этом режиме ничего не сервит, а всего лишь менеджерит дочерние процессы, всё встало на свои места.
    Спасибо за помощь, узнал много нового 🙂

  31. Aktno:

    так почему тупили uwsgi воркеры то выяснил?

Добавить комментарий