Почему Гатлинг делает паузу перед отправкой запросов

Question

Гатлинг 3.0.3 делает паузу на 25 секунд перед инъекцией.

Я использую плагин Radius bpabdelkader / gatling-radius Я уже разработал тест для загрузки нашего сервера Radius.

Мой пример сценария выглядит следующим образом:

import io.gatling.core.Predef._

import com.ngenia.radius.Predef._
import com.ngenia.radius.protocol._

class RadiusSimulation extends Simulation {

  implicit val radiusProtocol: RadiusProtocol = radius
    .host("10.20.30.40")
    .sharedKey("mySharedKey")
    .replyTimeout(100) // 100 ms

  val scn = scenario("Access Request")
    .feed(csv("data/dataFeeder.csv").circular)
    .exec(
      radius("Access Request")
        .username("${username}")
        .password("${password}")
        .properties(
          Map(
            "NAS-Identifier" -> "${NAS-Identifier}",
            "NAS-IP-Address" -> "${NAS-IP-Address}",
            "Calling-Station-Id" -> "${Calling-Station-Id}",
            "Called-Station-Id" -> "${Called-Station-Id}"
          ))
        .authenticate()
    )

  setUp(scn.inject(atOnceUsers(1000))).protocols(radiusProtocol)
}

После запуска я вижу 1000 пользователей, ожидающих в течение 25 секунд до начала инъекции

Select run description (optional)

17:15:26.944 [INFO ] i.g.c.s.w.ConsoleDataWriter - Initializing
17:15:26.944 [INFO ] i.g.c.s.w.LogFileDataWriter - Initializing
17:15:26.949 [INFO ] i.g.c.s.w.ConsoleDataWriter - Initialized
17:15:26.955 [INFO ] i.g.c.s.w.LogFileDataWriter - Initialized

================================================================================
2019-07-08 17:15:31                                           5s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=0      KO=0     )


---- Access Request ------------------------------------------------------------
[                                                                          ]  0%
          waiting: 1000   / active: 0      / done: 0     
================================================================================


================================================================================
2019-07-08 17:15:36                                          10s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=0      KO=0     )


---- Access Request ------------------------------------------------------------
[                                                                          ]  0%
          waiting: 1000   / active: 0      / done: 0     
================================================================================


================================================================================
2019-07-08 17:15:41                                          15s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=0      KO=0     )


---- Access Request ------------------------------------------------------------
[                                                                          ]  0%
          waiting: 1000   / active: 0      / done: 0     
================================================================================


================================================================================
2019-07-08 17:15:46                                          20s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=0      KO=0     )


---- Access Request ------------------------------------------------------------
[                                                                          ]  0%
          waiting: 1000   / active: 0      / done: 0     
================================================================================

Simulation RadiusSimulation started...
log4j:WARN No appenders could be found for logger (org.tinyradius.util.RadiusClient).
log4j:WARN Please initialize the log4j system properly.
17:15:51.676 [INFO ] i.g.c.c.i.Injector - StoppedInjecting

================================================================================
2019-07-08 17:15:51                                          25s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=9      KO=0     )
> Access Request                                           (OK=9      KO=0     )

---- Access Request ------------------------------------------------------------
[--------------------------------------------------------------------------]  0%
          waiting: 0      / active: 991    / done: 9     
================================================================================


================================================================================
2019-07-08 17:15:56                                          30s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=317    KO=0     )
> Access Request                                           (OK=317    KO=0     )

---- Access Request ------------------------------------------------------------
[#######################---------------------------------------------------] 31%
          waiting: 0      / active: 683    / done: 317   
================================================================================


================================================================================
2019-07-08 17:16:01                                          35s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=650    KO=0     )
> Access Request                                           (OK=650    KO=0     )

---- Access Request ------------------------------------------------------------
[################################################--------------------------] 65%
          waiting: 0      / active: 350    / done: 650   
================================================================================


================================================================================
2019-07-08 17:16:06                                          40s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=966    KO=0     )
> Access Request                                           (OK=966    KO=0     )

---- Access Request ------------------------------------------------------------
[#######################################################################---] 96%
          waiting: 0      / active: 34     / done: 966   
================================================================================

17:16:07.446 [INFO ] i.g.c.c.i.Injector - All users of scenario Access Request are stopped
17:16:07.447 [INFO ] i.g.c.c.i.Injector - Stopping
17:16:07.449 [INFO ] i.g.c.c.Controller - Injector has stopped, initiating graceful stop

================================================================================
2019-07-08 17:16:07                                          40s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=1000   KO=0     )
> Access Request                                           (OK=1000   KO=0     )

---- Access Request ------------------------------------------------------------
[##########################################################################]100%
          waiting: 0      / active: 0      / done: 1000  
================================================================================

17:16:07.485 [INFO ] i.g.c.c.Controller - StatsEngineStopped
Simulation RadiusSimulation completed in 15 seconds
Parsing log file(s)...
17:16:07.529 [INFO ] i.g.c.s.LogFileReader - Collected ArrayBuffer(D:\Bitbucket\gatling\target\gatling\radiussimulation-20190708151526921\simulation.log) from radiussimulation-20190708151526921
17:16:07.535 [INFO ] i.g.c.s.LogFileReader - First pass
17:16:07.555 [INFO ] i.g.c.s.LogFileReader - First pass done: read 3001 lines
17:16:07.563 [INFO ] i.g.c.s.LogFileReader - Second pass
17:16:07.656 [INFO ] i.g.c.s.LogFileReader - Second pass: read 3001 lines
Parsing log file(s) done
Generating reports...

================================================================================
---- Global Information --------------------------------------------------------
> request count                                       1000 (OK=1000   KO=0     )
> min response time                                     12 (OK=12     KO=-     )
> max response time                                    143 (OK=143    KO=-     )
> mean response time                                    16 (OK=16     KO=-     )
> std deviation                                          6 (OK=6      KO=-     )
> response time 50th percentile                         15 (OK=15     KO=-     )
> response time 75th percentile                         16 (OK=16     KO=-     )
> response time 95th percentile                         21 (OK=21     KO=-     )
> response time 99th percentile                         31 (OK=31     KO=-     )
> mean requests/sec                                   62.5 (OK=62.5   KO=-     )
---- Response Time Distribution ------------------------------------------------
> t < 800 ms                                          1000 (100%)
> 800 ms < t < 1200 ms                                   0 (  0%)
> t > 1200 ms                                            0 (  0%)
> failed                                                 0 (  0%)
================================================================================

Reports generated in 0s.
Please open the following file: D:\Bitbucket\gatling\target\gatling\radiussimulation-20190708151526921\index.html

Process finished with exit code 0

Еще один момент: как вы видите, 1 секунда теста, +/- несколько секунд для завершения последних запросов, продолжалась в течение 15 секунд !!!!

Заранее спасибо за помощь

Answer 1

Что касается обмена опытом по проблеме, описанной выше, кажется, что мои вызовы Radius блокируются, поэтому актеры выполняют Последовательно !!!!!

решениесостоит в асинхронизации вызовов Radius с использованием блоков Scala Future / onComplete.

вот основное пользовательское действие:

package com.ngenia.radius.action

import scala.util.{Failure, Success}

import io.gatling.core.action._
import io.gatling.core.session.Session
import io.gatling.core.stats.StatsEngine
import io.gatling.commons.util.Clock

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

import com.ngenia.radius.client
import com.ngenia.radius.client.RadiusUtils
import com.ngenia.radius.protocol.RadiusProtocol
import com.ngenia.radius.request._

case class RadiusAction(
                         requestType: Type,
                         radiusAttributes: RadiusAttributes,
                         radiusProtocol: RadiusProtocol,
                         clock: Clock,
                         statsEngine: StatsEngine,
                         next: Action
                       ) extends RadiusLogging {

  override def name: String = "RADIUS"

  override def execute(session: Session): Unit = {

    implicit val iSession = session

    val start = clock.nowMillis

    val future = Future {
      client.RadiusClient.sendRequest(radiusProtocol, requestType, radiusAttributes)
    }

    future.onComplete {
      case Success(response) => {
        log(start, clock.nowMillis, response._2, radiusAttributes.requestName, session, statsEngine)
        next !
          session
            .set("Acct-Session-Id", RadiusUtils.sessionId)
            .set("Framed-IP-Address", RadiusUtils.framedIPAddress(response._1))
      }
      case Failure(e) => e.printStackTrace
    }
  }
}