140: #140 implement applicative filter DSL

build.sbt

@@ -145,3 +145,11 @@ lazy val examplesJs = crossProject(JSPlatform)
   .settings(publish / skip := true)
   .jsConfigure(_.settings(scalaJSUseMainModuleInitializer := true))
   .dependsOn(core)
+
+lazy val benchmarks = crossProject(JSPlatform, JVMPlatform, NativePlatform)
+  .crossType(CrossType.Pure)
+  .in(file("./modules/benchmarks"))
+  .dependsOn(core)
+  .enablePlugins(JmhPlugin)
+  .settings(commonSettings)
+  .settings(publish / skip := true)

modules/benchmarks/FilterBenchmark.scala.output.md

@@ -0,0 +1,67 @@
+# The configuration and hardware info
+
+```
+Software:
+
+  System Version: macOS 13.2.1 (22D68)
+  Kernel Version: Darwin 22.3.0
+  Boot Volume: Macintosh HD
+  Boot Mode: Normal
+  Computer Name: MacBook Pro (21)
+  Secure Virtual Memory: Enabled
+
+Hardware:
+
+  Model Name: MacBook Pro
+  Model Identifier: MacBookPro18,1
+  Model Number: Z14Y00047DK/A
+  Chip: Apple M1 Pro
+  Total Number of Cores: 10 (8 performance and 2 efficiency)
+  Memory: 32 GB
+```
+
+```
+[info] # JMH version: 1.32
+[info] # VM version: JDK 17.0.1, OpenJDK 64-Bit Server VM, 17.0.1+12
+[info] # VM invoker: /Users/dkFePaHa/.asdf/installs/java/adoptopenjdk-17.0.1+12/bin/java
+[info] # VM options: <none>
+[info] # Blackhole mode: full + dont-inline hint
+[info] # Warmup: 5 iterations, 10 s each
+[info] # Measurement: 5 iterations, 10 s each
+[info] # Timeout: 10 min per iteration
+[info] # Threads: 1 thread, will synchronize iterations
+[info] # Benchmark mode: Throughput, ops/time
+```
+
+# The results
+
+```
+[info] # Run complete. Total time: 00:25:04
+[info] REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
+[info] why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
+[info] experiments, perform baseline and negative tests that provide experimental control, make sure
+[info] the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
+[info] Do not assume the numbers tell you what you want them to tell.
+[info] Benchmark                        Mode  Cnt      Score     Error  Units
+[info] FilterBenchmark.testEverything  thrpt   25    255,250 ±  12,763  ops/s
+[info] FilterBenchmark.testInfo        thrpt   25    722,664 ±  25,608  ops/s
+[info] FilterBenchmark.testNothing     thrpt   25  11275,189 ± 314,631  ops/s
+[success] Total time: 1509 s (25:09), completed 31 Mar 2023, 10.38.35
+```
+
+## Interpretation
+
+The results look similar to what I would expect. The benchmarks log 3 times at different levels (Info, Warn, Error) in a
+tight loop of 1000 iterations. `testEverything` uses `Filter.everything`, i.e. it has to _always_ materialize the log
+output. This is the worst case scenario.
+
+`testInfo` uses the `Filter.exactLevel(LogLevel.Info)` which will only materialize `1/3` of the lines. This is almost 3
+times as fast as `everything`.
+
+`testNothing` is the best case scenario where nothing is materialized. This is more than 3 times faster, since not only
+is nothing materialized, the outputs are never called, i.e. the compiler should be able to eliminate a lot of code (no
+blackhole consume calls anymore!).
+
+In general, these results are in line with the outcome I hoped for with the refactoring
+from `type Filter = LogLine => Boolean` to
+this new applicative style.

modules/benchmarks/src/main/scala/benchmarks/FilterBenchmark.scala

@@ -0,0 +1,49 @@
+package benchmarks
+
+import cats.effect.IO
+import cats.syntax.all.*
+import org.legogroup.woof.{*, given}
+import org.openjdk.jmh.annotations.Benchmark
+import org.openjdk.jmh.infra.Blackhole
+import cats.effect.unsafe.implicits.global
+
+import scala.annotation.tailrec
+
+class FilterBenchmark:
+
+  def test(blackhole: Blackhole)(using Filter): IO[Unit] =
+
+    val blackholeOutput: Output[IO] = new:
+      override def output(str: String): IO[Unit]      = IO.delay(blackhole.consume(str))
+      override def outputError(str: String): IO[Unit] = IO.delay(blackhole.consume(str))
+
+    given Printer = ColorPrinter()
+    for
+      logger <- DefaultLogger.makeIo(blackholeOutput)
+      _ <-
+        def loop(remaining: Int): IO[Unit] =
+          val message = s"message$remaining"
+          if remaining <= 0 then IO.unit
+          else
+            for
+              _ <- logger.info(message)
+              _ <- logger.warn(message)
+              _ <- logger.error(message)
+              _ <- loop(remaining - 1)
+            yield ()
+        end loop
+        loop(1000)
+    yield ()
+    end for
+  end test
+
+  @Benchmark
+  def testEverything(blackhole: Blackhole): Unit = test(blackhole)(using Filter.everything).unsafeRunSync()
+
+  @Benchmark
+  def testNothing(blackhole: Blackhole): Unit = test(blackhole)(using Filter.nothing).unsafeRunSync()
+
+  @Benchmark
+  def testInfo(blackhole: Blackhole): Unit = test(blackhole)(using Filter.exactLevel(LogLevel.Info)).unsafeRunSync()
+
+end FilterBenchmark

modules/core/shared/src/main/scala/org/legogroup/woof/DefaultLogger.scala

@@ -0,0 +1,59 @@
+package org.legogroup.woof
+
+import cats.Monad
+import cats.effect.IO
+import cats.effect.kernel.Clock
+import org.legogroup.woof.Logger.{ioStringLocal, StringLocal}
+import cats.syntax.all.*
+
+class DefaultLogger[F[_]: StringLocal: Monad: Clock](output: Output[F], outputs: Output[F]*)(using Printer, Filter)
+    extends Logger[F]:
+
+  val stringLocal: StringLocal[F] = summon[StringLocal[F]]
+  val printer: Printer            = summon[Printer]
+  val filter: Filter              = summon[Filter]
+
+  private[woof] def makeLogString(
+      level: LogLevel,
+      info: LogInfo,
+      message: String,
+      context: List[(String, String)],
+  ): F[String] =
+    Clock[F].realTime
+      .map(d => EpochMillis(d.toMillis))
+      .map(now => summon[Printer].toPrint(now, level, info, message, context))
+
+  private[woof] def doOutputs(level: LogLevel, s: String): F[Unit] =
+    val allOutputs = outputs.prepended(output)
+    level match
+      case LogLevel.Error => allOutputs.traverse_(_.outputError(s))
+      case _              => allOutputs.traverse_(_.output(s))
+
+  override def doLog(level: LogLevel, message: String)(using logInfo: LogInfo): F[Unit] =
+    if shouldLog(level, message, filter) then logToOutputs(level, message) else ().pure
+
+  private[woof] def shouldLog(level: LogLevel, message: String, filter: Filter)(using logInfo: LogInfo): Boolean =
+    filter match
+      case Filter.AtLeastLevel(atLeastLevel) => level >= atLeastLevel
+      case Filter.ExactLevel(exactLevel)     => level === exactLevel
+      case Filter.ClassRegex(regex)          => regex.matches(logInfo.enclosingClass.printableName)
+      case Filter.MessageFilter(filter)      => filter(message)
+      case Filter.LineNumberFilter(filter)   => filter(logInfo.lineNumber)
+      case Filter.CompositeAnd(a, b)         => shouldLog(level, message, a) && shouldLog(level, message, b)
+      case Filter.CompositeOr(a, b)          => shouldLog(level, message, a) || shouldLog(level, message, b)
+      case Filter.Nothing                    => false
+      case Filter.Everything                 => true
+
+  private[woof] def logToOutputs(level: LogLevel, message: String)(using logInfo: LogInfo): F[Unit] = for
+    context <- summon[StringLocal[F]].ask
+    logLine <- makeLogString(level, logInfo, message, context)
+    _       <- doOutputs(level, logLine).whenA(summon[Filter].interpret(LogLine(level, logInfo, logLine, context)))
+  yield ()
+
+end DefaultLogger
+
+object DefaultLogger:
+  def makeIo(output: Output[IO], outputs: Output[IO]*)(using Clock[IO], Printer, Filter): IO[DefaultLogger[IO]] =
+    for given StringLocal[IO] <- ioStringLocal
+    yield new DefaultLogger[IO](output, outputs*)
+end DefaultLogger

modules/core/shared/src/main/scala/org/legogroup/woof/Filter.scala

@@ -7,22 +7,46 @@ import scala.util.matching.Regex
 
 case class LogLine(level: LogLevel, info: LogInfo, message: String, context: List[(String, String)])
 
-type Filter = LogLine => Boolean
+enum Filter:
+  private[woof] case AtLeastLevel(level: LogLevel)
+  private[woof] case ExactLevel(level: LogLevel)
+  private[woof] case ClassRegex(regex: Regex)
+  private[woof] case MessageFilter(filter: String => Boolean)
+  private[woof] case LineNumberFilter(filter: Int => Boolean)
+  private[woof] case CompositeAnd(a: Filter, b: Filter)
+  private[woof] case CompositeOr(a: Filter, b: Filter)
+  private[woof] case Nothing
+  private[woof] case Everything
+end Filter
 
 object Filter:
 
-  val atLeastLevel: LogLevel => Filter = level => line => line.level >= level
-  val exactLevel: LogLevel => Filter   = level => line => line.level == level
-  val regexFilter: Regex => Filter     = regex => line => regex.matches(line.info.enclosingClass.printableName)
-  val nothing: Filter                  = _ => false
-  val everything: Filter               = _ => true
+  val atLeastLevel: LogLevel => Filter               = level => AtLeastLevel(level)
+  val exactLevel: LogLevel => Filter                 = level => ExactLevel(level)
+  val regexFilter: Regex => Filter                   = regex => ClassRegex(regex)
+  val nothing: Filter                                = Nothing
+  val everything: Filter                             = Everything
+  def lineNumberFilter(test: Int => Boolean): Filter = LineNumberFilter(test)
+  def messageFilter(test: String => Boolean): Filter = MessageFilter(test)
 
   given Monoid[Filter] with
     def empty: Filter                         = nothing
     def combine(f: Filter, g: Filter): Filter = f or g
 
-end Filter
+  extension (f: Filter)
+    infix def and(g: Filter): Filter = Filter.CompositeAnd(f, g)
+    infix def or(g: Filter): Filter  = Filter.CompositeOr(f, g)
+    def interpret: LogLine => Boolean = line =>
+      f match
+        case Filter.AtLeastLevel(level)      => line.level >= level
+        case Filter.ExactLevel(level)        => line.level == level
+        case Filter.ClassRegex(regex)        => regex.matches(line.info.enclosingClass.printableName)
+        case Filter.CompositeAnd(a, b)       => a.interpret(line) && b.interpret(line)
+        case Filter.CompositeOr(a, b)        => a.interpret(line) || b.interpret(line)
+        case Filter.LineNumberFilter(filter) => filter(line.info.lineNumber)
+        case Filter.MessageFilter(filter)    => filter(line.message)
+        case Filter.Nothing                  => false
+        case Filter.Everything               => true
+  end extension
 
-extension (f: Filter)
-  infix def and(g: Filter): Filter = line => f(line) && g(line)
-  infix def or(g: Filter): Filter  = line => f(line) || g(line)
+end Filter

modules/core/shared/src/main/scala/org/legogroup/woof/Logger.scala

@@ -27,44 +27,6 @@ trait Logger[F[_]]:
 
 end Logger
 
-class DefaultLogger[F[_]: StringLocal: Monad: Clock](output: Output[F], outputs: Output[F]*)(using Printer, Filter)
-    extends Logger[F]:
-
-  val stringLocal: StringLocal[F] = summon[StringLocal[F]]
-  val printer: Printer            = summon[Printer]
-  val filter: Filter              = summon[Filter]
-
-  private[woof] def makeLogString(
-      level: LogLevel,
-      info: LogInfo,
-      message: String,
-      context: List[(String, String)],
-  ): F[String] =
-    Clock[F].realTime
-      .map(d => EpochMillis(d.toMillis))
-      .map(now => summon[Printer].toPrint(now, level, info, message, context))
-
-  private[woof] def doOutputs(level: LogLevel, s: String): F[Unit] =
-    val allOutputs = outputs.prepended(output)
-    level match
-      case LogLevel.Error => allOutputs.traverse_(_.outputError(s))
-      case _              => allOutputs.traverse_(_.output(s))
-
-  override def doLog(level: LogLevel, message: String)(using logInfo: LogInfo): F[Unit] =
-    for
-      context <- summon[StringLocal[F]].ask
-      logLine <- makeLogString(level, logInfo, message, context)
-      _       <- doOutputs(level, logLine).whenA(summon[Filter](LogLine(level, logInfo, logLine, context)))
-    yield ()
-
-end DefaultLogger
-
-object DefaultLogger:
-  def makeIo(output: Output[IO], outputs: Output[IO]*)(using Clock[IO], Printer, Filter): IO[DefaultLogger[IO]] =
-    for given StringLocal[IO] <- ioStringLocal
-    yield new DefaultLogger[IO](output, outputs*)
-end DefaultLogger
-
 object Logger:
 
   extension [F[_]: Logger, A](fa: F[A])

modules/examples/src/main/scala/examples/filters/CustomFilter.scala

@@ -19,23 +19,23 @@ object CustomFilter extends IOApp.Simple:
     yield ()
 
   def evenLines: IO[Unit] =
-    given Filter = logLine => logLine.info.lineNumber % 2 == 0 // only print *even* lines
+    given Filter = Filter.lineNumberFilter(_ % 2 == 0) // only print *even* lines
     for
       given Logger[IO] <- DefaultLogger.makeIo(Output.fromConsole)
       _                <- program
     yield ()
 
   def filterWords: IO[Unit] =
     val filterWords = Set("Serious", "business", "crazy")
-    given Filter    = logLine => logLine.message.split("\\s").exists(filterWords.contains)
+    given Filter    = Filter.messageFilter(_.split("\\s").exists(filterWords.contains))
     for
       given Logger[IO] <- DefaultLogger.makeIo(Output.fromConsole)
       _                <- program
     yield ()
 
   def filterNotWords: IO[Unit] =
     val filterWords = Set("crazy")
-    given Filter    = logLine => !logLine.message.split("\\s").exists(filterWords.contains)
+    given Filter    = Filter.messageFilter(!_.split("\\s").exists(filterWords))
     for
       given Logger[IO] <- DefaultLogger.makeIo(Output.fromConsole)
       _                <- program

project/plugins.sbt

@@ -5,5 +5,6 @@ addSbtPlugin("org.portable-scala" % "sbt-scalajs-crossproject"      % "1.2.0")
 addSbtPlugin("org.scala-native"   % "sbt-scala-native"              % "0.4.12")
 addSbtPlugin("org.portable-scala" % "sbt-scala-native-crossproject" % "1.2.0")
 addSbtPlugin("org.scalameta"      % "sbt-scalafmt"                  % "2.5.0")
+addSbtPlugin("pl.project13.scala" % "sbt-jmh"                       % "0.4.3")
 
 addDependencyTreePlugin