apple
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.
NoOpLogger
╒══════════════════════════╤═════════╤═════════╤═════════╤═════════╤═════════╤═════════╤═════════╤═════════╕
│ Metric │ p0 │ p25 │ p50 │ p75 │ p90 │ p99 │ p100 │ Samples │
╞══════════════════════════╪═════════╪═════════╪═════════╪═════════╪═════════╪═════════╪═════════╪═════════╡
│ Instructions * │ 20 │ 20 │ 20 │ 20 │ 20 │ 20 │ 20 │ 100 │
├──────────────────────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Malloc (total) * │ 0 │ 0 │ 0 │ 0 │ 0 │ 0 │ 0 │ 100 │
├──────────────────────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Time (wall clock) (ns) * │ 2 │ 2 │ 2 │ 2 │ 2 │ 2 │ 2 │ 100 │
╘══════════════════════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╛
NoOpLogger task local
╒══════════════════════════╤═════════╤═════════╤═════════╤═════════╤═════════╤═════════╤═════════╤═════════╕
│ Metric │ p0 │ p25 │ p50 │ p75 │ p90 │ p99 │ p100 │ Samples │
╞══════════════════════════╪═════════╪═════════╪═════════╪═════════╪═════════╪═════════╪═════════╪═════════╡
│ Instructions * │ 289 │ 289 │ 289 │ 289 │ 289 │ 290 │ 290 │ 100 │
├──────────────────────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Malloc (total) * │ 0 │ 0 │ 0 │ 0 │ 0 │ 0 │ 0 │ 100 │
├──────────────────────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Time (wall clock) (ns) * │ 33 │ 39 │ 39 │ 40 │ 40 │ 42 │ 42 │ 100 │
╘══════════════════════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╛
Using task locals for loggers enables easier passing of metadata for log messages and removes the cumbersome passing around of loggers.
What does a task-local logger enable that's not yet possible using metadata providers? For example, a metadata provider can already be used to look up a task-local and turn it into metadata transparently.
Removes the cumbersome passing around of loggers.
What other use cases are there for passing around loggers? I believe I saw it being used to pass around the minimum log level.
What does a task-local logger enable that's not yet possible using metadata providers? For example, a metadata provider can already be used to look up a task-local and turn it into metadata transparently.
From experience with metadata providers now I think they are just too unergonomic in both discoverability but also usability. As an application author to correctly setup metadata providers you need to both know what library (often transitive) in your dependencies defines a metadata provider and then remember to correctly set it up.
This IMO goes against the goals that we want to have with observability in Swift which is "works out of the box". If I recall correctly a big reason for introducing metadata providers was that we wanted our tracing backends to add logging metadata but since they don't have the logger available we had to invert control and let the user stitch the two pieces together.
Nowdays, with package traits and the potential task local logger here I think we can provide a way better experience where tracing backends can do this automatically while offering to disable it when needed. This brings us back to the "works out of the box" that we aim for.
What other use cases are there for passing around loggers? I believe I saw it being used to pass around the minimum log level.
Log levels really should only be set by the application that creates the logger. The big problem that I try to solve here is that the structured call tree works great but our loggers are not automatically included in it. So what I see happening all over the place is that either the logger has almost no metadata or the wrong logger is used since it is passed in through an init. I personally strongly believe that we should offer a task local logger since it is so essential for our debugging capabilities to have the right metadata attached to it.
What other use cases are there for passing around loggers? Log levels really should only be set by the application that creates the logger.
Disagree. I very frequently want to lower (e.g. to debug) the level of a particular tree when I know the problem is happening in a certain corner. Occasionally I also raise the level (e.g. to warning) when a library keeps spewing out unimportant stuff in info or notice.
The other big use case is to provide a Logger with an alternative backend for sub operations. One thing I've done successfully is this:
func someFunctionality(logger realLogger: Logger) async throws {
[...]
let inMemoryLogAccumulator = InMemoryLogAccumulator()
var inMemoryLogger = Logger(label: "foo", factory: { _ in inMemoryLogAccumulator })
inMemoryLogger.logLevel = .trace
do {
try await codeThatHasAnnoyingBugs(logger: inMemoryLogger)
} catch SomeSpecificWeirdError {
// A reproduction of this one weird error that I can't reproduce outside of prod happened, let's emit all the logs
// into our real logging system.
var realLogger = realLogger
realLogger.logLevel = .trace
realLogger[metadataKey: "weird-error-reproduction"] = "true"
inMemoryLogAccumulator.emitAllLogs(info: realLogger)
throw error
}
[...]
}
That way I get all the .trace logs from codeThatHasAnnoyingBugs() but only if we hit SomeSpecificWeirdError. In all other cases, it's silenced. This is really powerful, exactly like tail-sampling, implemented super easily.
And I get to select it easily with weird-error-reproduction = "true" GROUP BY request-id or similar (assuming that something else emitted request-id into the metadata).
