Performance regression in 2.27.0 RC

[rok-cesnovar]

@wds15 reported a performance regression that we need to get to the bottom of: https://discourse.mc-stan.org/t/cmdstan-2-27-0-release-candidate/22602/2

Stan model and data: regression.zip

I can reproduce and will investigate and post any progress here.

The first instinct was that its related to the range checks, but it seems that may not be the case.

[rok-cesnovar]

Reverting stan-dev/stanc3#849 (added range checks) makes no difference in this case so it seems to be something else.

[wds15]

I added profiling to the stan program:

blrm_exnex-profile_stan.txt

Output:

> fit_26$time()$total
[1] 21.89892
> fit_27b$time()$total
[1] 25.5831
> fit_26$profiles()
[[1]]
       name   thread_id total_time forward_time reverse_time chain_stack
1   log-lik 0x10c17bdc0   14.21690     12.57950     1.637460   226782179
2     prior 0x10c17bdc0    1.70180      1.59811     0.103685    13408400
3 transform 0x10c17bdc0    1.75127      1.13223     0.619044    21120372
  no_chain_stack autodiff_calls no_autodiff_calls
1      102915172         167605                 1
2        5698570         167605                 1
3       10057320         167605              5001

> fit_27b$profiles()
[[1]]
       name   thread_id total_time forward_time reverse_time chain_stack
1   log-lik 0x10ed04dc0   16.56900     14.49760     2.071480   225845240
2     prior 0x10ed04dc0    1.96636      1.83771     0.128652    13353360
3 transform 0x10ed04dc0    2.40248      1.72354     0.678942     9014166
  no_chain_stack autodiff_calls no_autodiff_calls
1      102489998         166917                 1
2        5007510         166917                 1
3       24037776         166917              5001

Not sure.. The problem seems to be smeared out somewhat.

Ah... I also disabled generated quantities.

[wds15]

I just reran this with STAN_CPP_OPTIMS=TRUE for 2.26.0 and 2.27.0. No change:

> fit_26$time()$total
[1] 21.64465
> fit_27b$time()$total
[1] 25.10066
> fit_26$profiles()
[[1]]
       name   thread_id total_time forward_time reverse_time chain_stack
1   log-lik 0x109891dc0   13.10350     11.51520     1.588270   226782179
2     prior 0x109891dc0    1.69421      1.58724     0.106974    13408400
3 transform 0x109891dc0    1.64914      1.06284     0.586304    21120372
  no_chain_stack autodiff_calls no_autodiff_calls
1      102915172         167605                 1
2        5698570         167605                 1
3       10057320         167605              5001

> fit_27b$profiles()
[[1]]
       name   thread_id total_time forward_time reverse_time chain_stack
1   log-lik 0x111094dc0   15.68390     13.62370     2.060180   225845240
2     prior 0x111094dc0    1.96505      1.84542     0.119629    13353360
3 transform 0x111094dc0    2.29094      1.66794     0.622994     9014166
  no_chain_stack autodiff_calls no_autodiff_calls
1      102489998         166917                 1
2        5007510         166917                 1
3       24037776         166917              5001

> 

[wds15]

Given that the slowdown is so smeared out I thought that maybe a change in the compiler is guilty. The usual way of testing this does not work here. So I tried to use stanc3 from 2.26.0 and then compile it with 2.27.0, but that fails in the compilation stage.

[wds15]

Some progress: What I can do is use cmdstan 2.26.0 and point it to use math 2.27.0. Then I get with this mixed setup:

> fit_mix$time()$total
[1] 19.24794
> fit_mix$profiles()
[[1]]
       name   thread_id total_time forward_time reverse_time chain_stack
1   log-lik 0x1110fbdc0   12.26030     10.31270     1.947580   226056690
2     prior 0x1110fbdc0    1.43655      1.33204     0.104508    13365760
3 transform 0x1110fbdc0    1.72902      1.15965     0.569375     9022590
  no_chain_stack autodiff_calls no_autodiff_calls
1      102585954         167072                 1
2        5012160         167072                 1
3       24060240         167072              5001

Since this is now even somewhat faster than before, I do think that this suggests that the issue is upstream. So either stan or the compiler has some problem causing performance issues is what I would think.

[rok-cesnovar]

Yeah, one cause is stan-dev/stanc3#842 but not for the whole regression.

[SteveBronder]

What in stan-dev/stanc3#842 would cause the regression? The local statement thing? That shouldn't have a big effect

[rok-cesnovar]

Scratch that, had a bad testing setup when tested that. Sorry for that false alarm.

It seems to be the stan-dev/stanc3#856 PR

• cmdstan on develop and stanc3 on git hash 036d9307055ba40ea5b2ca556f2d0014e3d8288d (one prior to 856) the execution I time at around 21s

• cmdstan on develop and stanc3 on git hash 282439ea73cd348b22b09be78bb78875b03a0e64 (856 merged) I time at around 16s (binaries for that hash are being built here: https://github.com/stan-dev/stanc3/actions/runs/861509419)

In both cases, the only flag was the STAN_NO_RANGE_CHECKS. g++ 9.3.0 on Ubuntu 20.04.

@SteveBronder First we should see if anyone can reproduce my findings. But if we can the question is that PR critical right now (for this release) or is that required for varmat and tuples? I dont know enough about that PR to revert it on master (too many conflicts).

[SteveBronder]

I'm running the below and actually seeing 2.27 is faster locally for me

https://discourse.mc-stan.org/t/cmdstan-2-27-0-release-candidate/22602/14?u=stevebronder

[SteveBronder]

Before we talk about reverting anything I'd like someone to run the scheme I have in the above link. It just seems very odd to have such large differences in timings. I have a semi fancy machine but nothing that is going to see a 20%+ timing difference. Maybe it's clang? I can try that out

[wds15]

Nope... I am on clang and @rok-cesnovar used g++ on Ubuntu

[rok-cesnovar]

And to avoid confusion, the model is in the top comment and has no profile statements.

Timing results are exactly the same with cmdstan or cmdstanr.

[rok-cesnovar]

I however do not have march native on.

[wds15]

Here is the time result:

time -p for run in {1..10}; do ./blrm_exnex-profile-26 sample num_warmup=10000 num_samples=10000 data file="./test_24/blrm_exnex-combo3.data.R" random seed=1234 init=0; done

 Elapsed Time: 19.25 seconds (Warm-up)
               19.463 seconds (Sampling)
               38.713 seconds (Total)

real 386.28
user 381.35
sys 2.29


time -p for run in {1..10}; do ./blrm_exnex-profile-27 sample num_warmup=10000 num_samples=10000 data file="./test_24/blrm_exnex-combo3.data.R" random seed=1234 init=0; done

 Elapsed Time: 22.888 seconds (Warm-up)
               22.985 seconds (Sampling)
               45.873 seconds (Total)

real 459.85
user 455.00
sys 2.86

[wds15]

BTW... do I see this right in that the performance tests are not run on all PRs for stanc3? Maybe the performance test suite detected this issue already? It should have, but that we can sort out another day...