Make non-emitted logs cheaper

[Lukasa]

Looking at some perf traces today, I stumbled upon the fact that swift-log appears to be failing at its goal of making non-issued logs approximately free. Consider this code:

public func whyThough(_ logger: Logger) {
    logger.trace("Hello, world!")
}

In an ideal world, in release builds this code would execute almost no instructions when the log level is higher than trace: it would check the log level, and then return.

In practice what it does is:

• Call swift_beginAccess
• Call outlined init with copy of Logging.LogHandler, which includes calling through the VWT for the LogHandler to execute its copy constructor
• Call swift_project_boxed_opaque_existential_1
• Call swift_destroy_boxed_opaque_existential_1

This appears to all boil down to the fact that the logLevel is held on the LogHandler, not the Logger, so we have to touch the existential in order to load the log level.

In some cases this may not be excessive, but if anyone has inserted trace level logs in hot code paths the cost can spiral quite badly. We’re seeing it take up to 10% of the CPU time in some of our high packet rate benchmarks.

Now, we can resolve this issue by just deleting the trace logging, but I wanted to ask: do we think swift-log should be this expensive? Are we interested in making it faster? We could make it faster by moving the log level to the Logger, not the LogHandler, but conceptually that could break existing code if they were playing weird tricks, and it could cause things that used to fit safely into existentials to not fit. How do we feel?

[czechboy0]

If we assume that we won't break API to address this, we somehow need to tell the Logger not to consult the LogHandler for its logLevel, and just use an inline value in Logger itself.

Some options:

1. A flag on Logger itself, specified during Logger.init, e.g. Logger(label: ..., factory: ..., usesInlineLogLevel: Bool = false) - defaults to existing behavior today, allows opting into the fast path.
2. An override point on LogHandler, read once by Logger during init, for example: var usesDynamicLogLevel: Bool { true }, which a LogHandler can override to false to take the fast path.

[Lukasa]

We may need to play clever games here, because any extra check here will slow both paths down. Not a lot (it should branch predict well), but it won't be free unless we do something quite clever, at least on the fast path.

[czechboy0]

If we add a let usesInlineLogLevel: Bool into the Logger itself, not even in the Storage (

swift-log/Sources/Logging/Logging.swift

Line 47 in 1be2c17

public struct Logger {

), it should be cheap enough?

[Lukasa]

The downside of that is it makes the logger even larger, and it also produces slightly-less-than-optimal outcome. What we would have ideal is something close to a two instruction operation, cmp and jmp. That is, we want to compare the log level, and then for non-matching cases just jump over all the logging.

If we have a boolean like that, we get two comparisons: one against the boolean, then one against the level. I think the sneaky thing I'd want to do is to define some wrapping spelling to arrange for us to be able to say "I have an inline level and it's higher than the level of this log, so return now", vs "I either don't have an inline level or it's lower than the level of this log". That allows the fast path to remain at one comparison, while the slow path potentially has to re-check this value. Not the end of the world. It'll be a bit nasty looking, but that's what it'll cost us to get this to do what it should.

[czechboy0]

While the Logger gets larger, it's still safely under the 3 words limit so it'll stay on the stack. If we put it into the storage, that might be even slower, but I'm happy with either.

I don't exactly follow how to achieve all this in a single comparison while preserving backwards compatibility, so would love to see a patch :)

[FranzBusch]

I think we should seriously explore if we can just break the semantics here and move the log level and potentially the metadata up to the logger. This needs a bit of investigation to first:

1. Produce a baselevel benchmark
2. Understand how much this change would net in performance
3. Write up a small proposal of how this change would work and be rolled out

[Lukasa]

So FWIW, retaining the existing semantics won't hurt the performance of the new optimal path, and will only very slightly hurt the performance of the existing path (specifically, getting and setting the log level is slightly more complex than it was before). The actual cost isn't going to be a performance delta, it's the complexity delta of not knowing if you've accidentally got a "slow" logger or a "fast" one.

[Lukasa]

So you can do it like this:

diff --git a/Sources/Logging/Logging.swift b/Sources/Logging/Logging.swift
index 544a739..3059bba 100644
--- a/Sources/Logging/Logging.swift
+++ b/Sources/Logging/Logging.swift
@@ -69,6 +69,11 @@ public struct Logger {
 
     @usableFromInline
     internal var _storage: Storage
+
+    @usableFromInline
+    internal var inlineLogLevel: Level?
+
+    @inlinable
     public var label: String {
         self._storage.label
     }
@@ -94,12 +99,19 @@ public struct Logger {
     }
 
     @usableFromInline
-    internal init(label: String, _ handler: any LogHandler) {
+    internal init(label: String, usesInlineLogLevel: Bool, _ handler: any LogHandler) {
         self._storage = Storage(label: label, handler: handler)
+        self.inlineLogLevel = usesInlineLogLevel ? handler.logLevel : nil
     }
 }
 
 extension Logger {
+    @inlinable
+    @inline(__always)
+    func definitelyShouldNotLog(level: Level) -> Bool {
+        self.inlineLogLevel.naturalIntegralValue > level.naturalIntegralValue
+    }
+
     /// Log a message passing the log level as a parameter.
     ///
     /// If the `logLevel` passed to this method is more severe than the `Logger`'s ``logLevel``, it will be logged,
@@ -127,7 +139,12 @@ extension Logger {
         function: String = #function,
         line: UInt = #line
     ) {
-        if self.logLevel <= level {
+        // First, we check the inline log level. If this returns false, we
+        // _either_ have an inline log level that lets us log, _or_ we don't
+        // and have to ask the handler. Having an inline log level is the only
+        // fast path we have, so we optimize hard for that.
+        if self.definitelyShouldNotLog(level: level) { return }
+        if self.inlineLogLevel != nil || self.handler.logLevel <= level {
             self.handler.log(
                 level: level,
                 message: message(),
@@ -190,10 +207,18 @@ extension Logger {
     @inlinable
     public var logLevel: Logger.Level {
         get {
-            self.handler.logLevel
+            if let inlineLogLevel = self.inlineLogLevel {
+                return inlineLogLevel
+            } else {
+                return self.handler.logLevel
+            }
         }
         set {
-            self.handler.logLevel = newValue
+            if self.inlineLogLevel != nil {
+                self.inlineLogLevel = newValue
+            } else {
+                self.handler.logLevel = newValue
+            }
         }
     }
 }
@@ -884,7 +909,22 @@ extension Logger {
     /// - parameters:
     ///     - label: An identifier for the creator of a `Logger`.
     public init(label: String) {
-        self.init(label: label, LoggingSystem.factory(label, LoggingSystem.metadataProvider))
+        self.init(label: label, usesInlineLogLevel: false)
+    }
+
+
+    /// Construct a `Logger` given a `label` identifying the creator of the `Logger`.
+    ///
+    /// The `label` should identify the creator of the `Logger`. This can be an application, a sub-system, or even
+    /// a datatype.
+    ///
+    /// - parameters:
+    ///     - label: An identifier for the creator of a `Logger`.
+    ///     - usesInlineLogLevel: If `true`, uses a log level stored on the `Logger` instead of asking the
+    ///         bootstrapped `LogHandler`. Allows more efficient log bypassing at the cost of not allowing
+    ///         dynamic log level changes.
+    public init(label: String, usesInlineLogLevel: Bool) {
+        self.init(label: label, usesInlineLogLevel: usesInlineLogLevel, LoggingSystem.factory(label, LoggingSystem.metadataProvider))
     }
 
     /// Construct a `Logger` given a `label` identifying the creator of the `Logger` or a non-standard `LogHandler`.
@@ -899,7 +939,25 @@ extension Logger {
     ///     - label: An identifier for the creator of a `Logger`.
     ///     - factory: A closure creating non-standard `LogHandler`s.
     public init(label: String, factory: (String) -> any LogHandler) {
-        self = Logger(label: label, factory(label))
+        self = Logger(label: label, usesInlineLogLevel: false, factory: factory)
+    }
+
+    /// Construct a `Logger` given a `label` identifying the creator of the `Logger` or a non-standard `LogHandler`.
+    ///
+    /// The `label` should identify the creator of the `Logger`. This can be an application, a sub-system, or even
+    /// a datatype.
+    ///
+    /// This initializer provides an escape hatch in case the global default logging backend implementation (set up
+    /// using `LoggingSystem.bootstrap` is not appropriate for this particular logger.
+    ///
+    /// - parameters:
+    ///     - label: An identifier for the creator of a `Logger`.
+    ///     - usesInlineLogLevel: If `true`, uses a log level stored on the `Logger` instead of asking the
+    ///         bootstrapped `LogHandler`. Allows more efficient log bypassing at the cost of not allowing
+    ///         dynamic log level changes.
+    ///     - factory: A closure creating non-standard `LogHandler`s.
+    public init(label: String, usesInlineLogLevel: Bool, factory: (String) -> any LogHandler) {
+        self = Logger(label: label, usesInlineLogLevel: usesInlineLogLevel, factory(label))
     }
 
     /// Construct a `Logger` given a `label` identifying the creator of the `Logger` or a non-standard `LogHandler`.
@@ -914,7 +972,25 @@ extension Logger {
     ///     - label: An identifier for the creator of a `Logger`.
     ///     - factory: A closure creating non-standard `LogHandler`s.
     public init(label: String, factory: (String, Logger.MetadataProvider?) -> any LogHandler) {
-        self = Logger(label: label, factory(label, LoggingSystem.metadataProvider))
+        self = Logger(label: label, usesInlineLogLevel: false, factory: factory)
+    }
+
+    /// Construct a `Logger` given a `label` identifying the creator of the `Logger` or a non-standard `LogHandler`.
+    ///
+    /// The `label` should identify the creator of the `Logger`. This can be an application, a sub-system, or even
+    /// a datatype.
+    ///
+    /// This initializer provides an escape hatch in case the global default logging backend implementation (set up
+    /// using `LoggingSystem.bootstrap` is not appropriate for this particular logger.
+    ///
+    /// - parameters:
+    ///     - label: An identifier for the creator of a `Logger`.
+    ///     - usesInlineLogLevel: If `true`, uses a log level stored on the `Logger` instead of asking the
+    ///         bootstrapped `LogHandler`. Allows more efficient log bypassing at the cost of not allowing
+    ///         dynamic log level changes.
+    ///     - factory: A closure creating non-standard `LogHandler`s.
+    public init(label: String, usesInlineLogLevel: Bool, factory: (String, Logger.MetadataProvider?) -> any LogHandler) {
+        self = Logger(label: label, usesInlineLogLevel: usesInlineLogLevel, factory(label, LoggingSystem.metadataProvider))
     }
 
     /// Construct a `Logger` given a `label` identifying the creator of the `Logger` and a non-standard ``Logger/MetadataProvider``.
@@ -932,6 +1008,34 @@ extension Logger {
     public init(label: String, metadataProvider: MetadataProvider) {
         self = Logger(
             label: label,
+            usesInlineLogLevel: false,
+            factory: { label in
+                var handler = LoggingSystem.factory(label, metadataProvider)
+                handler.metadataProvider = metadataProvider
+                return handler
+            }
+        )
+    }
+
+    /// Construct a `Logger` given a `label` identifying the creator of the `Logger` and a non-standard ``Logger/MetadataProvider``.
+    ///
+    /// The `label` should identify the creator of the `Logger`. This can be an application, a sub-system, or even
+    /// a datatype.
+    ///
+    /// This initializer provides an escape hatch in case the global default logging backend implementation (set up
+    /// using `LoggingSystem.bootstrap` is not appropriate for this particular logger.
+    ///
+    /// - parameters:
+    ///     - label: An identifier for the creator of a `Logger`.
+    ///     - usesInlineLogLevel: If `true`, uses a log level stored on the `Logger` instead of asking the
+    ///         bootstrapped `LogHandler`. Allows more efficient log bypassing at the cost of not allowing
+    ///         dynamic log level changes.
+    ///     - metadataProvider: The custom metadata provider this logger should invoke,
+    ///                         instead of the system wide bootstrapped one, when a log statement is about to be emitted.
+    public init(label: String, usesInlineLogLevel: Bool, metadataProvider: MetadataProvider) {
+        self = Logger(
+            label: label,
+            usesInlineLogLevel: usesInlineLogLevel,
             factory: { label in
                 var handler = LoggingSystem.factory(label, metadataProvider)
                 handler.metadataProvider = metadataProvider
@@ -942,6 +1046,7 @@ extension Logger {
 }
 
 extension Logger.Level {
+    @inlinable
     internal var naturalIntegralValue: Int {
         switch self {
         case .trace:
@@ -1605,3 +1710,28 @@ extension Logger.MetadataValue: Sendable {}
 extension Logger: Sendable {}
 extension Logger.Level: Sendable {}
 extension Logger.Message: Sendable {}
+
+// MARK: - Log level trickiness
+extension Optional<Logger.Level> {
+    @inlinable
+    internal var naturalIntegralValue: Int {
+        switch self {
+        case .trace:
+            return 0
+        case .debug:
+            return 1
+        case .info:
+            return 2
+        case .notice:
+            return 3
+        case .warning:
+            return 4
+        case .error:
+            return 5
+        case .critical:
+            return 6
+        case .none:
+            return 7
+        }
+    }
+}
diff --git a/Tests/LoggingTests/LoggingTest.swift b/Tests/LoggingTests/LoggingTest.swift
index 50447ae..67a629f 100644
--- a/Tests/LoggingTests/LoggingTest.swift
+++ b/Tests/LoggingTests/LoggingTest.swift
@@ -1283,12 +1283,17 @@ class LoggingTest: XCTestCase {
         )
     }
 
-    func testLoggerIsJustHoldingASinglePointer() {
-        let expectedSize = MemoryLayout<UnsafeRawPointer>.size
+    func testLoggerIsSmall() {
+        let expectedSize = MemoryLayout<UnsafeRawPointer>.size + MemoryLayout<Logger.Level?>.size
         XCTAssertEqual(MemoryLayout<Logger>.size, expectedSize)
     }
 
-    func testLoggerCopyOnWrite() {
+    func testOptionalLogLevelIsSmall() {
+        XCTAssertEqual(MemoryLayout<Logger.Level?>.size, MemoryLayout<Logger.Level>.size)
+        XCTAssertEqual(MemoryLayout<Logger.Level?>.stride, MemoryLayout<Logger.Level>.stride)
+    }
+
+    func testLoggerCopyOnWriteLevel() {
         var logger1 = Logger(label: "foo")
         logger1.logLevel = .error
         var logger2 = logger1
@@ -1296,6 +1301,134 @@ class LoggingTest: XCTestCase {
         XCTAssertEqual(.error, logger1.logLevel)
         XCTAssertEqual(.trace, logger2.logLevel)
     }
+
+    func testLoggerCopyOnWriteLevelInline() {
+        var logger1 = Logger(label: "foo", usesInlineLogLevel: true)
+        logger1.logLevel = .error
+        var logger2 = logger1
+        logger2.logLevel = .trace
+        XCTAssertEqual(.error, logger1.logLevel)
+        XCTAssertEqual(.trace, logger2.logLevel)
+    }
+
+    func testInlineLogLevel() {
+        // bootstrap with our test logging impl
+        let logging = TestLogging()
+        LoggingSystem.bootstrapInternal { logging.make(label: $0) }
+
+        var logger = Logger(label: "foo", usesInlineLogLevel: true)
+        logger.logLevel = .info
+        XCTAssertNotEqual(logger.logLevel, logger.handler.logLevel)
+
+        logger.trace(
+            {
+                XCTFail("trace should not be called")
+                return "trace"
+            }()
+        )
+        logger.debug(
+            {
+                XCTFail("debug should not be called")
+                return "debug"
+            }()
+        )
+        logger.info(
+            {
+                "info"
+            }()
+        )
+        logger.warning(
+            {
+                "warning"
+            }()
+        )
+        logger.error(
+            {
+                "error"
+            }()
+        )
+
+        XCTAssertEqual(3, logging.history.entries.count, "expected number of entries to match")
+        logging.history.assertNotExist(level: .trace, message: "trace")
+        logging.history.assertNotExist(level: .debug, message: "debug")
+        logging.history.assertExist(level: .info, message: "info")
+        logging.history.assertExist(level: .warning, message: "warning")
+        logging.history.assertExist(level: .error, message: "error")
+
+        // Now modify the log level up.
+        XCTAssertNotEqual(logger.logLevel, logger.handler.logLevel)
+        logger.logLevel = .warning
+        logger.trace(
+            {
+                XCTFail("trace should not be called")
+                return "trace2"
+            }()
+        )
+        logger.debug(
+            {
+                XCTFail("debug should not be called")
+                return "debug2"
+            }()
+        )
+        logger.info(
+            {
+                XCTFail("info should not be called")
+                return "info2"
+            }()
+        )
+        logger.warning(
+            {
+                "warning2"
+            }()
+        )
+        logger.error(
+            {
+                "error2"
+            }()
+        )
+
+        XCTAssertEqual(5, logging.history.entries.count, "expected number of entries to match")
+        logging.history.assertNotExist(level: .trace, message: "trace2")
+        logging.history.assertNotExist(level: .debug, message: "debug2")
+        logging.history.assertNotExist(level: .info, message: "info2")
+        logging.history.assertExist(level: .warning, message: "warning2")
+        logging.history.assertExist(level: .error, message: "error2")
+
+        // Now modify the log level down.
+        logger.logLevel = .trace
+        logger.trace(
+            {
+                return "trace3"
+            }()
+        )
+        logger.debug(
+            {
+                return "debug3"
+            }()
+        )
+        logger.info(
+            {
+                return "info3"
+            }()
+        )
+        logger.warning(
+            {
+                "warning3"
+            }()
+        )
+        logger.error(
+            {
+                "error3"
+            }()
+        )
+
+        XCTAssertEqual(10, logging.history.entries.count, "expected number of entries to match")
+        logging.history.assertExist(level: .trace, message: "trace3")
+        logging.history.assertExist(level: .debug, message: "debug3")
+        logging.history.assertExist(level: .info, message: "info3")
+        logging.history.assertExist(level: .warning, message: "warning3")
+        logging.history.assertExist(level: .error, message: "error3")
+    }
 }
 
 extension Logger {
diff --git a/Tests/LoggingTests/TestLogger.swift b/Tests/LoggingTests/TestLogger.swift
index 9dfb9d3..46c6394 100644
--- a/Tests/LoggingTests/TestLogger.swift
+++ b/Tests/LoggingTests/TestLogger.swift
@@ -64,7 +64,7 @@ internal struct TestLogHandler: LogHandler {
         self.label = label
         self.config = config
         self.recorder = recorder
-        self.logger = Logger(label: "test", StreamLogHandler.standardOutput(label: label))
+        self.logger = Logger(label: "test", usesInlineLogLevel: false, StreamLogHandler.standardOutput(label: label))
         self.logger.logLevel = .debug
         self.metadataProvider = metadataProvider
     }
@@ -73,7 +73,7 @@ internal struct TestLogHandler: LogHandler {
         self.label = label
         self.config = config
         self.recorder = recorder
-        self.logger = Logger(label: "test", StreamLogHandler.standardOutput(label: label))
+        self.logger = Logger(label: "test", usesInlineLogLevel: false, StreamLogHandler.standardOutput(label: label))
         self.logger.logLevel = .debug
         self.metadataProvider = LoggingSystem.metadataProvider
     }

This is a complete patch that makes the change. It's not perfect, but it's very close. My example above now hits a fast path that looks like this on arm64:

and        w8, w1, #0xff
sub        w8, w8, #0x1
cmp        w8, #0x7
b.lo       loc_fef8

This is four instructions, not three, but I'm completely unable to prevent the swift compiler pulling the if let into this check. I think that's ok: the cost of the extra sub is very low, and if we came up with a new strategy we could fix it later on.

[Lukasa]

This change also avoids making the structure any larger than it has to be (LogLevel and LogLevel? are the same size and have the same alignment requirements), and so minimise the risk of blowing up existentials that hold Loggers.