IOLocal propagation for unsafe access

[armanbilge]

Still needs quite a bit of work, but wanted to sketch the basic idea.

Goal: to expose a fiber's IOLocals as ThreadLocals within a side-effecting block, so that they can be accessed and modified in unsafe land.

Motivation: basically telemetry Java interop.

• Unable to start span as current otel4s#202
• Context switching between Natchez and backend instrumentation natchez#706

Constraints: to do this as safely as possible 😅

[armanbilge]

Bikesheddable configuration for opting-in. So the rest of us don't have to pay the penalty 😇

[rossabaker]

Is this specifically "tracing", even if that's the most obvious use case?

[armanbilge]

Oh woops, this was a very lazy copy-pasta. I copied it from the system properties we use to configure fiber tracing. We should rename it anyway, dumpLocals is not quite right I think 😅

[kevin-lee]

What about cats.effect.localContextPropagation similar to Monix's monix.environment.localContextPropagation?

[armanbilge]

Thanks, I liked that! I went with cats.effect.ioLocalPropagation.

[armanbilge]

I did this just for delay, but I guess blocking and interruptible would want it too.

[armanbilge]

Ok, so I was extremely lazy with implementing this thing. But the main idea of this wrapper API is that it should only give the user access to IOLocals that they know about i.e. they should not able to clear out other locals that happen to be present.

[armanbilge]

We can even go in the opposite direction for IO#unsafeRun* 😁

It's less clear if/how to do this for fibers started in a Dispatcher, since they should be inheriting locals from the fiber backing the Dispatcher.

[rossabaker]

Interesting. I will try to give a snapshot of this a shot over on the otel4s side.

[rossabaker]

Is this specifically "tracing", even if that's the most obvious use case?

[armanbilge]

This is not good. To avoid this we'll either have to replicate it at both the cats.effect and cats.effect.unsafe levels, or move the thread-local IOLocals accessors into cats.effect.

[kevin-lee]

I apologise for jumping in and asking this question but, can it be used as an alternative to Local from Monix?
I need it specifically for logging, much like what's explained in the post, "Better logging with Monix 3, part 1: MDC" but with cats-effect 3. This has been a blocker for my company's transition from cats-effect 2 with Monix to cats-effect 3. The issue has become increasingly critical as more and more libraries cease to support cats-effect 2, choosing to support only cats-effect 3 instead. So it would be great to see if there's any upcoming solution.

[armanbilge]

@kevin-lee no problem! At a glance, yes, this does look like an alternative/replacement to that Monix feature. Perhaps @alexandru can confirm :)

[kevin-lee]

@kevin-lee no problem! At a glance, yes, this does look like an alternative/replacement to that Monix feature. Perhaps @alexandru can confirm :)

@armanbilge Thank you. That's great!
It looks quite similar and looks like it can be used for the same purpose, but I can see the methods in IOLocals taking IOLocal[A] whereas the methods in Local from Monix don't. So I'm wondering if it can be used for the same purpose. I need to use it in a logging library like Logback, which doesn't have IO or any effect.
Yeah, it would be nice if @alexandru can confirm this.

[armanbilge]

but I can see the methods in IOLocals taking IOLocal[A] whereas the methods in Local from Monix don't. So I'm wondering if it can be used for the same purpose. I need to use it in a logging library like Logback, which doesn't have IO or any effect.

@kevin-lee the IOLocal[A] is just the "key". Once you have that key (and you can build one unsafely outside of the effect) then you don't need any more effects to read and write it.

For an example integration, see this PR which implements a Java SPI using this IOLocals API.

• Experimental IOLocalContextStorage otel4s#214

[kevin-lee]

@kevin-lee the IOLocal[A] is just the "key". Once you have that key (and you can build one unsafely outside of the effect) then you don't need any more effects to read and write it.

For an example integration, see this PR which implements a Java SPI using this IOLocals API.

• Experimental IOLocalContextStorage otel4s#214

@armanbilge Oh... got it. It looks very promising then. Thank you!

[djspiewak]

Finished benchmarking. @armanbilge let's see your armchair performance reasoning explain this result. I'm at a loss.

Before

[info] Benchmark                                             (cpuTokens)   (size)   Mode  Cnt      Score     Error    Units
[info] DeepBindBenchmark.async                                       N/A    10000  thrpt   10   2786.655 ±   3.536    ops/s
[info] DeepBindBenchmark.delay                                       N/A    10000  thrpt   10   9613.496 ± 234.106    ops/s
[info] DeepBindBenchmark.pure                                        N/A    10000  thrpt   10  11168.222 ± 465.787    ops/s
[info] MapCallsBenchmark.batch120                                    N/A      N/A  thrpt   10    338.430 ±   3.116    ops/s
[info] MapCallsBenchmark.batch30                                     N/A      N/A  thrpt   10     86.709 ±   0.563    ops/s
[info] MapCallsBenchmark.one                                         N/A      N/A  thrpt   10      2.944 ±   0.017    ops/s
[info] MapStreamBenchmark.batch120                                   N/A      N/A  thrpt   10   5561.435 ±  14.217    ops/s
[info] MapStreamBenchmark.batch30                                    N/A      N/A  thrpt   10   2524.134 ±   2.286    ops/s
[info] MapStreamBenchmark.one                                        N/A      N/A  thrpt   10   3233.048 ±   4.027    ops/s
[info] ParallelBenchmark.parTraverse                               10000     1000  thrpt   10    886.610 ±   0.865    ops/s
[info] ParallelBenchmark.traverse                                  10000     1000  thrpt   10     70.460 ±   0.067    ops/s
[info] ShallowBindBenchmark.async                                    N/A    10000  thrpt   10   2031.729 ±   3.593    ops/s
[info] ShallowBindBenchmark.delay                                    N/A    10000  thrpt   10   9778.303 ±  62.426    ops/s
[info] ShallowBindBenchmark.pure                                     N/A    10000  thrpt   10  11973.770 ±  32.027    ops/s
[info] WorkStealingBenchmark.alloc                                   N/A  1000000  thrpt   10     14.152 ±   0.090  ops/min
[info] WorkStealingBenchmark.manyThreadsSchedulingBenchmark          N/A  1000000  thrpt   10     31.868 ±   5.072  ops/min
[info] WorkStealingBenchmark.runnableScheduling                      N/A  1000000  thrpt   10    870.238 ±   3.475  ops/min
[info] WorkStealingBenchmark.runnableSchedulingScalaGlobal           N/A  1000000  thrpt   10   2245.542 ±   7.645  ops/min
[info] WorkStealingBenchmark.scheduling                              N/A  1000000  thrpt   10     29.631 ±   2.092  ops/min

After

[info] Benchmark                                             (cpuTokens)   (size)   Mode  Cnt      Score     Error    Units
[info] DeepBindBenchmark.async                                       N/A    10000  thrpt   10   2814.793 ±   6.982    ops/s
[info] DeepBindBenchmark.delay                                       N/A    10000  thrpt   10   9589.880 ±  27.294    ops/s
[info] DeepBindBenchmark.pure                                        N/A    10000  thrpt   10  11377.434 ±  37.080    ops/s
[info] MapCallsBenchmark.batch120                                    N/A      N/A  thrpt   10    336.483 ±   2.160    ops/s
[info] MapCallsBenchmark.batch30                                     N/A      N/A  thrpt   10     85.833 ±   0.404    ops/s
[info] MapCallsBenchmark.one                                         N/A      N/A  thrpt   10      2.925 ±   0.007    ops/s
[info] MapStreamBenchmark.batch120                                   N/A      N/A  thrpt   10   5684.510 ±   8.954    ops/s
[info] MapStreamBenchmark.batch30                                    N/A      N/A  thrpt   10   2522.568 ±   7.291    ops/s
[info] MapStreamBenchmark.one                                        N/A      N/A  thrpt   10   3284.312 ±   2.895    ops/s
[info] ParallelBenchmark.parTraverse                               10000     1000  thrpt   10    891.486 ±   0.846    ops/s
[info] ParallelBenchmark.traverse                                  10000     1000  thrpt   10     70.303 ±   0.060    ops/s
[info] ShallowBindBenchmark.async                                    N/A    10000  thrpt   10   1985.424 ±   2.771    ops/s
[info] ShallowBindBenchmark.delay                                    N/A    10000  thrpt   10   9655.691 ± 182.608    ops/s
[info] ShallowBindBenchmark.pure                                     N/A    10000  thrpt   10  10075.531 ±  22.884    ops/s
[info] WorkStealingBenchmark.alloc                                   N/A  1000000  thrpt   10     14.044 ±   0.078  ops/min
[info] WorkStealingBenchmark.manyThreadsSchedulingBenchmark          N/A  1000000  thrpt   10     48.611 ±   1.642  ops/min
[info] WorkStealingBenchmark.runnableScheduling                      N/A  1000000  thrpt   10   2987.595 ±   5.299  ops/min
[info] WorkStealingBenchmark.runnableSchedulingScalaGlobal           N/A  1000000  thrpt   10   2249.480 ±  48.568  ops/min
[info] WorkStealingBenchmark.scheduling                              N/A  1000000  thrpt   10     52.240 ±   3.133  ops/min

[djspiewak]

Finally scraped together the time needed to shave a few dev environment yaks and test this PR with propagation enabled. The performance hit is about 25% on microbenchmarks involving delay or map, and (as expected) ~0% (within margin of error) on everything else. The bizarre acceleration of WSTP scheduling on non-parTraverse benchmarks remains consistent (notably, parTraverse itself was around 0%).

So I think the summary of this PR, from a performance standpoint, is the following:

• When disabled, no meaningful impact.
  • Does seem to spookily effect the WSTP microbenchmarks in a way which resets the baseline
• When enabled, 25% worse on delay/map microbenchmarks
  • No effect within margin of error on scheduling or traverse-y benchmarks
  • WSTP microbenchmark baseline effect remains and is of the same magnitude

So enabling this is analogous to enabling cached tracing, but of course would be cumulative with that flag as well, so technically turning both of them on would bop your microbenchmark scores by something like 55%. It's very unclear whether this type of performance impact matters in practice. We would probably need to run some end-to-end scale tests with propagation enabled in order to see.

Given that this is default-off and the impact when disabled is zero (outside of the still bizarre WSTP microbenchmark mirages), I'm comfortable merging this as-is and we can do some further testing. We should also probably document (or at least, write a ticket to document) the performance effects so it doesn't surprise anyone.

[armanbilge]

I added some documentation.

The performance hit is about 25% on microbenchmarks involving delay or map, and (as expected) ~0% (within margin of error) on everything else.

Discussed on Discord, but to clarify there is no reason to expect that delay or map should be impacted differently, because the propagation logic runs when the fiber is scheduled/descheduled, not for specific ops. (Although note that my initial implementation ran the propagation logic ran before/after delay blocks, in which case the performance discrepancy would be expected.)

[henricook]

@djspiewak Please forgive my impetuousness - do you have a guesstimate of when this might be going in please?

[henricook]

Oh-em-gee. Exciting.

[djspiewak]

@armanbilge Conflict resolution time!