apple / swift-log

A Logging API for Swift
https://apple.github.io/swift-log/
Apache License 2.0
3.48k stars 284 forks source link

Introduce task local logger #315

Open FranzBusch opened 1 month ago

FranzBusch commented 1 month ago

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 │
╘══════════════════════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╧═════════╛