LogFilter overhead - Githubissues

Dennis4b commented 4 days ago

I am aware of #810 which addressed initial performance concerns by implementing isDebugEnabled(..) and friends.

I am using zio-logging as an slf4j2 bridge, in order to capture all output related to particular requests or tasks, also from third party components.

In one project I use Apache Fop, which since its latest version 2.10 uses Apache Commons logger, which is an unconfigurable (in terms of filtering) log forwarder, to, in this case, zio-logging.

As far as logging goes it works perfectly.

However, I don't know if there is any amplification going on, but inside slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/ZioLoggerRuntime.scala the method isEnabled(name: String, level: Level) gets called with loglevel Debug over 3 million times for a single run of a single tiny document. I agree that this is probably excessive, but it's not something I can control.

Timings for comparison:

Original Apache Fop 2.9 (no usable zio-logging) > ~300ms per document
Slf4jBridge.initialize and default filtering in the loggers (>= Info) -> 5-10 seconds per document
Slf4jBridge.init(LogFilter.logLevel(_ > LogLevel.Debug)) -> ~900ms per document
No bridge logging into a black hole -> ~300ms per document

The current design of LogFilter requires collecting and passing all the parameters, even though a simple LogLevel filter is just going to look at one of them. When replaced by a short circuit check the overhead disappears and we go from 900ms down to 300ms for a single document run.

The following example modification demonstrates the idea- but note that the type test can not be checked at runtime so it is not a proper solution and would probably cause issues if another LogFilter is used in its case.

  override def isEnabled(name: String, level: Level): Boolean = { 
    val logLevel = ZioLoggerRuntime.logLevelMapping(level)
    filter match {
        /* if we are filtering on LogLevel, short circuit */
        case gp: LogFilter.GroupPredicateFilter[Any, LogLevel] => {
            val predicateFunction: (LogLevel => Boolean) = gp.valuePredicate
            predicateFunction(logLevel)
        }
        /* Otherwise previous behaviour */
        case _ => {
            filter(
              Trace(name, "", 0), 
              FiberId.None,
              logLevel,
              () => "", 
              Cause.empty,
              FiberRefs.empty,
              List.empty,
              Map(zio.logging.loggerNameAnnotationKey -> name)
            )   
        }
    }

With this code I have proper logging of everything >= Info at the original 300ms duration.

justcoon commented 4 days ago

hello @Dennis4b, yes, i understand, that there is some performance degradation, with current solution in considering your use case

actually initially i was thinking to do

final class ZioLoggerRuntime(runtime: Runtime[Any], filter: (String, LogLevel) => Boolean) extends LoggerRuntime

object Slf4jBridge {

  def init(filter: LogFilter[Any]): ZLayer[Any, Nothing, Unit] 
  def init(filter: (String, LogLevel) => Boolean): ZLayer[Any, Nothing, Unit] 

}

but at the end i did it like it is now, to have it less complicated ...

so, probably to do it like ^^^, could make it more performant in your case

Dennis4b commented 3 days ago

Thank you for your response!

The main cost is in constructing the Trace(name, "", 0), and the Map(zio.logging.loggerNameAnnotationKey -> name). If these are replaced with constants (for some particular dummy name) performance is nearly like a short circuit.

While I don't mind contributing or testing possible solutions, so that I don't need to maintain a private fork to use with Apache Fop, I don't know what the design goals for zio-logging are and what kind of solutions, if any, would be considered. It is of course a very extreme case to log so many messages, but it happens and I have to deal with it somehow.

At first glance, because of all the default constants, it seems the ZioLoggerRuntime.isEnabled doesn't really use much of the LogFilter functionality.

Your example: def init(filter: (String, LogLevel) => Boolean): ZLayer[Any, Nothing, Unit] looks like the ideal fit for such a sanity-check filter.

This is not ZIO library style but as an example that works for me:

diff --git a/slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/Slf4jBridge.scala b/slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/Slf4jBridge.scala
index 9240b14..bb29177 100644
--- a/slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/Slf4jBridge.scala
+++ b/slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/Slf4jBridge.scala
@@ -16,22 +16,29 @@
 package zio.logging.slf4j.bridge

 import zio.logging.LogFilter
-import zio.{ Config, NonEmptyChunk, Runtime, Semaphore, Unsafe, ZIO, ZLayer }
+import zio.{ Config, NonEmptyChunk, Runtime, Semaphore, Unsafe, ZIO, ZLayer, LogLevel }

 object Slf4jBridge {

+  sealed trait IngressFilter
+  object IngressFilter {
+     case class ViaLogFilter(filter: LogFilter[Any]) extends IngressFilter
+     case class ViaMethod(method: (String, LogLevel) => Boolean) extends IngressFilter
+  }
+
   val logFilterConfigPath: NonEmptyChunk[String] = zio.logging.loggerConfigPath :+ "filter"

   /**
    * initialize SLF4J bridge
    */
-  def initialize: ZLayer[Any, Nothing, Unit] = init(LogFilter.acceptAll)
+  def initialize: ZLayer[Any, Nothing, Unit] = init((_, _) => true)

   /**
    * initialize SLF4J bridge with `LogFilter`
    * @param filter Log filter
    */
-  def init(filter: LogFilter[Any]): ZLayer[Any, Nothing, Unit] = Runtime.enableCurrentFiber ++ layer(filter)
+  def init(filter: LogFilter[Any]): ZLayer[Any, Nothing, Unit] = Runtime.enableCurrentFiber ++ layer(IngressFilter.ViaLogFilter(filter))
+  def init(filter: (String, LogLevel) => Boolean): ZLayer[Any, Nothing, Unit] = Runtime.enableCurrentFiber ++ layer(IngressFilter.ViaMethod(filter))

   /**
    * initialize SLF4J bridge with `LogFilter` from configuration
@@ -43,25 +50,24 @@ object Slf4jBridge {
   /**
    * initialize SLF4J bridge without `FiberRef` propagation
    */
-  def initializeWithoutFiberRefPropagation: ZLayer[Any, Nothing, Unit] = initWithoutFiberRefPropagation(
-    LogFilter.acceptAll
-  )
+  def initializeWithoutFiberRefPropagation: ZLayer[Any, Nothing, Unit] = initWithoutFiberRefPropagation((_, _) => true)

   /**
    * initialize SLF4J bridge with `LogFilter`, without `FiberRef` propagation
    * @param filter Log filter
    */
-  def initWithoutFiberRefPropagation(filter: LogFilter[Any]): ZLayer[Any, Nothing, Unit] = layer(filter)
+  def initWithoutFiberRefPropagation(filter: LogFilter[Any]): ZLayer[Any, Nothing, Unit] = layer(IngressFilter.ViaLogFilter(filter))
+  def initWithoutFiberRefPropagation(filter: (String, LogLevel) => Boolean): ZLayer[Any, Nothing, Unit] = layer(IngressFilter.ViaMethod(filter))

   private val initLock = Semaphore.unsafe.make(1)(Unsafe.unsafe)

-  private def layer(filter: LogFilter[Any]): ZLayer[Any, Nothing, Unit] =
+  private def layer(filter: IngressFilter): ZLayer[Any, Nothing, Unit] =
     ZLayer(make(filter))

   private def layer(configPath: NonEmptyChunk[String]): ZLayer[Any, Config.Error, Unit] =
     ZLayer(make(configPath))

-  def make(filter: LogFilter[Any]): ZIO[Any, Nothing, Unit] =
+  def make(filter: IngressFilter): ZIO[Any, Nothing, Unit] =
     for {
       runtime <- ZIO.runtime[Any]
       _       <- initLock.withPermit {
@@ -75,6 +81,6 @@ object Slf4jBridge {
     } yield ()

   def make(configPath: NonEmptyChunk[String] = logFilterConfigPath): ZIO[Any, Config.Error, Unit] =
-    LogFilter.LogLevelByNameConfig.load(configPath).flatMap(c => make(c.toFilter))
+    LogFilter.LogLevelByNameConfig.load(configPath).flatMap(c => make(IngressFilter.ViaLogFilter(c.toFilter)))

 }
diff --git a/slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/ZioLoggerRuntime.scala b/slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/ZioLoggerRuntime.scala
index 43ac331..26a265f 100644
--- a/slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/ZioLoggerRuntime.scala
+++ b/slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/ZioLoggerRuntime.scala
@@ -17,12 +17,11 @@ package zio.logging.slf4j.bridge

 import org.slf4j.event.{ KeyValuePair, Level }
 import org.slf4j.helpers.MessageFormatter
-import zio.logging.LogFilter
 import zio.{ Cause, Fiber, FiberId, FiberRef, FiberRefs, LogLevel, Runtime, Trace, Unsafe }

 import scala.jdk.CollectionConverters._

-final class ZioLoggerRuntime(runtime: Runtime[Any], filter: LogFilter[Any]) extends LoggerRuntime {
+final class ZioLoggerRuntime(runtime: Runtime[Any], filter: Slf4jBridge.IngressFilter) extends LoggerRuntime {

   override def log(
     name: String,
@@ -78,19 +77,20 @@ final class ZioLoggerRuntime(runtime: Runtime[Any], filter: LogFilter[Any]) exte

   override def isEnabled(name: String, level: Level): Boolean = {
     val logLevel = ZioLoggerRuntime.logLevelMapping(level)
-
-    filter(
-      Trace(name, "", 0),
-      FiberId.None,
-      logLevel,
-      () => "",
-      Cause.empty,
-      FiberRefs.empty,
-      List.empty,
-      Map(zio.logging.loggerNameAnnotationKey -> name)
-    )
+    filter match {
+        case Slf4jBridge.IngressFilter.ViaMethod(m) => m(name, logLevel)
+        case Slf4jBridge.IngressFilter.ViaLogFilter(filter) => filter(
+          Trace(name, "", 0),
+          FiberId.None,
+          logLevel,
+          () => "",
+          Cause.empty,
+          FiberRefs.empty,
+          List.empty,
+          Map(zio.logging.loggerNameAnnotationKey -> name)
+        )
+    }
   }
-
 }

 object ZioLoggerRuntime {

justcoon commented 3 days ago

The main cost is in constructing the Trace(name, "", 0), and the Map(zio.logging.loggerNameAnnotationKey -> name)

yes, i see it in same way

so probably then, rather then have specific implementation of filters for slf4j-bridge

it could be better to change underlying implementation, in way that trace and annotations for name are created just once more like there is already logger per name https://github.com/zio/zio-logging/blob/master/slf4j2-bridge/src/main/java/zio/logging/slf4j/bridge/Logger.java but, it will require to do more changes ...

justcoon commented 1 day ago

hello @Dennis4b , i created PR https://github.com/zio/zio-logging/pull/901 , there are changes for slf4j-bridge (v1) as it was easier to do it there, please take a look

then i can do conceptually similar changes for slf4j2-bridge

Dennis4b commented 1 day ago

Thank you for looking at this so quickly.

So, I don't use the bridge v1, but, if I simulate the same changes in v2, that is:

  // is there a reason for this to be lazy ?
  lazy val m = Map(zio.logging.loggerNameAnnotationKey -> "Dummy")

  override def isEnabled(name: String, level: Level): Boolean = { 
    val logLevel = ZioLoggerRuntime.logLevelMapping(level)

    filter(
      Trace.empty,    //  Trace(name, "", 0),
      FiberId.None,
      logLevel,
      () => "", 
      Cause.empty,
      FiberRefs.empty,
      List.empty,
      m,      // Map(zio.logging.loggerNameAnnotationKey -> name)
    )

then this solves the issue and performance is similar to the short circuit filter, so I think this would be a good solution.

zio / zio-logging

LogFilter overhead #899