Есть REST бэкэнд для мобильной игры, построенный на node.js и mongodb (express, mongoose). Приложение развернуто на Heroku (2 dyno (1x)), база данных - на Mongolab (M1 Cluster (1.7 GB). Используется для обработки рейтингов, подарков, сохранений, пользовательских профилей и т.п.
Клиент общается с сервером через POST запросы (внутри клиента используется libcurl), передавая и получая данные в виде JSON. Характер нагрузки на сервер - 50/50 read/write, никакого кеширования. На один запрос к бэкэнду приходится в среднем 2 запроса к бд.
После запуска проекта нагрузка составила 4500rpm в пике, время отклика 30-40мс (данные получены в NewRelic). По мере роста бд, время отклика стало расти, а rpm - падать. На данный момент имеем ~1000rpm в пике и 100мс. Время в базе увеличилось с 3-5мс до 15-20мс.
И все бы хорошо, но с момента старта и до текущего времени в метрике все больше и больше ошибок. Сначала их вообще не было, потом стали проскакивать 1-2. А теперь:
i.imgur.com/8n6YbpO.png
"H18 - Request Interrupted" -
https://devcenter.heroku.com/articles/error-codes#...
"H15 - Idle connection"
https://devcenter.heroku.com/articles/error-codes#...
Это очень странно, т.к. несмотря на снижение нагрузки, количество ошибок растет.
В логах (Logentries) есть только H15, выглядят так:
heroku router - - at=error code=H15 desc="Idle connection" method=POST path="/v1/userString/set" host=xxxxxxxxxx.com request_id=c339d810-c020-4df1-81d0-e9016a25c8eb fwd="213.44.130.41/i16-les01-ntr-213-44-130-41.sfr.lns.abo.bbox.fr" dyno=web.2 connect=0ms service=55001ms status=503 bytes=0
H18 почему-то в логах нет вообще.
service=55001ms - странное время. Внутри клиента выставлен таймаут 30с на все запросы. Выставление таймаута на сервере (ставил для тестов 30 секунд) ни на что не влияет. Пробовал писать в лог по таймеру 30с с начала запроса, но ни одного такого случая в лог не попало - все запросы завершались быстрее.
Я проверил Slow Queries в Mongolab и не увидел там ничего страшного - за два дня всего ~160 запросов со средним откликом 264мс, и это при средняем за день cpm в 2k.
99.9% H15 в логах приходятся на method=POST path="/v1/userString/set" (rpm этого запроса ~120 из 1000).
Внутри ничего интересного. Сначала middleware: express.compress, express.json, express.urlencoded, затем мой код:
pastebin.com/5xqs2y3q Точно такая же обработка запросов используется в десятке других мест проекта и не вызывает никаких проблем. Единственное отличие - здесь довольно большой объем данных на входе и выходе: 3-5kb против 0.1-0.5kb в других запросах.
Принцип работы:
Клиент присылает JSON со id игрока и данными (сохраненка):
{ "UserId" : "f1234567890", "Key" : "progress", "Value" : " ---- [ SOME USER DATA HERE - 3-5kb of text ] ---- ", "Version" : 123, "AccessToken" : "1234567890asdfghjkl", "ClientVersion" : 14}
Сервер вытягивает соответствующую запись из бд, проверяет её (решение принимается по полю "Version", банальным сравнением инта). Если все в порядке, то "Value" записывается в базу и клиенту отправляется ответ:
{"result":{"code":0,"message":{"status":"updated"}}}
А если нет, то "Value" из базы отправляется обратно клиенту для решения конфликта.
{"result":{"code":0,"message":{"status":"need merge","Value":" ---- [ SOME DATA HERE - 3-5kb of text ] ---- }}}
Мои вопросы:
1. Почему время ответа такого простого запроса 200-400мс (при ответе бд за 3-5мс)?
2. Почему возникают ошибки H15? В моем коде нет варианта, когда на запрос не отсылается ответ.
3. Как узнать, кто виноват в H18 - клиент или сервер, если в логах этой ошибки почему-то нет. Кстати, почему?
4. Почему при снижении rpm количество ошибок продолжает расти?
5. В чем, собственно, проблема и как можно её исправить.
Простой
