Latency внутри приложения и снаружи

[Alexander Petrovsky]

Привет!

Коллеги, нужна ваша помощь в виде советов и накопленного опыта по профилированию приложения!

Итак, есть приложение, которое через http (fasthttp) принимает динамический json, перекладывает его в map[string]interface{} через ffjson, далее адресно вычитываются некоторые данные из мапы пишутся в структурка, по ним производятся вычисления, далее данные пишутся обратно в мапу, мапа пишется в кафку (асинхронно!) и после отдается в виде json'а обратно клиенту. Все это при рейте порядка 4к запросов на один сервер (32 ядра, суммарная нагрузка максимум 15%). Так же есть 2 больших кеша/справочника, по 100 млн и 20 млн записей соответственно, построенных на основе freecache, дабы уменьшить GC, (на мапах это работает грустно).

Собственно говоря сама проблема — замеры по латенси внутри приложения, совсе не соответствуют тем же замерам снаружи.

1. Как вообще я мерю латенси?

2. Как я понял, что латенси внутри приложения совсем не соответствует латенси снаружи?

3. Окей, и насколько велико несоответствие?

1. В функцию-хендлер, которая занимается обработкой http запроса, добавлены тайминги (начало выполнения и конец, соответственно) и по ним рисуются графики.

2. Поставил перед приложением nginx, на каждый запрос так же пишется тайминг всего запроса и по этим данным тоже рисуются графики.

3. Судя по графиком, латенси отличается на порядки. Тайминги по функции хендлеру показывают 500 микросекунд на 99 процентиле, тайминги nginx показывают от 10-15 миллисекунд так же на 99 процентиле.

Я конечно понимаю, что GC и все дела, который кстати судя по графикам отрабатывает за 2 миллисекунды в пике и выполняется не чаще чем раз в 30-40 секунд. Но вот почему такая сильная разница м/у тем, что я вижу внутри и снаружи?

Варианты вида: перепутал размерность, плохая сеть м/у nginx и приложением, плохо расставлены тайминги, не предлагать )

[Alex Lurye]

А где находятся nginx и приложение - на одной машине или на разных? Может всё-таки плохая сеть, или расстояние между машинами?

--
Вы получили это сообщение, поскольку подписаны на группу "Golang Russian".
Чтобы отменить подписку на эту группу и больше не получать от нее сообщения, отправьте письмо на электронный адрес golang-ru+...@googlegroups.com.
Чтобы настроить другие параметры, перейдите по ссылке https://groups.google.com/d/optout.

[Alexander Petrovsky]

Привет!

Нет, они стоят на одном и том же сервере, рядышком, вот лог:

185.*.*.146 - - [18/Mar/2017:09:35:23 +0000] "POST /api/v1/calculate HTTP/1.1" 200 945 "-" "-" "-" 911 0.009 0.000 0.009
185.*.*.164 - - [18/Mar/2017:09:35:23 +0000] "POST /api/v1/calculate HTTP/1.1" 200 1322 "-" "-" "-" 1289 0.008 0.001 0.008
185.*.*.195 - - [18/Mar/2017:09:35:23 +0000] "POST /api/v1/calculate HTTP/1.1" 200 1346 "-" "-" "-" 1313 0.010 0.001 0.010
185.*.*.129 - - [18/Mar/2017:09:35:23 +0000] "POST /api/v1/calculate HTTP/1.1" 200 1335 "-" "-" "-" 1302 0.007 0.000 0.006
...
185.*.*.100 - - [18/Mar/2017:09:35:24 +0000] "POST /api/v1/calculate HTTP/1.1" 200 1371 "-" "-" "-" 1342 0.009 0.000 0.009
185.*.*.104 - - [18/Mar/2017:09:35:24 +0000] "POST /api/v1/calculate HTTP/1.1" 200 957 "-" "-" "-" 926 0.008 0.000 0.008
185.*.*.185 - - [18/Mar/2017:09:35:24 +0000] "POST /api/v1/calculate HTTP/1.1" 200 1368 "-" "-" "-" 1320 0.009 0.000 0.009
185.*.*.178 - - [18/Mar/2017:09:35:24 +0000] "POST /api/v1/calculate HTTP/1.1" 200 1338 "-" "-" "-" 1304 0.007 0.000 0.007
185.*.*.227 - - [18/Mar/2017:09:35:24 +0000] "POST /api/v1/calculate HTTP/1.1" 200 962 "-" "-" "-" 928 0.006 0.000 0.006
185.*.*.130 - - [18/Mar/2017:09:35:24 +0000] "POST /api/v1/calculate HTTP/1.1" 200 1350 "-" "-" "-" 1313 0.007 0.000 0.007

Собственно три последние параметра это $request_time $upstream_connect_time и $upstream_response_time соответственно. В лог nginx сейчас пишутся только запросы, время выполнения которых превышает 5 миллисекунд. Кстати, как видно из лога, порой на установку коннекта уходит до 1мс. Из лога ранее:

# cat access.log-20170318 | grep "17/Mar/2017:03:42:17" | awk '{ print $15,$16 }' | sort | uniq -c
   2056 0.000 0.000
    200 0.001 0.000
   1313 0.001 0.001
      3 0.002 0.001
      9 0.002 0.002
      5 0.003 0.003
      3 0.004 0.004
      4 0.005 0.005
      5 0.006 0.006
      4 0.007 0.007
      2 0.008 0.007
      5 0.008 0.008
      1 0.009 0.009

где awk-поля $15, $16 — $request_time, $upstream_connect_time соответственно.

Далее, вот те самые графики, смотря на которые, я могу делать вывод о том, что латенси внутри приложения и снаружи ну вот соооовсем не бьется (прошу прощения за размер, пришлось делать скрины, т.к. пошарить через grafana'вской share не вышло):

Что в данном случае меня волнует:

- Почему я не вижу такого латенси внутри приложения? Ведь если делается какой-либо stop the world, почему он не аффектит мои внутренние тайминги?

- Почему вылеты по латенси, который случаются происходят каждую минуту, а например GC, судя по графикам происходит раз в 30 - 40 секунд. К слову, мое понимание работы GC в golang крайне поверхностное.

пятница, 17 марта 2017 г., 23:35:27 UTC+3 пользователь Alex Lurye написал:

[Alex Lurye]

Интересно. Под подозрением: nginx, сетевой стек, планировщик ядра, железо и приложение. Проверить, наверное, проще всего сеть. Посмотрите tcpdump - между чем и чем тормоза появляются?

[Aln Kapa]

Вариантов много.

Предлагаю ввести принудительную, заведомо известную задержку, и сравнить показатели. 

Выявив где врет, можно уже копать дальше.

17 марта 2017 г., 20:12 пользователь Alexander Petrovsky <askj...@gmail.com> написал:

Привет!

[Max Lapshin]

Главный вопрос: а вам вообще там nginx нужен?

[Юрий Соколов]

И даже если он там действительно нужен, почему не используется keep_alive до апстрима?

И всё-таки, скорее всего действительно не нужен.

А тайминги даже на одной машине могут возникнуть:

- из-за шедулинга процессов (ты не забыл разнести nginx и гошку на разные ядра?)

- из-за не мгновенного accept (если ты забыл сделать keep_alive до апстрима)

- из-за шедулинга event_loop в nginx

- из-за шедулинга event_loop в go

- из-за шедулинга внутриядерных нотификаций для epoll

В общем, чем больше общающихся процессов, тем больше тайминги, даже на одной машине.

Хочешь уменьшать тайминги для пользователя? Убирай лишние процессы (nginx).

вторник, 21 марта 2017 г., 11:40:42 UTC+3 пользователь Max Lapshin написал:

[Alexander Petrovsky]

Привет!

В это сообщении, отвечу сразу и Максу, на вопрос зачем Nginx и попытаюсь ответить Юрию.

Главный вопрос: а вам вообще там nginx нужен?

Изначально, nginx'а там быть не должно. Однако, были жалобы от потребителей сервиса, которые его используют, но сильно высокий латенси, примерно тот, что показывает Nginx, в то время, как я видел, совсем другое латенси. Чтоб локализовать проблему, и понять на какой стороне проблемы, я поставил nginx и определял вреия запроса.

вторник, 21 марта 2017 г., 20:47:00 UTC+3 пользователь Юрий Соколов написал:

И даже если он там действительно нужен, почему не используется keep_alive до апстрима?

И всё-таки, скорее всего действительно не нужен.

А тайминги даже на одной машине могут возникнуть:

- из-за шедулинга процессов (ты не забыл разнести nginx и гошку на разные ядра?)

Нет, этого я не сделал. Изначально, латенси извне было таким же и без nginx. См. мой ответ выше, зачем я поставил Nginx.

 

- из-за не мгновенного accept (если ты забыл сделать keep_alive до апстрима)

keepalive до апстрима не включем, ну и сам апстрим бежит не через ngx_http_upstream_module, не думаю, что это влияет.

# cat access.log-20170318 | grep "17/Mar/2017:03:42:17" | awk '{ print $15,$16 }' | sort | uniq -c
   2056 0.000 0.000
    200 0.001 0.000
   1313 0.001 0.001
      3 0.002 0.001
      9 0.002 0.002
      5 0.003 0.003
      3 0.004 0.004
      4 0.005 0.005
      5 0.006 0.006
      4 0.007 0.007
      2 0.008 0.007
      5 0.008 0.008
      1 0.009 0.009

Не оч, верю, что это из-за accept!

 

- из-за шедулинга event_loop в nginx

Думаю, тут тоже мимо.

 

- из-за шедулинга event_loop в go

Вот тут возможно, да. Но вопрос, же более в другом. Почему я это не вижу этих на графиках внутри приложения. Я слабо верю, что тот же STW, происходит всегда, когда нет запросов и http хендрел, внутри моего приложения отработал.

 

- из-за шедулинга внутриядерных нотификаций для epoll

Тоже слишком сомнительно. Домыслы можно строить сколько угодно. Как проверить?

 

В общем, чем больше общающихся процессов, тем больше тайминги, даже на одной машине.

Хочешь уменьшать тайминги для пользователя? Убирай лишние процессы (nginx).

Ну ты уже немного капитанишь.

[Юрий Соколов]

> Не оч, верю, что это из-за accept!

А ты проверь. Сделай кипалив до апстрима.

Установка соединения - длительная операция. После чего epoll уведомляет о новом соединении. Потом event-loop в цикле зовет accept, порождая по горутине на каждый коннект (а может и не одной).

А замер внутри хэндлера не видит ни accept, ни read запроса, ни write ответа. Он живёт в своем уютном маленьком мирке.

Еще, конечно, 32 ядра "пугают". Это один сокет? Т.е. есть NUMA, или нет? Правда, тогда и GC должен был бы под тормаживать.
Но вполне возможно, что горутины, порожденные на accept коннекта, складываются в очередь того же екзекютера. И чтобы другое ядро (экзекютор) могло украсть эту горутину , тоже уходит время. Опять таки, в этом случае keepalive может помочь (заодно будет повод говорить, что nginx нужен).

Кстати, советую все-таки прибивать гошку и nginx на разные ядра (используя taskset).

[Alex Lurye]

Перед тем, как спекулировать на тему accept, read, write, и т.д., лог tcpdump между nginx и сервисом - в студию.

--
Вы получили это сообщение, поскольку подписаны на группу Golang Russian.

Чтобы отменить подписку на эту группу и больше не получать от нее сообщения, отправьте письмо на электронный адрес golang-ru+...@googlegroups.com.

Настройки подписки и доставки писем: https://groups.google.com/d/optout.