Use the thread_local crate allowing multiple registries

[jeromegn]

Motivation

Fixes part of #898 where creating multiple registries made them fight over the thread_local-stored span stacks.

Solution

Use the thread_local crate which has a tighter scope.

I believe @hawkw has a test that fails without this PR.

[hawkw]

I believe @hawkw has a test that fails without this PR.

I think adding a test like this should fail on master but pass after making this change. Can you add a test and confirm that this is the case? Thanks!

[jeromegn]

I think adding a test like this should fail on master but pass after making this change. Can you add a test and confirm that this is the case? Thanks!

Thanks, that does fail on master and work with this branch. Pushed it up.

[hawkw]

Can we get before/after benchmarks with this? It would be nice to know how big the performance difference between the ThreadLocal crate and std::thread_local!.

[jeromegn]

Here you go:

     Running /home/jerome/src/github.com/superfly/tracing/target/release/deps/filter-de3132ff29c30a19
Gnuplot not found, using plotters backend
static/baseline_single_threaded
                        time:   [66.260 ns 66.630 ns 67.089 ns]
                        change: [+14.956% +15.955% +17.124%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 4 outliers among 100 measurements (4.00%)
  4 (4.00%) high severe
static/single_threaded  time:   [34.126 ns 34.206 ns 34.306 ns]
                        change: [+9.4442% +10.350% +11.140%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 8 outliers among 100 measurements (8.00%)
  4 (4.00%) high mild
  4 (4.00%) high severe
static/enabled_one      time:   [16.463 ns 16.519 ns 16.587 ns]
                        change: [+11.078% +13.119% +15.092%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 7 outliers among 100 measurements (7.00%)
  4 (4.00%) high mild
  3 (3.00%) high severe
static/enabled_many     time:   [16.157 ns 16.196 ns 16.241 ns]
                        change: [+7.0105% +7.4694% +7.8780%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 3 outliers among 100 measurements (3.00%)
  2 (2.00%) high mild
  1 (1.00%) high severe
static/disabled_level_one
                        time:   [1.3849 ns 1.3890 ns 1.3952 ns]
                        change: [+3.6392% +4.1954% +4.8170%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 10 outliers among 100 measurements (10.00%)
  1 (1.00%) low mild
  6 (6.00%) high mild
  3 (3.00%) high severe
static/disabled_level_many
                        time:   [793.66 ps 795.55 ps 798.09 ps]
                        change: [-40.702% -40.418% -40.112%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 6 outliers among 100 measurements (6.00%)
  3 (3.00%) high mild
  3 (3.00%) high severe
static/disabled_one     time:   [817.79 ps 819.18 ps 820.92 ps]
                        change: [-37.605% -37.064% -36.674%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  2 (2.00%) high mild
  2 (2.00%) high severe
static/disabled_many    time:   [817.00 ps 818.00 ps 819.22 ps]
                        change: [-39.445% -39.219% -39.014%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 6 outliers among 100 measurements (6.00%)
  5 (5.00%) high mild
  1 (1.00%) high severe
static/baseline_multithreaded
                        time:   [8.6921 us 8.7837 us 8.9105 us]
                        change: [+2.5397% +4.9010% +7.1759%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 11 outliers among 100 measurements (11.00%)
  1 (1.00%) low mild
  7 (7.00%) high mild
  3 (3.00%) high severe
static/multithreaded    time:   [8.7168 us 8.8003 us 8.9002 us]
                        change: [-5.0503% -2.7737% -0.4553%] (p = 0.02 < 0.05)
                        Change within noise threshold.
Found 8 outliers among 100 measurements (8.00%)
  4 (4.00%) high mild
  4 (4.00%) high severe

dynamic/baseline_single_threaded
                        time:   [141.11 ns 141.52 ns 142.00 ns]
                        change: [-2.2274% -1.7163% -1.2214%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 5 outliers among 100 measurements (5.00%)
  2 (2.00%) high mild
  3 (3.00%) high severe
dynamic/single_threaded time:   [440.87 ns 442.39 ns 444.34 ns]
                        change: [+2.2807% +3.0485% +3.7310%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 6 outliers among 100 measurements (6.00%)
  4 (4.00%) high mild
  2 (2.00%) high severe
dynamic/baseline_multithreaded
                        time:   [8.7474 us 8.8613 us 9.0030 us]
                        change: [-1.5668% +1.6539% +4.6327%] (p = 0.31 > 0.05)
                        No change in performance detected.
Found 7 outliers among 100 measurements (7.00%)
  2 (2.00%) high mild
  5 (5.00%) high severe
dynamic/multithreaded   time:   [12.736 us 12.941 us 13.231 us]
                        change: [-0.0396% +2.1426% +4.4522%] (p = 0.07 > 0.05)
                        No change in performance detected.
Found 8 outliers among 100 measurements (8.00%)
  1 (1.00%) low mild
  4 (4.00%) high mild
  3 (3.00%) high severe

mixed/disabled          time:   [36.146 ns 36.264 ns 36.404 ns]
                        change: [-2.4297% -1.8673% -1.3176%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) high mild
mixed/disabled_by_level time:   [11.344 ns 11.373 ns 11.408 ns]
                        change: [+3.8966% +4.5878% +5.3008%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 9 outliers among 100 measurements (9.00%)
  4 (4.00%) high mild
  5 (5.00%) high severe

     Running /home/jerome/src/github.com/superfly/tracing/target/release/deps/filter_log-31c9d1c8beaba194
Gnuplot not found, using plotters backend
log/static/baseline_single_threaded
                        time:   [253.26 ns 253.88 ns 254.62 ns]
                        change: [+2.1135% +2.7167% +3.3516%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 32 outliers among 100 measurements (32.00%)
  9 (9.00%) low severe
  7 (7.00%) low mild
  5 (5.00%) high mild
  11 (11.00%) high severe
log/static/single_threaded
                        time:   [256.36 ns 257.06 ns 258.03 ns]
                        change: [-6.7988% -4.8181% -2.6649%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 7 outliers among 100 measurements (7.00%)
  2 (2.00%) high mild
  5 (5.00%) high severe
log/static/enabled_one  time:   [89.348 ns 89.578 ns 89.872 ns]
                        change: [-8.6556% -8.1713% -7.7433%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 18 outliers among 100 measurements (18.00%)
  4 (4.00%) high mild
  14 (14.00%) high severe
log/static/enabled_many time:   [89.080 ns 89.384 ns 89.770 ns]
                        change: [-9.0067% -8.5183% -7.9943%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 16 outliers among 100 measurements (16.00%)
  12 (12.00%) high mild
  4 (4.00%) high severe
log/static/disabled_level_one
                        time:   [28.225 ns 28.269 ns 28.321 ns]
                        change: [-15.038% -14.643% -14.270%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  1 (1.00%) high mild
  3 (3.00%) high severe
log/static/disabled_level_many
                        time:   [28.478 ns 28.528 ns 28.587 ns]
                        change: [-13.351% -12.249% -11.412%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 21 outliers among 100 measurements (21.00%)
  4 (4.00%) low mild
  5 (5.00%) high mild
  12 (12.00%) high severe
log/static/disabled_one time:   [35.508 ns 35.577 ns 35.659 ns]
                        change: [-12.398% -11.898% -11.451%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) high mild
log/static/disabled_many
                        time:   [55.690 ns 55.842 ns 56.024 ns]
                        change: [-9.6779% -9.1278% -8.6265%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 10 outliers among 100 measurements (10.00%)
  2 (2.00%) low mild
  3 (3.00%) high mild
  5 (5.00%) high severe
log/static/baseline_multithreaded
                        time:   [8.6881 us 8.7909 us 8.9327 us]
                        change: [+1.4038% +3.9369% +7.0666%] (p = 0.01 < 0.05)
                        Performance has regressed.
Found 7 outliers among 100 measurements (7.00%)
  2 (2.00%) high mild
  5 (5.00%) high severe
log/static/multithreaded
                        time:   [9.0601 us 9.1176 us 9.1794 us]
                        change: [-28.442% -12.659% -1.2974%] (p = 0.20 > 0.05)
                        No change in performance detected.
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) high mild

log/dynamic/baseline_single_threaded
                        time:   [345.52 ns 346.63 ns 347.96 ns]
                        change: [+7.5780% +8.2499% +8.9141%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 2 outliers among 100 measurements (2.00%)
  1 (1.00%) high mild
  1 (1.00%) high severe
log/dynamic/single_threaded
                        time:   [555.33 ns 557.38 ns 559.98 ns]
                        change: [-1.5187% -0.1665% +1.5911%] (p = 0.86 > 0.05)
                        No change in performance detected.
Found 35 outliers among 100 measurements (35.00%)
  7 (7.00%) low severe
  8 (8.00%) low mild
  7 (7.00%) high mild
  13 (13.00%) high severe
log/dynamic/baseline_multithreaded
                        time:   [10.010 us 10.061 us 10.117 us]
                        change: [+10.121% +13.125% +16.481%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 9 outliers among 100 measurements (9.00%)
  5 (5.00%) high mild
  4 (4.00%) high severe
log/dynamic/multithreaded
                        time:   [12.565 us 12.712 us 12.939 us]
                        change: [-6.3985% -3.7238% -0.7253%] (p = 0.01 < 0.05)
                        Change within noise threshold.
Found 11 outliers among 100 measurements (11.00%)
  1 (1.00%) low severe
  1 (1.00%) low mild
  6 (6.00%) high mild
  3 (3.00%) high severe

log/mixed/disabled      time:   [56.132 ns 56.308 ns 56.507 ns]
                        change: [-6.6512% -6.0523% -5.5172%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  1 (1.00%) low severe
  1 (1.00%) low mild
  1 (1.00%) high mild
  1 (1.00%) high severe
log/mixed/disabled_by_level
                        time:   [29.508 ns 29.593 ns 29.703 ns]
                        change: [-15.510% -14.558% -13.311%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 15 outliers among 100 measurements (15.00%)
  3 (3.00%) low mild
  2 (2.00%) high mild
  10 (10.00%) high severe

     Running /home/jerome/src/github.com/superfly/tracing/target/release/deps/fmt-28efba8f8f01af4f
Gnuplot not found, using plotters backend
new_span/single_thread/1
                        time:   [415.50 ns 416.35 ns 417.42 ns]
                        thrpt:  [2.3957 Melem/s 2.4018 Melem/s 2.4067 Melem/s]
                 change:
                        time:   [+0.8423% +2.1757% +3.2941%] (p = 0.00 < 0.05)
                        thrpt:  [-3.1891% -2.1294% -0.8353%]
                        Change within noise threshold.
Found 14 outliers among 100 measurements (14.00%)
  5 (5.00%) low severe
  2 (2.00%) low mild
  1 (1.00%) high mild
  6 (6.00%) high severe
new_span/multithreaded/1
                        time:   [63.175 us 64.903 us 66.621 us]
                        thrpt:  [15.010 Kelem/s 15.408 Kelem/s 15.829 Kelem/s]
                 change:
                        time:   [-2.3610% +1.6966% +5.9767%] (p = 0.43 > 0.05)
                        thrpt:  [-5.6396% -1.6683% +2.4181%]
                        No change in performance detected.
new_span/single_thread/10
                        time:   [4.1879 us 4.1946 us 4.2024 us]
                        thrpt:  [2.3796 Melem/s 2.3840 Melem/s 2.3878 Melem/s]
                 change:
                        time:   [+3.1390% +3.6241% +4.0986%] (p = 0.00 < 0.05)
                        thrpt:  [-3.9373% -3.4974% -3.0434%]
                        Performance has regressed.
Found 4 outliers among 100 measurements (4.00%)
  1 (1.00%) low mild
  3 (3.00%) high severe
new_span/multithreaded/10
                        time:   [68.322 us 70.102 us 71.858 us]
                        thrpt:  [139.16 Kelem/s 142.65 Kelem/s 146.37 Kelem/s]
                 change:
                        time:   [-5.1103% -1.6727% +1.8615%] (p = 0.34 > 0.05)
                        thrpt:  [-1.8275% +1.7012% +5.3855%]
                        No change in performance detected.
new_span/single_thread/50
                        time:   [20.322 us 20.389 us 20.478 us]
                        thrpt:  [2.4416 Melem/s 2.4523 Melem/s 2.4603 Melem/s]
                 change:
                        time:   [-0.1168% +0.3743% +0.8322%] (p = 0.14 > 0.05)
                        thrpt:  [-0.8253% -0.3729% +0.1169%]
                        No change in performance detected.
Found 8 outliers among 100 measurements (8.00%)
  2 (2.00%) low mild
  2 (2.00%) high mild
  4 (4.00%) high severe
new_span/multithreaded/50
                        time:   [91.937 us 93.439 us 94.924 us]
                        thrpt:  [526.74 Kelem/s 535.11 Kelem/s 543.85 Kelem/s]
                 change:
                        time:   [-0.5858% +1.8129% +4.2596%] (p = 0.15 > 0.05)
                        thrpt:  [-4.0856% -1.7806% +0.5892%]
                        No change in performance detected.
Found 5 outliers among 100 measurements (5.00%)
  4 (4.00%) low mild
  1 (1.00%) high mild

event/root/single_threaded/1
                        time:   [1.3802 us 1.3840 us 1.3887 us]
                        thrpt:  [720.12 Kelem/s 722.53 Kelem/s 724.51 Kelem/s]
                 change:
                        time:   [+3.8156% +4.8622% +6.3486%] (p = 0.00 < 0.05)
                        thrpt:  [-5.9696% -4.6368% -3.6754%]
                        Performance has regressed.
Found 7 outliers among 100 measurements (7.00%)
  1 (1.00%) low severe
  1 (1.00%) low mild
  3 (3.00%) high mild
  2 (2.00%) high severe
event/root/multithreaded/1
                        time:   [72.371 us 74.261 us 76.135 us]
                        thrpt:  [13.135 Kelem/s 13.466 Kelem/s 13.818 Kelem/s]
                 change:
                        time:   [+1.4081% +5.1916% +8.7641%] (p = 0.01 < 0.05)
                        thrpt:  [-8.0579% -4.9354% -1.3885%]
                        Performance has regressed.
event/unique_parent/single_threaded/1
                        time:   [2.0749 us 2.0833 us 2.0938 us]
                        thrpt:  [477.60 Kelem/s 480.00 Kelem/s 481.96 Kelem/s]
                 change:
                        time:   [+1.0968% +2.1995% +3.2827%] (p = 0.00 < 0.05)
                        thrpt:  [-3.1784% -2.1522% -1.0849%]
                        Performance has regressed.
Found 8 outliers among 100 measurements (8.00%)
  1 (1.00%) low mild
  4 (4.00%) high mild
  3 (3.00%) high severe
event/unique_parent/multithreaded/1
                        time:   [75.153 us 77.020 us 78.850 us]
                        thrpt:  [12.682 Kelem/s 12.984 Kelem/s 13.306 Kelem/s]
                 change:
                        time:   [+1.1132% +4.5572% +8.3414%] (p = 0.01 < 0.05)
                        thrpt:  [-7.6992% -4.3585% -1.1009%]
                        Performance has regressed.
Found 2 outliers among 100 measurements (2.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
event/shared_parent/multithreaded/1
                        time:   [73.221 us 75.502 us 78.238 us]
                        thrpt:  [12.781 Kelem/s 13.245 Kelem/s 13.657 Kelem/s]
                 change:
                        time:   [-0.7090% +3.4825% +8.5713%] (p = 0.13 > 0.05)
                        thrpt:  [-7.8946% -3.3653% +0.7141%]
                        No change in performance detected.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high severe
event/root/single_threaded/10
                        time:   [13.827 us 13.870 us 13.924 us]
                        thrpt:  [718.21 Kelem/s 720.99 Kelem/s 723.23 Kelem/s]
                 change:
                        time:   [+0.2894% +0.9201% +1.5017%] (p = 0.00 < 0.05)
                        thrpt:  [-1.4795% -0.9117% -0.2885%]
                        Change within noise threshold.
Found 6 outliers among 100 measurements (6.00%)
  1 (1.00%) low severe
  1 (1.00%) low mild
  1 (1.00%) high mild
  3 (3.00%) high severe
event/root/multithreaded/10
                        time:   [90.027 us 91.804 us 93.589 us]
                        thrpt:  [106.85 Kelem/s 108.93 Kelem/s 111.08 Kelem/s]
                 change:
                        time:   [-0.3211% +2.6109% +5.5146%] (p = 0.08 > 0.05)
                        thrpt:  [-5.2264% -2.5445% +0.3221%]
                        No change in performance detected.
Found 2 outliers among 100 measurements (2.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
event/unique_parent/single_threaded/10
                        time:   [20.821 us 20.882 us 20.955 us]
                        thrpt:  [477.20 Kelem/s 478.87 Kelem/s 480.28 Kelem/s]
                 change:
                        time:   [-1.6059% -1.0336% -0.5015%] (p = 0.00 < 0.05)
                        thrpt:  [+0.5040% +1.0444% +1.6321%]
                        Change within noise threshold.
Found 10 outliers among 100 measurements (10.00%)
  3 (3.00%) low severe
  1 (1.00%) low mild
  3 (3.00%) high mild
  3 (3.00%) high severe
event/unique_parent/multithreaded/10
                        time:   [102.79 us 104.53 us 106.21 us]
                        thrpt:  [94.149 Kelem/s 95.663 Kelem/s 97.284 Kelem/s]
                 change:
                        time:   [-0.1408% +2.5285% +5.2684%] (p = 0.07 > 0.05)
                        thrpt:  [-5.0047% -2.4662% +0.1410%]
                        No change in performance detected.
Found 4 outliers among 100 measurements (4.00%)
  4 (4.00%) low mild
event/shared_parent/multithreaded/10
                        time:   [100.47 us 102.15 us 103.82 us]
                        thrpt:  [96.317 Kelem/s 97.898 Kelem/s 99.534 Kelem/s]
                 change:
                        time:   [+0.9285% +3.3230% +5.9288%] (p = 0.01 < 0.05)
                        thrpt:  [-5.5970% -3.2161% -0.9199%]
                        Change within noise threshold.
event/root/single_threaded/50
                        time:   [67.557 us 67.930 us 68.528 us]
                        thrpt:  [729.63 Kelem/s 736.05 Kelem/s 740.11 Kelem/s]
                 change:
                        time:   [-2.6345% -1.6693% -0.3435%] (p = 0.00 < 0.05)
                        thrpt:  [+0.3447% +1.6977% +2.7058%]
                        Change within noise threshold.
Found 6 outliers among 100 measurements (6.00%)
  1 (1.00%) low severe
  1 (1.00%) low mild
  4 (4.00%) high severe
event/root/multithreaded/50
                        time:   [168.40 us 171.20 us 174.16 us]
                        thrpt:  [287.08 Kelem/s 292.05 Kelem/s 296.91 Kelem/s]
                 change:
                        time:   [+0.0708% +2.3186% +4.6715%] (p = 0.04 < 0.05)
                        thrpt:  [-4.4630% -2.2660% -0.0708%]
                        Change within noise threshold.
Found 2 outliers among 100 measurements (2.00%)
  1 (1.00%) high mild
  1 (1.00%) high severe
event/unique_parent/single_threaded/50
                        time:   [104.62 us 104.92 us 105.31 us]
                        thrpt:  [474.78 Kelem/s 476.53 Kelem/s 477.92 Kelem/s]
                 change:
                        time:   [-2.1027% -1.3903% -0.7428%] (p = 0.00 < 0.05)
                        thrpt:  [+0.7484% +1.4099% +2.1478%]
                        Change within noise threshold.
Found 6 outliers among 100 measurements (6.00%)
  2 (2.00%) low severe
  1 (1.00%) low mild
  3 (3.00%) high severe
event/unique_parent/multithreaded/50
                        time:   [228.25 us 232.22 us 236.19 us]
                        thrpt:  [211.69 Kelem/s 215.31 Kelem/s 219.05 Kelem/s]
                 change:
                        time:   [+5.2991% +8.0410% +10.757%] (p = 0.00 < 0.05)
                        thrpt:  [-9.7121% -7.4426% -5.0324%]
                        Performance has regressed.
event/shared_parent/multithreaded/50
                        time:   [228.36 us 232.23 us 236.07 us]
                        thrpt:  [211.80 Kelem/s 215.30 Kelem/s 218.95 Kelem/s]
                 change:
                        time:   [+1.6743% +4.1477% +6.6113%] (p = 0.00 < 0.05)
                        thrpt:  [-6.2013% -3.9825% -1.6468%]
                        Performance has regressed.
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) low mild

Edit: re-ran with less noise on my system

[hawkw]

I left a couple of notes. Overall, though, this looks good to me.

[hawkw]

Also, it looks like rustfmt needs to be run before CI will pass.

[hawkw]

looks great to me, thank you!