Skip to content

Commit 13be449

Browse files
committed
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.
1 parent db86ac7 commit 13be449

File tree

6 files changed

+252
-2
lines changed

6 files changed

+252
-2
lines changed

Benchmarks/.gitignore

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,9 @@
1+
.DS_Store
2+
/.build
3+
/Packages
4+
xcuserdata/
5+
DerivedData/
6+
.swiftpm/configuration/registries.json
7+
.swiftpm/xcode/package.xcworkspace/contents.xcworkspacedata
8+
.netrc
9+
.benchmarkBaselines/
Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,58 @@
1+
//===----------------------------------------------------------------------===//
2+
//
3+
// This source file is part of the Swift Logging API open source project
4+
//
5+
// Copyright (c) 2024 Apple Inc. and the Swift Logging API project authors
6+
// Licensed under Apache License v2.0
7+
//
8+
// See LICENSE.txt for license information
9+
// See CONTRIBUTORS.txt for the list of Swift Logging API project authors
10+
//
11+
// SPDX-License-Identifier: Apache-2.0
12+
//
13+
//===----------------------------------------------------------------------===//
14+
15+
import Benchmark
16+
import Logging
17+
18+
let benchmarks = {
19+
let defaultMetrics: [BenchmarkMetric] = [
20+
.mallocCountTotal,
21+
.instructions,
22+
.wallClock,
23+
]
24+
25+
Benchmark(
26+
"NoOpLogger",
27+
configuration: Benchmark.Configuration(
28+
metrics: defaultMetrics,
29+
scalingFactor: .mega,
30+
maxDuration: .seconds(10_000_000),
31+
maxIterations: 100
32+
)
33+
) { benchmark in
34+
let logger = Logger(label: "Logger", SwiftLogNoOpLogHandler())
35+
36+
for _ in 0..<benchmark.scaledIterations.upperBound {
37+
logger.info("Log message")
38+
}
39+
}
40+
41+
Benchmark(
42+
"NoOpLogger task local",
43+
configuration: Benchmark.Configuration(
44+
metrics: defaultMetrics,
45+
scalingFactor: .mega,
46+
maxDuration: .seconds(10_000_000),
47+
maxIterations: 100
48+
)
49+
) { benchmark in
50+
let logger = Logger(label: "Logger", SwiftLogNoOpLogHandler())
51+
52+
Logger.$logger.withValue(logger) {
53+
for _ in 0..<benchmark.scaledIterations.upperBound {
54+
Logger.logger.info("Log message")
55+
}
56+
}
57+
}
58+
}

Benchmarks/Package.swift

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,27 @@
1+
// swift-tools-version: 5.8
2+
3+
import PackageDescription
4+
5+
let package = Package(
6+
name: "benchmarks",
7+
platforms: [
8+
.macOS("14")
9+
],
10+
dependencies: [
11+
.package(path: "../"),
12+
.package(url: "https://github.com/ordo-one/package-benchmark.git", from: "1.22.0"),
13+
],
14+
targets: [
15+
.executableTarget(
16+
name: "LoggingBenchmarks",
17+
dependencies: [
18+
.product(name: "Benchmark", package: "package-benchmark"),
19+
.product(name: "Logging", package: "swift-log"),
20+
],
21+
path: "Benchmarks/LoggingBenchmarks",
22+
plugins: [
23+
.plugin(name: "BenchmarkPlugin", package: "package-benchmark")
24+
]
25+
),
26+
]
27+
)

Sources/Logging/Logging.swift

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,9 @@ import WASILibc
4343
/// logger.info("Hello World!")
4444
/// ```
4545
public struct Logger {
46+
@available(macOS 10.15, *)
47+
@TaskLocal
48+
public static var logger: Logger = Logger(label: "NoOp", SwiftLogNoOpLogHandler())
4649
/// Storage class to hold the label and log handler
4750
@usableFromInline
4851
internal final class Storage: @unchecked /* and not actually */ Sendable /* but safe if only used with CoW */ {
@@ -90,8 +93,9 @@ public struct Logger {
9093
return self.handler.metadataProvider
9194
}
9295

93-
@usableFromInline
94-
internal init(label: String, _ handler: any LogHandler) {
96+
/// Creates a logger with a specific label and handler.
97+
@inlinable
98+
public init(label: String, _ handler: any LogHandler) {
9599
self._storage = Storage(label: label, handler: handler)
96100
}
97101
}
Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
//===----------------------------------------------------------------------===//
2+
//
3+
// This source file is part of the Swift Logging API open source project
4+
//
5+
// Copyright (c) 2024 Apple Inc. and the Swift Logging API project authors
6+
// Licensed under Apache License v2.0
7+
//
8+
// See LICENSE.txt for license information
9+
// See CONTRIBUTORS.txt for the list of Swift Logging API project authors
10+
//
11+
// SPDX-License-Identifier: Apache-2.0
12+
//
13+
//===----------------------------------------------------------------------===//
14+
import XCTest
15+
import Logging
16+
17+
final class TaskLocalLoggerTests: XCTestCase {
18+
func test() async {
19+
let logger = Logger(label: "TestLogger") { StreamLogHandler.standardOutput(label: $0) }
20+
21+
Logger.$logger.withValue(logger) {
22+
Logger.logger.info("Start log")
23+
var logger = Logger.logger
24+
logger[metadataKey: "MetadataKey1"] = "Value1"
25+
logger.logLevel = .trace
26+
Logger.$logger.withValue(logger) {
27+
Logger.logger.info("Log2")
28+
}
29+
Logger.logger.info("End log")
30+
}
31+
}
32+
}
33+
34+
struct MyClient {
35+
init(logger: Logger? = Logger.logger) {
36+
37+
}
38+
}
Lines changed: 114 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,114 @@
1+
# Task local logger
2+
3+
Authors: [Franz Busch](https://github.com/FranzBusch)
4+
5+
## Introduction
6+
7+
Swift Structured Concurrency provides first class capabilities to propagate data
8+
down the task tree via task locals. This provides an amazing opportunity for
9+
structured logging.
10+
11+
## Motivation
12+
13+
Structured logging is a powerful tool to build logging message that contain
14+
contextual metadata. This metadata is often build up over time by adding more to
15+
it the more context is available. A common example for this are request ids.
16+
Once a request id is extracted it is added to the loggers metadata and from that
17+
point onwards all log messages contain the request id. This improves
18+
observability and debuggability. The current pattern to do this in `swift-log`
19+
looks like this:
20+
21+
```swift
22+
func handleRequest(_ request: Request, logger: Logger) async throws {
23+
// Extract the request id to the metadata of the logger
24+
var logger = logger
25+
logger[metadataKey: "request.id"] = "\(request.id)"
26+
27+
// Importantly we have to pass the new logger forward since it contains the request id
28+
try await sendResponse(logger: logger)
29+
}
30+
```
31+
32+
This works but it causes significant overhead due to passing of the logger
33+
through all methods in the call stack. Furthermore, sometimes it is impossible to pass
34+
a logger to some methods if those are protocol requirements like `init(from: Decoder)`.
35+
36+
Swift Structured Concurrency introduced the concept of task locals which
37+
propagate down the structured task tree. This fits perfectly with how we expect
38+
logging metadata to accumulate and provide more information the further down the
39+
task tree we get.
40+
41+
## Proposed solution
42+
43+
I propose to add a new task local definition to `Logger`. Adding this task local
44+
inside the `Logging` module provides the one canonical task local that all other
45+
packages in the ecosystem can use.
46+
47+
```swift
48+
extension Logger {
49+
/// The task local logger.
50+
///
51+
/// It is recommended to use this logger in applications and libraries that use Swift Concurrency
52+
/// instead of passing around loggers manually.
53+
@TaskLocal
54+
public static var logger: Logger
55+
}
56+
```
57+
58+
The default value for this logger is going to be a `SwiftLogNoOpLogHandler()`.
59+
60+
Applications can then set the task local logger similar to how they currently bootstrap
61+
the logging backend. If no library in the proccess is creating its own logger it is even possible
62+
to not use the normal bootstrapping methods at all and fully rely on structured concurrency for
63+
propagating the logger and its metadata.
64+
65+
```swift
66+
static func main() async throws {
67+
let logger = Logger(label: "Logger") { StreamLogHandler.standardOutput(label: $0)}
68+
69+
Logger.$logger.withValue(logger) {
70+
// Run your application code
71+
try await application.run()
72+
}
73+
}
74+
```
75+
76+
Places that want to log can then just access the task local and produce a log message.
77+
78+
```swift
79+
Logger.logger.info("My log message")
80+
```
81+
82+
Adding additional metadata to the task local logger is as easy as updating the logger
83+
and binding the task local value again.
84+
85+
```swift
86+
Logger.$logger.withValue(logger) {
87+
Logger.logger.info("First log")
88+
89+
var logger = Logger.logger
90+
logger[metadataKey: "MetadataKey1"] = "Value1"
91+
Logger.$logger.withValue(logger) {
92+
Logger.logger.info("Second log")
93+
}
94+
95+
Logger.logger.info("Third log")
96+
}
97+
```
98+
99+
Running the above code will produce the following output:
100+
101+
```
102+
First log
103+
MetadataKey1=Value1 Second log
104+
Third log
105+
```
106+
107+
## Alternatives considered
108+
109+
### Provide static log methods
110+
111+
Instead of going through the task local `Logger.logger` to emit log messages we
112+
could add new static log methods like `Logger.log()` or `Logger.info()` that
113+
access the task local internally. This is soemthing that we can do in the future
114+
as an enhancement but isn't required initially.

0 commit comments

Comments
 (0)