From 565e5fc9e626c482084cf2f5e1d09abe7a57ef31 Mon Sep 17 00:00:00 2001
From: Franz Busch <f.busch@apple.com>
Date: Thu, 8 Aug 2024 13:48:44 +0100
Subject: [PATCH] Introduce task local logger

# Motivation

Structured logging and structured concurrency are a match made in heaven. Using task locals for loggers enables easier passing of metadata for log messages and removes the cumbersome passing around of loggers.

# Modification

This PR adds a proposal, the implementation and benchmarks for a task local logger.

# Result

Using a task local for logging makes it incredible ergonomic to carry around metadata. To be transparent the benchmarks show that this is around 20x slower than a bare no-op log. A no-op log takes around 2ns whereas a task local logger no-op log takes around 40ns. 95% of that time is spent in accessing the task local since that is missing some `@inlinable` in the runtime and goes through the C interface. Instruction wise it is 20 vs 290 instructions.

Now I still propose that we go forward with this since the ergonomics far outweigh the performance initially. Furthermore, this acts as a great forcing function for performance improvements in the runtime since logging is often done in hot paths.
---
 Benchmarks/.gitignore                         |   9 ++
 .../LoggingBenchmarks/Benchmarks.swift        |  58 +++++++++
 Benchmarks/Package.swift                      |  27 +++++
 Sources/Logging/Logging.swift                 |   8 +-
 Tests/LoggingTests/TaskLocalLoggerTests.swift |  32 +++++
 proposals/0002-task-local-logger.md           | 114 ++++++++++++++++++
 6 files changed, 246 insertions(+), 2 deletions(-)
 create mode 100644 Benchmarks/.gitignore
 create mode 100644 Benchmarks/Benchmarks/LoggingBenchmarks/Benchmarks.swift
 create mode 100644 Benchmarks/Package.swift
 create mode 100644 Tests/LoggingTests/TaskLocalLoggerTests.swift
 create mode 100644 proposals/0002-task-local-logger.md

diff --git a/Benchmarks/.gitignore b/Benchmarks/.gitignore
new file mode 100644
index 00000000..2517bcdf
--- /dev/null
+++ b/Benchmarks/.gitignore
@@ -0,0 +1,9 @@
+.DS_Store
+/.build
+/Packages
+xcuserdata/
+DerivedData/
+.swiftpm/configuration/registries.json
+.swiftpm/xcode/package.xcworkspace/contents.xcworkspacedata
+.netrc
+.benchmarkBaselines/
\ No newline at end of file
diff --git a/Benchmarks/Benchmarks/LoggingBenchmarks/Benchmarks.swift b/Benchmarks/Benchmarks/LoggingBenchmarks/Benchmarks.swift
new file mode 100644
index 00000000..cd47cf9d
--- /dev/null
+++ b/Benchmarks/Benchmarks/LoggingBenchmarks/Benchmarks.swift
@@ -0,0 +1,58 @@
+//===----------------------------------------------------------------------===//
+//
+// This source file is part of the Swift Logging API open source project
+//
+// Copyright (c) 2024 Apple Inc. and the Swift Logging API project authors
+// Licensed under Apache License v2.0
+//
+// See LICENSE.txt for license information
+// See CONTRIBUTORS.txt for the list of Swift Logging API project authors
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+//===----------------------------------------------------------------------===//
+
+import Benchmark
+import Logging
+
+let benchmarks = {
+    let defaultMetrics: [BenchmarkMetric] = [
+        .mallocCountTotal,
+        .instructions,
+        .wallClock,
+    ]
+
+    Benchmark(
+        "NoOpLogger",
+        configuration: Benchmark.Configuration(
+            metrics: defaultMetrics,
+            scalingFactor: .mega,
+            maxDuration: .seconds(10_000_000),
+            maxIterations: 100
+        )
+    ) { benchmark in
+        let logger = Logger(label: "Logger", SwiftLogNoOpLogHandler())
+
+        for _ in 0..<benchmark.scaledIterations.upperBound {
+            logger.info("Log message")
+        }
+    }
+
+    Benchmark(
+        "NoOpLogger task local",
+        configuration:  Benchmark.Configuration(
+            metrics: defaultMetrics,
+            scalingFactor: .mega,
+            maxDuration: .seconds(10_000_000),
+            maxIterations: 100
+        )
+    ) { benchmark in
+        let logger = Logger(label: "Logger", SwiftLogNoOpLogHandler())
+
+        Logger.$logger.withValue(logger) {
+            for _ in 0..<benchmark.scaledIterations.upperBound {
+                Logger.logger.info("Log message")
+            }
+        }
+    }
+}
diff --git a/Benchmarks/Package.swift b/Benchmarks/Package.swift
new file mode 100644
index 00000000..d72a47ef
--- /dev/null
+++ b/Benchmarks/Package.swift
@@ -0,0 +1,27 @@
+// swift-tools-version: 5.8
+
+import PackageDescription
+
+let package = Package(
+    name: "benchmarks",
+    platforms: [
+        .macOS("14")
+    ],
+    dependencies: [
+        .package(path: "../"),
+        .package(url: "https://github.com/ordo-one/package-benchmark.git", from: "1.22.0"),
+    ],
+    targets: [
+        .executableTarget(
+            name: "LoggingBenchmarks",
+            dependencies: [
+                .product(name: "Benchmark", package: "package-benchmark"),
+                .product(name: "Logging", package: "swift-log"),
+            ],
+            path: "Benchmarks/LoggingBenchmarks",
+            plugins: [
+                .plugin(name: "BenchmarkPlugin", package: "package-benchmark")
+            ]
+        ),
+    ]
+)
diff --git a/Sources/Logging/Logging.swift b/Sources/Logging/Logging.swift
index 04ef0b1a..f63c987d 100644
--- a/Sources/Logging/Logging.swift
+++ b/Sources/Logging/Logging.swift
@@ -43,6 +43,9 @@ import WASILibc
 /// logger.info("Hello World!")
 /// ```
 public struct Logger {
+    @available(macOS 10.15, *)
+    @TaskLocal
+    public static var logger: Logger = Logger(label: "NoOp")
     /// Storage class to hold the label and log handler
     @usableFromInline
     internal final class Storage: @unchecked /* and not actually */ Sendable /* but safe if only used with CoW */ {
@@ -90,8 +93,9 @@ public struct Logger {
         return self.handler.metadataProvider
     }
 
-    @usableFromInline
-    internal init(label: String, _ handler: any LogHandler) {
+    /// Creates a logger with a specific label and handler.
+    @inlinable
+    public init(label: String, _ handler: any LogHandler) {
         self._storage = Storage(label: label, handler: handler)
     }
 }
diff --git a/Tests/LoggingTests/TaskLocalLoggerTests.swift b/Tests/LoggingTests/TaskLocalLoggerTests.swift
new file mode 100644
index 00000000..f4eb7ce9
--- /dev/null
+++ b/Tests/LoggingTests/TaskLocalLoggerTests.swift
@@ -0,0 +1,32 @@
+//===----------------------------------------------------------------------===//
+//
+// This source file is part of the Swift Logging API open source project
+//
+// Copyright (c) 2024 Apple Inc. and the Swift Logging API project authors
+// Licensed under Apache License v2.0
+//
+// See LICENSE.txt for license information
+// See CONTRIBUTORS.txt for the list of Swift Logging API project authors
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+//===----------------------------------------------------------------------===//
+import XCTest
+import Logging
+
+final class TaskLocalLoggerTests: XCTestCase {
+    func test() async {
+        let logger = Logger(label: "TestLogger") { StreamLogHandler.standardOutput(label: $0) }
+
+        Logger.$logger.withValue(logger) {
+            Logger.logger.info("Start log")
+            var logger = Logger.logger
+            logger[metadataKey: "MetadataKey1"] = "Value1"
+            logger.logLevel = .trace
+            Logger.$logger.withValue(logger) {
+                Logger.logger.info("Log2")
+            }
+            Logger.logger.info("End log")
+        }
+    }
+}
diff --git a/proposals/0002-task-local-logger.md b/proposals/0002-task-local-logger.md
new file mode 100644
index 00000000..a71a49e1
--- /dev/null
+++ b/proposals/0002-task-local-logger.md
@@ -0,0 +1,114 @@
+# Task local logger
+
+Authors: [Franz Busch](https://github.com/FranzBusch)
+
+## Introduction
+
+Swift Structured Concurrency provides first class capabilities to propagate data
+down the task tree via task locals. This provides an amazing opportunity for
+structured logging.
+
+## Motivation
+
+Structured logging is a powerful tool to build logging message that contain
+contextual metadata. This metadata is often build up over time by adding more to
+it the more context is available. A common example for this are request ids.
+Once a request id is extracted it is added to the loggers metadata and from that
+point onwards all log messages contain the request id. This improves
+observability and debuggability. The current pattern to do this in `swift-log`
+looks like this:
+
+```swift
+func handleRequest(_ request: Request, logger: Logger) async throws {
+    // Extract the request id to the metadata of the logger
+    var logger = logger
+    logger[metadataKey: "request.id"] = "\(request.id)"
+
+    // Importantly we have to pass the new logger forward since it contains the request id
+    try await sendResponse(logger: logger)
+}
+```
+
+This works but it causes significant overhead due to passing of the logger
+through all methods in the call stack. Furthermore, sometimes it is impossible to pass
+a logger to some methods if those are protocol requirements like `init(from: Decoder)`.
+
+Swift Structured Concurrency introduced the concept of task locals which
+propagate down the structured task tree. This fits perfectly with how we expect
+logging metadata to accumulate and provide more information the further down the 
+task tree we get. 
+
+## Proposed solution
+
+I propose to add a new task local definition to `Logger`. Adding this task local
+inside the `Logging` module provides the one canonical task local that all other
+packages in the ecosystem can use.
+
+```swift
+extension Logger {
+    /// The task local logger.
+    ///
+    /// It is recommended to use this logger in applications and libraries that use Swift Concurrency
+    /// instead of passing around loggers manually.
+    @TaskLocal
+    public static var logger: Logger
+}
+```
+
+The default value for this logger is going to be a `SwiftLogNoOpLogHandler()`.
+
+Applications can then set the task local logger similar to how they currently bootstrap
+the logging backend. If no library in the proccess is creating its own logger it is even possible
+to not use the normal bootstrapping methods at all and fully rely on structured concurrency for
+propagating the logger and its metadata.
+
+```swift
+static func main() async throws {
+    let logger = Logger(label: "Logger") { StreamLogHandler.standardOutput(label: $0)}
+
+    Logger.$logger.withValue(logger) {
+        // Run your application code
+        try await application.run()
+    }
+}
+```
+
+Places that want to log can then just access the task local and produce a log message.
+
+```swift
+Logger.logger.info("My log message")
+```
+
+Adding additional metadata to the task local logger is as easy as updating the logger
+and binding the task local value again.
+
+```swift
+Logger.$logger.withValue(logger) {
+    Logger.logger.info("First log")
+
+    var logger = Logger.logger
+    logger[metadataKey: "MetadataKey1"] = "Value1"
+    Logger.$logger.withValue(logger) {
+        Logger.logger.info("Second log")
+    }
+
+    Logger.logger.info("Third log")
+}
+```
+
+Running the above code will produce the following output:
+
+```
+First log
+MetadataKey1=Value1 Second log
+Third log
+```
+
+## Alternatives considered
+
+### Provide static log methods
+
+Instead of going through the task local `Logger.logger` to emit log messages we
+could add new static log methods like `Logger.log()` or `Logger.info()` that
+access the task local internally. This is soemthing that we can do in the future
+as an enhancement but isn't required initially.