logger-bench-results.md

Benchmark                                                     (size)  Mode  Cnt        Score       Error   Units
LoggerBench.LoggingOfStreamedBody                               1000  avgt    5        0.017 ±     0.002   ms/op
LoggerBench.LoggingOfStreamedBody:·gc.alloc.rate.norm           1000  avgt    5    39861.722 ±     4.766    B/op
LoggerBench.LoggingOfStreamedBody                              10000  avgt    5        0.037 ±     0.003   ms/op
LoggerBench.LoggingOfStreamedBody:·gc.alloc.rate.norm          10000  avgt    5   143985.389 ±     0.395    B/op
LoggerBench.LoggingOfStreamedBody                             100000  avgt    5        0.606 ±     0.005   ms/op
LoggerBench.LoggingOfStreamedBody:·gc.alloc.rate.norm         100000  avgt    5  1664486.729 ±     8.356    B/op
LoggerBench.LoggingOfStrictBody                                 1000  avgt    5        0.010 ±     0.001   ms/op
LoggerBench.LoggingOfStrictBody:·gc.alloc.rate.norm             1000  avgt    5     7359.449 ±     0.077    B/op
LoggerBench.LoggingOfStrictBody                                10000  avgt    5        0.090 ±     0.002   ms/op
LoggerBench.LoggingOfStrictBody:·gc.alloc.rate.norm            10000  avgt    5    59927.531 ±    44.047    B/op
LoggerBench.LoggingOfStrictBody                               100000  avgt    5        1.062 ±     0.004   ms/op
LoggerBench.LoggingOfStrictBody:·gc.alloc.rate.norm           100000  avgt    5   585793.991 ±     4.921    B/op

LoggerBench.scala

import cats.effect.IO
import cats.effect.unsafe.implicits.global
import org.http4s.{Entity, Response}
import org.http4s.internal.Logger
import org.openjdk.jmh.annotations._
import scodec.bits.ByteVector

import java.util.concurrent.TimeUnit
import scala.util.Random

@BenchmarkMode(Array(Mode.AverageTime))
@OutputTimeUnit(TimeUnit.MILLISECONDS)
@State(Scope.Benchmark)
class LoggerBench {
  @Param(Array("1000", "10000", "100000"))
  var size: Int = _

  var rawData: Array[Byte] = _

  @Setup(Level.Trial)
  def setup(): Unit =
    rawData = Random.nextBytes(size)

  @Benchmark
  def LoggingOfStreamedBody: Unit = {
    val stream =
      fs2.Stream
        .emits(rawData)
        .covary[IO]
        .rechunkRandomlyWithSeed(32, 32)(rawData.hashCode().toLong)

    Logger.defaultLogBody(Response(entity = Entity(stream)))(true).get.as(()).unsafeRunSync()
  }

  @Benchmark
  def LoggingOfStrictBody: Unit = {
    val bv = ByteVector(rawData)

    Logger
      .defaultLogBody(Response[IO](entity = Entity.strict(bv)))(true)
      .get
      .as(())
      .unsafeRunSync()
  }
}

ResponseLoggerBench.scala

import cats.effect.IO
import cats.effect.unsafe.implicits.global
import fs2.{Chunk, Pipe, Stream}
import org.http4s.{Entity, Response}
import org.http4s.internal.Logger
import org.openjdk.jmh.annotations._
import scodec.bits.ByteVector

import java.util.concurrent.TimeUnit
import scala.util.Random

@BenchmarkMode(Array(Mode.AverageTime))
@OutputTimeUnit(TimeUnit.MILLISECONDS)
@State(Scope.Benchmark)
class StreamBench {
  @Param(Array("1000", "10000", "100000"))
  var size: Int = _

  var rawData: Array[Byte] = _

  @Setup(Level.Trial)
  def setup(): Unit =
    rawData = Random.nextBytes(size)

  @Benchmark
  def CurrentBodyLogging: Unit =
    IO.ref(Vector.empty[Chunk[Byte]])
      .flatMap { vec =>
        val newBody = Stream.eval(vec.get).flatMap(v => Stream.emits(v)).unchunks
        val logPipe: Pipe[IO, Byte, Byte] =
          _.observe(_.chunks.flatMap(c => Stream.exec(vec.update(_ :+ c))))
            .onFinalizeWeak(
              Logger.defaultLogBody(Response(entity = Entity(newBody)))(true).get.as(())
            )

        fs2.Stream
          .emits(rawData)
          .covary[IO]
          .rechunkRandomlyWithSeed(32, 32)(rawData.hashCode().toLong)
          .through(logPipe)
          .compile
          .drain
      }
      .unsafeRunSync()

  @Benchmark
  def BodyLoggingRespectingEntityModel: Unit =
    IO.ref(ByteVector.empty)
      .flatMap { bv =>
        val logPipe: Pipe[IO, Byte, Byte] =
          _.observe(_.chunks.flatMap(c => Stream.exec(bv.update(_ ++ c.toByteVector))))
            .onFinalizeWeak(
              bv.get.flatMap(bv =>
                Logger
                  .defaultLogBody(Response[IO](entity = Entity.strict(bv)))(true)
                  .get
                  .as(())
              )
            )

        fs2.Stream
          .emits(rawData)
          .covary[IO]
          .rechunkRandomlyWithSeed(32, 32)(rawData.hashCode().toLong)
          .through(logPipe)
          .compile
          .drain
      }
      .unsafeRunSync()
}

results.md

Benchmark                                                                      (size)  Mode  Cnt        Score       Error   Units
StreamBench.BodyLoggingRespectingEntityModel                                     1000  avgt    5        0.119 ±     0.014   ms/op
StreamBench.BodyLoggingRespectingEntityModel:·gc.alloc.rate.norm                 1000  avgt    5   240551.126 ±   835.507    B/op
StreamBench.BodyLoggingRespectingEntityModel                                    10000  avgt    5        0.203 ±     0.046   ms/op
StreamBench.BodyLoggingRespectingEntityModel:·gc.alloc.rate.norm                10000  avgt    5   288581.383 ±  1675.334    B/op
StreamBench.BodyLoggingRespectingEntityModel                                   100000  avgt    5        1.195 ±     0.009   ms/op
StreamBench.BodyLoggingRespectingEntityModel:·gc.alloc.rate.norm               100000  avgt    5   717638.671 ±   331.169    B/op
StreamBench.CurrentBodyLogging                                                   1000  avgt    5        0.122 ±     0.012   ms/op
StreamBench.CurrentBodyLogging:·gc.alloc.rate.norm                               1000  avgt    5   260361.355 ±   190.546    B/op
StreamBench.CurrentBodyLogging                                                  10000  avgt    5        0.144 ±     0.013   ms/op
StreamBench.CurrentBodyLogging:·gc.alloc.rate.norm                              10000  avgt    5   416624.951 ±  1455.973    B/op
StreamBench.CurrentBodyLogging                                                 100000  avgt    5        0.701 ±     0.101   ms/op
StreamBench.CurrentBodyLogging:·gc.alloc.rate.norm                             100000  avgt    5  1411222.382 ±   887.469    B/op