Record HdrHistogram for standard REST perf tests

perf-tests/README.md

@@ -27,7 +27,7 @@ which displays help similar to:
 [error]   -d, --duration <value>  Single simulation duration in seconds, default is 10
 [error]   -g, --gatling-reports   Generate Gatling reports for individuals sims, may significantly affect total time (disabled by default)
 ```
-
+Generating Gatling reports is useful if you want to verify additional data like latency or throughput distribution over time.
 If you want to run a test server separately from simulations, use a separate sbt session and start it using `ServerRunner`:
 
 ```
@@ -64,8 +64,16 @@ perfTest/Test/runMain sttp.tapir.perf.PerfTestSuiteRunner -m PostBytes,PostLongB
 
 ## Reports
 
-After all tests finish successfully, your console output will point to report files, 
-containing aggregated results from the entire suite:
+Each single simulation results in a latency HDR Histogram report printed to stdout as well as a file:
+
+```
+[info] ******* Histogram saved to /home/kc/code/oss/tapir/.sbt/matrix/perfTests/SimpleGetSimulation-2024-02-26_10_30_22
+```
+
+You can use [HDR Histogram Plotter](https://hdrhistogram.github.io/HdrHistogram/plotFiles.html) to plot a set of such files.
+
+The main report is generated after all tests, and contains results for standard Gatling latencies and mean throughput in a table combining
+all servers and tests. They will be printed to a HTML and a CSV file after the suite finishes:
 ```
 [info] ******* Test Suite report saved to /home/alice/projects/tapir/.sbt/matrix/perfTests/tapir-perf-tests-2024-01-22_16_33_14.csv
 [info] ******* Test Suite report saved to /home/alice/projects/tapir/.sbt/matrix/perfTests/tapir-perf-tests-2024-01-22_16_33_14.html

perf-tests/src/test/scala/sttp/tapir/perf/HistogramPrinter.scala

@@ -0,0 +1,30 @@
+package sttp.tapir.perf
+
+import org.HdrHistogram.Histogram
+
+import java.io.{FileOutputStream, PrintStream}
+import java.nio.file.Paths
+import scala.util.{Failure, Success, Using}
+import java.time.format.DateTimeFormatter
+import java.time.LocalDateTime
+
+object HistogramPrinter {
+  val formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd_HH_mm_ss")
+
+  def saveToFile(histogram: Histogram, histogramName: String): Unit = {
+    val currentTime = LocalDateTime.now().format(formatter)
+    val baseDir = System.getProperty("user.dir")
+    val targetFilePath = Paths.get(baseDir).resolve(s"$histogramName-$currentTime")
+    Using.Manager { use =>
+      val fos = use(new FileOutputStream(targetFilePath.toFile))
+      val ps = use(new PrintStream(fos))
+      histogram.outputPercentileDistribution(System.out, 1.0)
+      histogram.outputPercentileDistribution(ps, 1.0)
+    } match {
+      case Success(_) =>
+        println(s"******* Histogram saved to $targetFilePath")
+      case Failure(ex) =>
+        ex.printStackTrace
+    }
+  }
+}

perf-tests/src/test/scala/sttp/tapir/perf/Simulations.scala

@@ -1,15 +1,14 @@
 package sttp.tapir.perf
 
 import io.gatling.core.Predef._
+import io.gatling.core.session.Expression
 import io.gatling.core.structure.{ChainBuilder, PopulationBuilder}
 import io.gatling.http.Predef._
 import org.HdrHistogram.{ConcurrentHistogram, Histogram}
 import sttp.tapir.perf.Common._
 
-import java.io.{FileOutputStream, PrintStream}
-import java.nio.file.Paths
 import scala.concurrent.duration._
-import scala.util.{Failure, Random, Success, Using}
+import scala.util.Random
 
 object CommonSimulations {
   private val baseUrl = "127.0.0.1:8080"
@@ -39,39 +38,56 @@ object CommonSimulations {
   def userCount = getParam("user-count").toInt
   def duration = getParam("duration-seconds").toInt
   def namePrefix = if (getParamOpt("is-warm-up").map(_.toBoolean) == Some(true)) "[WARMUP] " else ""
+  val responseTimeKey = "responseTime"
+  def sessionSaveResponseTime = responseTimeInMillis.saveAs(responseTimeKey)
+  def recordResponseTime(histogram: Histogram): Expression[Session] = { session =>
+    val responseTime = session("responseTime").as[Int]
+    histogram.recordValue(responseTime.toLong)
+    session
+  }
+
   val httpProtocol = http.baseUrl(s"http://$baseUrl")
   val wsPubHttpProtocol = http.wsBaseUrl(s"ws://$baseUrl/ws")
 
-  def scenario_simple_get(routeNumber: Int): PopulationBuilder = {
-    val execHttpGet: ChainBuilder = exec(http(s"HTTP GET /path$routeNumber/4").get(s"/path$routeNumber/4"))
+  def scenario_simple_get(routeNumber: Int, histogram: Histogram): PopulationBuilder = {
+    val execHttpGet: ChainBuilder = exec(
+      http(s"HTTP GET /path$routeNumber/4")
+        .get(s"/path$routeNumber/4")
+        .check(sessionSaveResponseTime)
+    )
+      .exec(recordResponseTime(histogram))
 
     scenario(s"${namePrefix}Repeatedly invoke GET of route number $routeNumber")
       .during(duration)(execHttpGet)
       .inject(atOnceUsers(userCount))
       .protocols(httpProtocol)
   }
 
-  def scenario_post_string(routeNumber: Int): PopulationBuilder = {
+  def scenario_post_string(routeNumber: Int, histogram: Histogram): PopulationBuilder = {
     val execHttpPost = exec(
       http(s"HTTP POST /path$routeNumber")
         .post(s"/path$routeNumber")
         .body(StringBody(_ => new String(randomAlphanumByteArray(256))))
         .header("Content-Type", "text/plain")
+        .check(sessionSaveResponseTime)
     )
+      .exec(recordResponseTime(histogram))
 
     scenario(s"${namePrefix}Repeatedly invoke POST with short string body")
       .during(duration)(execHttpPost)
       .inject(atOnceUsers(userCount))
       .protocols(httpProtocol)
 
   }
-  def scenario_post_bytes(routeNumber: Int): PopulationBuilder = {
+  def scenario_post_bytes(routeNumber: Int, histogram: Histogram): PopulationBuilder = {
     val execHttpPost = exec(
       http(s"HTTP POST /pathBytes$routeNumber")
         .post(s"/pathBytes$routeNumber")
         .body(ByteArrayBody(_ => randomAlphanumByteArray(256)))
         .header("Content-Type", "text/plain") // otherwise Play complains
+        .check(sessionSaveResponseTime)
     )
+      .exec(recordResponseTime(histogram))
 
     scenario(s"${namePrefix}Repeatedly invoke POST with short byte array body")
       .during(duration)(execHttpPost)
@@ -93,27 +109,31 @@ object CommonSimulations {
       .protocols(httpProtocol)
   }
 
-  def scenario_post_long_bytes(routeNumber: Int): PopulationBuilder = {
+  def scenario_post_long_bytes(routeNumber: Int, histogram: Histogram): PopulationBuilder = {
     val execHttpPost = exec(
       http(s"HTTP POST /pathBytes$routeNumber")
         .post(s"/pathBytes$routeNumber")
         .body(ByteArrayBody(constRandomLongAlphanumBytes))
         .header("Content-Type", "text/plain") // otherwise Play complains
+        .check(sessionSaveResponseTime)
     )
+      .exec(recordResponseTime(histogram))
 
     scenario(s"${namePrefix}Repeatedly invoke POST with large byte array")
       .during(duration)(execHttpPost)
       .inject(atOnceUsers(userCount))
       .protocols(httpProtocol)
   }
 
-  def scenario_post_long_string(routeNumber: Int): PopulationBuilder = {
+  def scenario_post_long_string(routeNumber: Int, histogram: Histogram): PopulationBuilder = {
     val execHttpPost = exec(
       http(s"HTTP POST /path$routeNumber")
         .post(s"/path$routeNumber")
         .body(ByteArrayBody(constRandomLongAlphanumBytes))
         .header("Content-Type", "text/plain")
+        .check(sessionSaveResponseTime)
     )
+      .exec(recordResponseTime(histogram))
 
     scenario(s"${namePrefix}Repeatedly invoke POST with large byte array, interpreted to a String")
       .during(duration)(execHttpPost)
@@ -125,41 +145,58 @@ object CommonSimulations {
 
 import CommonSimulations._
 
-abstract class PerfTestSuiteRunnerSimulation extends Simulation
+abstract class PerfTestSuiteRunnerSimulation extends Simulation {
+  lazy val histogram = new ConcurrentHistogram(1L, 10000L, 3)
+
+  before {
+    println("Resetting Histogram")
+    histogram.reset
+  }
+
+  after {
+    HistogramPrinter.saveToFile(histogram, getClass.getSimpleName)
+  }
+}
 
 class SimpleGetSimulation extends PerfTestSuiteRunnerSimulation {
-  setUp(scenario_simple_get(0)): Unit
+  setUp(scenario_simple_get(0, histogram)): Unit
 }
 
 class SimpleGetMultiRouteSimulation extends PerfTestSuiteRunnerSimulation {
-  setUp(scenario_simple_get(127)): Unit
+  setUp(scenario_simple_get(127, histogram)): Unit
 }
 
 class PostBytesSimulation extends PerfTestSuiteRunnerSimulation {
-  setUp(scenario_post_bytes(0)): Unit
+  setUp(scenario_post_bytes(0, histogram)): Unit
+
 }
 
 class PostLongBytesSimulation extends PerfTestSuiteRunnerSimulation {
-  setUp(scenario_post_long_bytes(0)): Unit
+  setUp(scenario_post_long_bytes(0, histogram)): Unit
 }
 
 class PostFileSimulation extends PerfTestSuiteRunnerSimulation {
   setUp(scenario_post_file(0)): Unit
 }
 
 class PostStringSimulation extends PerfTestSuiteRunnerSimulation {
-  setUp(scenario_post_string(0)): Unit
+  setUp(scenario_post_string(0, histogram)): Unit
 }
 
 class PostLongStringSimulation extends PerfTestSuiteRunnerSimulation {
-  setUp(scenario_post_long_string(0)): Unit
+  setUp(scenario_post_long_string(0, histogram)): Unit
 }
 
 /** Based on https://github.com/kamilkloch/websocket-benchmark/ Can't be executed using PerfTestSuiteRunner, see perfTests/README.md
   */
 class WebSocketsSimulation extends Simulation {
   val scenarioUserCount = 2500
   val scenarioDuration = 30.seconds
+  lazy val histogram = new ConcurrentHistogram(1L, 10000L, 3)
+
+  after {
+    HistogramPrinter.saveToFile(histogram, "ws-latency")
+  }
 
   /** Sends requests after connecting a user to a WebSocket. For each request, waits at most 1 second for a response. The response body
     * carries a timestamp which is subtracted from current timestamp to calculate latency. The latency represents time between server
@@ -181,25 +218,6 @@ class WebSocketsSimulation extends Simulation {
         )
     )
   }
-
-  val histogram = new ConcurrentHistogram(1L, 10000L, 3)
-  Runtime.getRuntime.addShutdownHook(new Thread {
-    override def run(): Unit = {
-      val baseDir = System.getProperty("user.dir")
-      val targetFilePath = Paths.get(baseDir).resolve(s"websockets-latency-${System.currentTimeMillis()}")
-      Using.Manager { use =>
-        val fos = use(new FileOutputStream(targetFilePath.toFile))
-        val ps = use(new PrintStream(fos))
-        histogram.outputPercentileDistribution(System.out, 1.0)
-        histogram.outputPercentileDistribution(ps, 1.0)
-      } match {
-        case Success(_) =>
-          println(s"******* Histogram saved to $targetFilePath")
-        case Failure(ex) =>
-          ex.printStackTrace
-      }
-    }
-  })
   val warmup = scenario("WS warmup")
     .exec(
       ws("Warmup Connect WS").connect("/ts"),