Performance regression in RxInfer code on current master

[bvdmitri]

We have a set of small benchmarks to quickly test our code in RxInfer. The aim of the package is to run efficient Bayesian inference, potentially on low-power low-memory devices like RaspberryPI. We just noticed, that on Julia 1.10 we have quite a noticeable GC regression. Consider this notebook. Not an MWE but still, this notebook computes Bayesian posteriors in a simple linear Gaussian state-space probabilistic model. There are two settings:

• Filtering, for each time step $t$ use observations up to the time step $t$.
• Smoothing, for each time step $t$ use observations up to the time step $T > t$

Here are the results on the current Julia release

julia> versioninfo()
Julia Version 1.9.2
Commit e4ee485e909 (2023-07-05 09:39 UTC)

julia> @benchmark run_filtering($datastream, $n, $v)
BenchmarkTools.Trial: 1504 samples with 1 evaluation.
 Range (min … max):  2.633 ms … 13.932 ms  ┊ GC (min … max): 0.00% … 69.28%
 Time  (median):     3.073 ms              ┊ GC (median):    0.00%
 Time  (mean ± σ):   3.319 ms ±  1.058 ms  ┊ GC (mean ± σ):  7.08% ± 13.05%

   ▅▇▇██▇▅▃▂                                                 ▁
  ██████████▇▇▅▇█▇▇▅▄▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▅▇██▇▆█▇▆▄▄▅ █
  2.63 ms      Histogram: log(frequency) by time     7.92 ms <

 Memory estimate: 2.35 MiB, allocs estimate: 63823.

julia> @benchmark run_smoothing($data, $n, $v)
BenchmarkTools.Trial: 288 samples with 1 evaluation.
 Range (min … max):  13.868 ms … 29.987 ms  ┊ GC (min … max):  0.00% … 35.63%
 Time  (median):     15.545 ms              ┊ GC (median):     0.00%
 Time  (mean ± σ):   17.411 ms ±  3.975 ms  ┊ GC (mean ± σ):  10.81% ± 14.33%

   ▄▃█▁▄▅▁
  ▇███████▇▆▅▅▃▃▄▂▄▃▂▁▃▃▁▁▁▁▁▁▁▁▁▂▃▅▃▃▅▅▄▃▂▃▃▃▃▃▂▂▁▄▂▁▃▁▁▂▂▂▂ ▃
  13.9 ms         Histogram: frequency by time        28.4 ms <

 Memory estimate: 10.05 MiB, allocs estimate: 220417.

Here are the results on the 1.10-beta1

julia> versioninfo()
Julia Version 1.10.0-beta1
Commit 6616549950e (2023-07-25 17:43 UTC)

julia> @benchmark run_filtering($datastream, $n, $v)
BenchmarkTools.Trial: 1308 samples with 1 evaluation.
 Range (min … max):  3.260 ms … 78.207 ms  ┊ GC (min … max): 0.00% … 94.71%
 Time  (median):     3.479 ms              ┊ GC (median):    0.00%
 Time  (mean ± σ):   3.818 ms ±  3.293 ms  ┊ GC (mean ± σ):  6.64% ±  7.41%

      ▄▆██▅▁
  ▂▃▄▇██████▇▅▅▃▃▃▃▃▂▂▃▃▃▃▃▃▂▃▃▂▂▂▁▂▂▂▂▁▂▁▂▂▁▂▂▁▁▁▂▂▂▂▂▂▂▂▂▂ ▃
  3.26 ms        Histogram: frequency by time        4.94 ms <

 Memory estimate: 2.51 MiB, allocs estimate: 69824.

julia> @benchmark run_smoothing($data, $n, $v)
BenchmarkTools.Trial: 291 samples with 1 evaluation.
 Range (min … max):  15.160 ms … 88.841 ms  ┊ GC (min … max): 0.00% … 79.71%
 Time  (median):     15.757 ms              ┊ GC (median):    0.00%
 Time  (mean ± σ):   17.336 ms ±  7.862 ms  ┊ GC (mean ± σ):  7.05% ± 11.57%

  █▅▁
  █████▇▄▁▁▄▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▅▅▄ ▅
  15.2 ms      Histogram: log(frequency) by time      57.9 ms <

 Memory estimate: 10.12 MiB, allocs estimate: 222915.

As you can see in the case of run_filtering, the maximum time jumped from 13ms to 78ms. The GC max also indicates a jump from 69% to 94%. In the case of run_smoothing the situation is similar, the maximum time jumped from 29ms to 88ms. The GC max jumped from 35% to 79%.

The inference precedure allocates a lot of intermediate "messages" in a form of distributions from Distributions.jl package, but does not use any sampling. Instead, it computes analytical solutions for posteriors. This analytical solutions also rely on dynamic multiple dispatch in many places. Eliminating dynamic multiple dispatch is not really an option, it just how it works and it was quite efficient anyway until now.

The major differences between two functions is that run_filtering allocates a lot of information (messages) and do not use it afterwards that is probably can be free-ed right away, and the run_smoothing retains/stores this information till the end of the procedure. You can also see that the resulting minimum execution time is also worse in both cases.

I think this is quite a severe regression, especially for the filtering case, which is supposed to run the real-time Bayesian inference with as little GC pauses as possible. We can of course refine our code base, but in the mean-time can it be improved in general? What can cause this? How should we proceed and debug this? How can we help figuring out further?

julia> versioninfo()
Julia Version 1.9.2
Commit e4ee485e909 (2023-07-05 09:39 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin22.4.0)
  CPU: 12 × Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, skylake)
  Threads: 1 on 12 virtual cores

julia>

[KristofferC]

Thanks for the report and the nice reproducers. The GC heuristics were significantly changed in #50144 so it isn't too surprising that there might be cases where it needs to be further refined.

Putting this on the milestone for now so it isn't forgotten at least.

[bvdmitri]

Thanks, glad to help!

Since the reproducers are not MWE, to give you an idea what might be happening, I think one potential problem here is that the program (as a part of the algorithm) allocates A LOT of small and short-lived objects. The algorithm, on the high-level, involves creating a sparse graph and passing messages between the nodes in the graph. These messages are needed only for a short period of time. In the benchmark example the messages are encoded as the Normal distributions, which consists of two numbers of Float64. These messages are allocated in the heap and are part of the dynamic multiple dispatch, because the algorithm does not (and can not) know in advance the types of the messages.

As a side note, I could not run the benchmark on master because some of the downstream packages failed to compile on master.

[gbaraldi]

So I ran your code (1.10 + #50682) and I see a wall time regression, but not necessarily a GC, because max GC time might not be the best way to quantify it. Specifically because if in one case we do 100 runs and only in one of the runs we do a collection but it's a big collection, we might see 90% max GC usage, but median/mean might be lower. The more concerning thing is that there seems to be a regression overall in the performance of the code that I'm not sure if it's just GC related.

1.9

julia> @benchmark run_filtering(datastream, n, $v)
BenchmarkTools.Trial: 2421 samples with 1 evaluation.
 Range (min … max):  1.847 ms …   5.287 ms  ┊ GC (min … max): 0.00% … 60.24%
 Time  (median):     1.906 ms               ┊ GC (median):    0.00%
 Time  (mean ± σ):   2.064 ms ± 612.807 μs  ┊ GC (mean ± σ):  6.81% ± 12.77%

  ▃█
  ██▅▃▃▂▂▂▂▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂▃▂ ▂
  1.85 ms         Histogram: frequency by time        4.66 ms <

 Memory estimate: 2.35 MiB, allocs estimate: 63824.

julia> @benchmark run_smoothing(data, n, $v)
BenchmarkTools.Trial: 476 samples with 1 evaluation.
 Range (min … max):   8.658 ms … 28.003 ms  ┊ GC (min … max):  0.00% … 29.64%
 Time  (median):      9.164 ms              ┊ GC (median):     0.00%
 Time  (mean ± σ):   10.508 ms ±  2.647 ms  ┊ GC (mean ± σ):  10.46% ± 13.81%

  ▆█▅▄▄▂▁                       ▁▁
  ███████▇███▇▆▄▅▁▅▁▄▁▁▄▄▄▄▇▇▇▆▇███▇█▇█▇█▆▇▇▅▅▆▄▅▄▅▁▁▁▁▁▁▄▁▄▄ ▇
  8.66 ms      Histogram: log(frequency) by time        18 ms <

 Memory estimate: 10.05 MiB, allocs estimate: 220418.

1.10 + that PR

julia> @benchmark run_filtering(datastream, n, $v)
BenchmarkTools.Trial: 1642 samples with 1 evaluation.
 Range (min … max):  2.746 ms … 23.783 ms  ┊ GC (min … max): 0.00% … 87.46%
 Time  (median):     2.908 ms              ┊ GC (median):    0.00%
 Time  (mean ± σ):   3.044 ms ±  1.398 ms  ┊ GC (mean ± σ):  4.46% ±  8.07%

    ▃▆▅▁▆▂▄▄▃▅▄▇▆█▅▇▆▆▇██▅▆▂▅▂
  ▃▇███████████████████████████▇▇▇▆▅▄▃▃▃▂▂▃▂▂▁▂▁▂▂▁▁▁▁▁▁▁▁▁▂ ▅
  2.75 ms        Histogram: frequency by time         3.3 ms <

 Memory estimate: 2.51 MiB, allocs estimate: 69825.

julia> @benchmark run_smoothing(data, n, $v)
BenchmarkTools.Trial: 416 samples with 1 evaluation.
 Range (min … max):  10.883 ms … 33.700 ms  ┊ GC (min … max): 0.00% … 65.24%
 Time  (median):     11.343 ms              ┊ GC (median):    0.00%
 Time  (mean ± σ):   12.041 ms ±  3.190 ms  ┊ GC (mean ± σ):  4.34% ± 10.21%

  █▇█
  ███▆▁▁▁▄▆▇▄▁▄▄▁▁▁▁▁▁▄▁▄▁▄▄▁▁▁▄▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▄▅▄▇▄ ▆
  10.9 ms      Histogram: log(frequency) by time        28 ms <

 Memory estimate: 10.12 MiB, allocs estimate: 222916.

So the mean GC went slightly down. But notice how the minimum time went up meaning that there is another regression somewhere, specially because on the minimum run the GC didn't run at all.

[bvdmitri]

@gbaraldi I agree with you that it could be some sort of other regression or a combination of regressions. I tend not to use mean statistics for comparison, specifically because they can be affected by background processes on a computer. I also do not immediately understand how to compare the mean statistics in percentages (for GC) because the base (wall time) is different. It could the case that the mean in percentage is lower because the absolute wall time is bigger.

For example for the filtering case, GC mean is just exactly the same with only small improvement is you account for the wall time:

julia> 2.064 * 0.0681
0.1405584

julia> 3.044 * 0.0446
0.1357624

But the mean values in benchmarks are tricky anyway. I tend to compare the min/max values instead, I recall an article about that but I've read it long ago and don't really have a reference but the rough idea is:

• min reflects the theoretical best performance of an algorithm, if everything goes perfect
• max reflects the worst case scenario, if everything goes wrong
• mean/median statistics are heavily affected by background tasks and cannot be reliably compared until you account for the skewness of the benchmark distributions (and I can see that skewness is largely different in benchmarks between 1.9 and 1.10)

I don't want to say that comparing mean/median is always a bad idea. I just want to say that it is safer to compare min/max values in majority of the cases, unless you invest much more time in proper analysis.

The max GC time is very consistent across different platforms and computers (I checked my 2 computers several times + plus your benchmark). It does not look to me as an outlier. But you are also correct saying that GC can be only one part of the story.

I checked the benchmarks with GC disabled. These are my results:

GC.enable(false)
benchmark = @benchmark run_filtering($datastream, $n, $v) samples=100
GC.enable(true)
GC.gc(true)
benchmark

# 1.9
BenchmarkTools.Trial: 100 samples with 1 evaluation.
 Range (min … max):  1.829 ms …   3.831 ms  ┊ GC (min … max): 0.00% … 0.00%
 Time  (median):     2.064 ms               ┊ GC (median):    0.00%
 Time  (mean ± σ):   2.106 ms ± 271.007 μs  ┊ GC (mean ± σ):  0.00% ± 0.00%

    ▂▂▃ ▇▅█ ▃▅▂▄▂                                              
  ▅▆███▃███▅█████▇▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▃▁▁▁▁▁▁▁▁▃ ▃
  1.83 ms         Histogram: frequency by time        3.44 ms <

 Memory estimate: 2.35 MiB, allocs estimate: 63823.

# 1.10-beta1
BenchmarkTools.Trial: 100 samples with 1 evaluation.
 Range (min … max):  2.568 ms …   4.568 ms  ┊ GC (min … max): 0.00% … 0.00%
 Time  (median):     2.749 ms               ┊ GC (median):    0.00%
 Time  (mean ± σ):   2.796 ms ± 319.726 μs  ┊ GC (mean ± σ):  0.00% ± 0.00%

  ▁▁  ▁▄█▆▃                                                    
  ███▅█████▆▆▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▃▁▁▃▁▁▁▃ ▃
  2.57 ms         Histogram: frequency by time        4.31 ms <

 Memory estimate: 2.51 MiB, allocs estimate: 69824.

GC.enable(false)
benchmark = @benchmark run_smoothing($data, $n, $v) samples=100
GC.enable(true)
GC.gc(true)
benchmark

# 1.9
BenchmarkTools.Trial: 100 samples with 1 evaluation.
 Range (min … max):  8.132 ms …  11.818 ms  ┊ GC (min … max): 0.00% … 0.00%
 Time  (median):     8.832 ms               ┊ GC (median):    0.00%
 Time  (mean ± σ):   8.997 ms ± 758.615 μs  ┊ GC (mean ± σ):  0.00% ± 0.00%

  ▂        █ ▂ ▃                                               
  █▅▇█▃▃▁▅▆███▆█▄▇▄▄▃▃▁▃▆▃▅▁▁▁▁▁▃▁▁▁▁▃▁▁▁▁▃▄▁▃▁▃▁▁▁▃▁▁▁▁▁▁▁▁▃ ▃
  8.13 ms         Histogram: frequency by time        11.8 ms <

 Memory estimate: 10.05 MiB, allocs estimate: 220417.

# 1.10-beta1
BenchmarkTools.Trial: 100 samples with 1 evaluation.
 Range (min … max):   9.918 ms …  12.661 ms  ┊ GC (min … max): 0.00% … 0.00%
 Time  (median):     10.534 ms               ┊ GC (median):    0.00%
 Time  (mean ± σ):   10.644 ms ± 460.803 μs  ┊ GC (mean ± σ):  0.00% ± 0.00%

              ▄█▅▃▃                                             
  ▅▁▁▅▃▅▁▅▆▇▇██████▆▅█▇▆▆▃▁▅▁▁▁▁▁▁▁▃▁▁▁▃▁▃▃▃▁▁▅▁▃▁▁▁▁▁▁▁▁▁▁▁▁▃ ▃
  9.92 ms         Histogram: frequency by time         12.4 ms <

 Memory estimate: 10.12 MiB, allocs estimate: 222915.

So yes, there is some sort of regression, which looks like it is further escalated by the GC timings. Something happens which triggers GC to spend even more time in the worst case scenario. But I'm not sure how to narrow it down further. The output of the Profile is very different between versions and basically unreadable.

[gbaraldi]

The GC might decide to coalesce the garbage collections to bring down overall time while having potentially longer pauses.

[nathanrboyer]

I imagine I'm having the same issue, but I'm not sure.

1.9.2

julia> @benchmark compute_fracture_polys($user_input)
BenchmarkTools.Trial: 1 sample with 1 evaluation.
 Single result which took 160.110 s (26.37% GC) to evaluate,
 with a memory estimate of 689.02 GiB, over 548291410 allocations.

1.10.0-beta1

julia> @benchmark compute_fracture_polys($user_input)
# Still running 17 hours later

1.10 beta makes my existing program unusable.

[gbaraldi]

So there is a bug on 1.10 beta that should be fixed on the next beta, but in any case is there a way for you to share an open source version of your code? Or try and run it on recent nightly?

[nathanrboyer]

I downloaded the nightly release from https://julialang.org/downloads/nightlies/ and got the same bad behavior as 1.10.0-beta1. I created a repository here for testing: https://github.com/nathanrboyer/JuliaNightlyTestCode

[gbaraldi]

Oddly enough I think this might not be a GC bug at all, this is where perf says we are spending time. Which makes me think this is a subtyping bug.

The other two calls are about 4x faster on master than on 1.9 for me.