Как отладить akka http крайне медленно обрабатывать время - PullRequest
Новая
       45

Как отладить akka http крайне медленно обрабатывать время

0 голосов
/ 14 января 2019

Я регистрирую «медленные» запросы примерно так, я вижу, что время обработки многих запросов занимает 200-300 мс, в то время как фактическая обработка в самом маршруте составляет всего 5 мс. Сервер обрабатывает только 5-10 операций на 8-ядерном компьютере с кучей 1 Гб. 

java -Xms1g -Xmx1g .... -XX:MaxGCPauseMillis=5 -XX:+UseG1GC ... -cp /path/to/jar blah.blah.Main

Я не понимаю, где теряется 199MS: 

def slowLogMagnet()(t: LoggingAdapter): HttpRequest => RouteResult => Unit = {
    request => {
      val startTime = System.currentTimeMillis()
      response => {
        val total = System.currentTimeMillis() - startTime
            if (total > 200) {
              logger.warn(s"[SLOWLOG] took '$total' ms '$request' response: '$response'")
            }
        }
      }
    }
  }

case class Result(res : Map[Int,Seq[String]], debug: Map[String,String])
implicit val format1 = jsonFormat3(MyRequest)
implicit val format2 = jsonFormat2(Result)
implicit val ec = .... blocking io ....
val route: Route = logRequestResult(LoggingMagnet(slowLogMagnet())) {
   pathPrefix("request1") {
      entity(as[MyRequest]) {
         Future {
            ... 
            val started = System.currentTimeMillis()
            // do somehting taking ~5 ms
            logger.debug("took ${System.currentTimeMillis() - started} ms")
            Result(Map(1 -> Seq("a","b","c")) , Map("thread" -> Thread.currentThread().getName)

         }
      }
   }
}

В ответе я вижу, что поток не является входящим потоком, он действительно обрабатывается в отдельном потоке

Я также проверил с журналом сборщика мусора, я не вижу никакой блокировки: 

[Times: user=0.02 sys=0.00, real=0.00 secs]
2019-01-14T16:24:26.552+0000: 5108.774: [GC pause (G1 Evacuation Pause) (young), 0.0078790 secs]
   [Parallel Time: 4.6 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 5108774.8, Avg: 5108777.0, Max: 5108779.4, Diff: 4.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 0.9, Diff: 0.8, Sum: 3.2]
      [Update RS (ms): Min: 0.0, Avg: 0.4, Max: 0.9, Diff: 0.9, Sum: 3.3]
         [Processed Buffers: Min: 0, Avg: 25.6, Max: 61, Diff: 61, Sum: 205]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 2.4]
      [Termination (ms): Min: 0.0, Avg: 1.2, Max: 2.3, Diff: 2.3, Sum: 9.8]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.0, Avg: 2.4, Max: 4.6, Diff: 4.6, Sum: 19.0]
      [GC Worker End (ms): Min: 5108779.4, Avg: 5108779.4, Max: 5108779.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 3.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 2.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 50.0M(50.0M)->0.0B(50.0M) Survivors: 1024.0K->1024.0K Heap: 127.9M(1024.0M)->77.9M(1024.0M)]
 [Times: user=0.03 sys=0.00, real=0.01 secs]
...