Skip to content

Commit

Permalink
Introduce task local logger
Browse files Browse the repository at this point in the history
# 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.
  • Loading branch information
FranzBusch committed Aug 15, 2024
1 parent db86ac7 commit 565e5fc
Show file tree
Hide file tree
Showing 6 changed files with 246 additions and 2 deletions.
9 changes: 9 additions & 0 deletions Benchmarks/.gitignore
Original file line number Diff line number Diff line change
@@ -0,0 +1,9 @@
.DS_Store
/.build
/Packages
xcuserdata/
DerivedData/
.swiftpm/configuration/registries.json
.swiftpm/xcode/package.xcworkspace/contents.xcworkspacedata
.netrc
.benchmarkBaselines/
58 changes: 58 additions & 0 deletions Benchmarks/Benchmarks/LoggingBenchmarks/Benchmarks.swift
Original file line number Diff line number Diff line change
@@ -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")
}
}
}
}
27 changes: 27 additions & 0 deletions Benchmarks/Package.swift
Original file line number Diff line number Diff line change
@@ -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")
]
),
]
)
8 changes: 6 additions & 2 deletions Sources/Logging/Logging.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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 */ {
Expand Down Expand Up @@ -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)
}
}
Expand Down
32 changes: 32 additions & 0 deletions Tests/LoggingTests/TaskLocalLoggerTests.swift
Original file line number Diff line number Diff line change
@@ -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")
}
}
}
114 changes: 114 additions & 0 deletions proposals/0002-task-local-logger.md
Original file line number Diff line number Diff line change
@@ -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.

0 comments on commit 565e5fc

Please sign in to comment.