Play Framework 2.5 Запрашивает время ожидания случайным образом

Question

симптом

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

Обновить

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

Настройка инфраструктуры

Мы запускаем Play 2.5 в AWS на экземпляре EC2 за балансировщиком нагрузки с базой данных PostgreSQL на RDS. Мы используем slick-pg в качестве соединителя нашей базы данных.

Что мы знаем

Вот несколько вещей, которые мы выяснили до сих пор.

О запросах HTTP

Наши журналы и отладка показывают нам, что запросы проходят фильтры. Кроме того, мы видим, что для аутентификации (для этого мы используем Silhoutte) приложение может выполнять запросы к базе данных, чтобы получить идентификатор для этого запроса. Однако действие контроллеров никогда не будет вызвано.

Бэкэнд отвечает за HEAD Запросы. Дальнейшее ведение журнала показало нам, что кажется, что контроллеры, использующие внедренные сервисы (для этого мы используем подсказку googles), являются теми, чьи методы больше не вызывают. Контроллеры без внедренных сервисов работают нормально.

Об экземпляре EC2

К сожалению, мы не можем получить много информации от этого. Мы используем boxfuse, который предоставляет нам неизменную инфраструктуру in-ssh. Мы собираемся изменить это на развертывание на основе докера и, возможно, сможем предоставить больше информации в ближайшее время. Тем не менее, у нас есть настройка New Relic для мониторинга наших серверов. Мы не можем найти ничего подозрительного там. Память и использование процессора выглядят нормально.

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

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

Поэтому нам трудно сказать, в чем проблема. Кажется, БД не работает ни с одним экземпляром EC2 (до тех пор, пока он не будет работать с новым), но с нашими локальными машинами.

О базе данных

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

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

Количество подключений к БД составляет около 20 в соответствии с консолью AWS, что является нормальным.

TL; DR

• Наш бэкэнд начинает вести себя как черная дыра для некоторых из его конечных точек в конечном итоге
• Запросы не доходят до действий контроллера
• Новый экземпляр в EC2 может решить эту проблему, но не обязательно
• локально с той же самой БД все работает нормально
• сброс рабочей базы данных в нее решает проблему
• Использование ЦП и памяти экземпляров EC2, а также количество подключений к БД выглядят совершенно нормально
• Мы можем воспроизвести поведение с помощью дампа базы данных, который мы сделали, когда сервер больше не отвечал (см. Обновление 2).
• с новыми настройками Slick Threadpool мы получим исключения ThreadPoolExecutor от Slick после перезагрузки БД с последующей перезагрузкой нашего экземпляра ec2. (см. обновление 3)

Обновление 1

Отвечая на Маркоспейра:

Возьмите для примера ApplicationController.scala:

package controllers

import scala.concurrent.ExecutionContext.Implicits.global
import scala.concurrent.Future

import akka.actor.ActorRef
import com.google.inject.Inject
import com.google.inject.name.Named
import com.mohiva.play.silhouette.api.Silhouette
import play.api.i18n.{ I18nSupport, MessagesApi }
import play.api.mvc.Action
import play.api.mvc.Controller

import jobs.jobproviders.BatchJobChecker.UpdateBasedOnResourceAvailability
import utils.auth.JobProviderEnv

/**
 * The basic application controller.
 *
 * @param messagesApi The Play messages API.
 * @param webJarAssets The webjar assets implementation.
 */
class ApplicationController @Inject() (
  val messagesApi: MessagesApi,
  silhouette: Silhouette[JobProviderEnv],
  implicit val webJarAssets: WebJarAssets,
  @Named("batch-job-checker") batchJobChecker: ActorRef
)
    extends Controller with I18nSupport {


  def index = Action.async { implicit request =>
    Future.successful(Ok)
  }

  def admin = Action.async { implicit request =>
    Future.successful(Ok(views.html.admin.index.render))
  }


  def taskChecker = silhouette.SecuredAction.async {
    batchJobChecker ! UpdateBasedOnResourceAvailability
    Future.successful(Ok)
  }

}

index а также admin просто работают нормально. taskchecker покажет странное поведение, хотя.

Обновление 2

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

Теперь мы начали регистрировать количество потоков в одном из наших фильтров, используя Thread.getAllStackTraces.keySet.size и обнаружил, что работает от 50 до 60 потоков.

Обновление 3

Как предложил @AxelFontaine, мы включили аварийное переключение MultiAZ Deployment для базы данных. Мы перезагрузили базу данных при сбое. До, во время и после перезагрузки сервер не отвечал.

После перезагрузки мы заметили, что количество подключений к базе данных осталось равным 0. Кроме того, мы больше не получали никаких журналов для аутентификации (до того, как мы это сделали, шаг аутентификации мог даже делать запросы базы данных и получать ответы).

После перезагрузки экземпляра EC2 мы получаем

play.api.UnexpectedException: Unexpected exception[RejectedExecutionException: Task slick.backend.DatabaseComponent$DatabaseDef$$anon$2@76d6ac53 rejected from java.util.concurrent.ThreadPoolExecutor@6ea1d0ce[Running, pool size = 4, active threads = 4, queued tasks = 5, completed tasks = 157]]

(мы не получили их раньше)

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

numThreads = 4
queueSize = 5
maxConnections = 10
connectionTimeout = 5000
validationTimeout = 5000

как предложено здесь

Обновление 4

После того как мы получили исключения, как описано в обновлении 3, серверная часть теперь снова работает нормально. Мы ничего не сделали для этого. Это был первый раз, когда бэкэнд вышел из этого состояния без нашего участия.

Answer 1

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

Таким образом, проблема заключалась в том, что мы выполняли транзакции БД с .transactionally в пределах .map из DBIOAction на слишком много потоков одновременно.

Answer 2

Это звучит как проблема управления потоками на первый взгляд. Slick предоставит свой собственный контекст выполнения для операций с базой данных, если вы используете Slick 3.1, но вы действительно хотите управлять размером очереди, чтобы он соответствовал примерно тому же размеру, что и база данных:

myapp = {
  database = {
    driver = org.h2.Driver
    url = "jdbc:h2:./test"
    user = "sa"
    password = ""

    // The number of threads determines how many things you can *run* in parallel
    // the number of connections determines you many things you can *keep in memory* at the same time
    // on the database server.
    // numThreads = (core_count (hyperthreading included))
    numThreads = 4

    // queueSize = ((core_count * 2) + effective_spindle_count)
    // on a MBP 13, this is 2 cores * 2 (hyperthreading not included) + 1 hard disk
    queueSize = 5

    // https://groups.google.com/forum/#!topic/scalaquery/Ob0R28o45eM
    // make larger than numThreads + queueSize
    maxConnections = 10

    connectionTimeout = 5000
    validationTimeout = 5000
  }
}

Также вы можете использовать пользовательский ActionBuilder, добавить компонент Futures и добавить

import play.api.libs.concurrent.Futures._

как только вы это сделаете, вы можете добавить future.withTimeout(500 миллисекунд) и установить тайм-аут на будущее, чтобы ответное сообщение вернулось. В примере Play приведен пример пользовательского ActionBuilder:

https://github.com/playframework/play-scala-rest-api-example/blob/2.5.x/app/v1/post/PostAction.scala

class PostAction @Inject()(messagesApi: MessagesApi)(
    implicit ec: ExecutionContext)
    extends ActionBuilder[PostRequest]
    with HttpVerbs {

  type PostRequestBlock[A] = PostRequest[A] => Future[Result]

  private val logger = org.slf4j.LoggerFactory.getLogger(this.getClass)

  override def invokeBlock[A](request: Request[A],
                              block: PostRequestBlock[A]): Future[Result] = {
    if (logger.isTraceEnabled()) {
      logger.trace(s"invokeBlock: request = $request")
    }

    val messages = messagesApi.preferred(request)
    val future = block(new PostRequest(request, messages))

    future.map { result =>
      request.method match {
        case GET | HEAD =>
          result.withHeaders("Cache-Control" -> s"max-age: 100")
        case other =>
          result
      }
    }
  }
}

так что вы бы добавили тайм-аут, метрики (или прерыватель цепи, если база данных не работает) здесь.