Trying to figure out why mkin 1.1.0 (to be released) tests fail on winbuilder and r-hub with R-devel, I am checking locally with R-devel on Linux. I am finding that certain tests run reasonably quick when using R 4.1.2
me@computer:~/git/mkin (main)$ time Rscript -e "testthat::test_file('tests/testthat/test_tests.R', reporter = 'Progress')"
Loading required package: mkin
Loading required package: parallel
✔ | F W S OK | Context
✔ | 9 | Hypothesis tests [9.0s]
══ Results ═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
Duration: 9.0 s
[ FAIL 0 | WARN 0 | SKIP 0 | PASS 9 ]
real 1m48,779s
user 4m37,386s
sys 3m17,240s
The additional time reported by the unix time command is spent in the setup_script.R file.
When I use locally compiled R-devel, the same tests need more than four times as much time
Loading required package: mkin
Loading required package: parallel
✔ | F W S OK | Context
✔ | 9 | Hypothesis tests [42.4s]
══ Results ═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
Duration: 42.4 s
[ FAIL 0 | WARN 0 | SKIP 0 | PASS 9 ]
real 2m21,823s
user 5m7,507s
sys 3m14,287s
In both cases, R uses openblas-pthread, see for R 4.1.2:
me@computer:~/git/mkin (main)$ Rscript -e "sessionInfo()"
R version 4.1.2 (2021-11-01)
Platform: x86_64-pc-linux-gnu (64-bit)
Running under: Debian GNU/Linux 11 (bullseye)
Matrix products: default
BLAS: /usr/lib/x86_64-linux-gnu/openblas-pthread/libblas.so.3
LAPACK: /usr/lib/x86_64-linux-gnu/openblas-pthread/libopenblasp-r0.3.13.so
locale:
[1] LC_CTYPE=de_DE.UTF-8 LC_NUMERIC=C
[3] LC_TIME=de_DE.UTF-8 LC_COLLATE=de_DE.UTF-8
[5] LC_MONETARY=de_DE.UTF-8 LC_MESSAGES=de_DE.UTF-8
[7] LC_PAPER=de_DE.UTF-8 LC_NAME=C
[9] LC_ADDRESS=C LC_TELEPHONE=C
[11] LC_MEASUREMENT=de_DE.UTF-8 LC_IDENTIFICATION=C
attached base packages:
[1] stats graphics grDevices utils datasets methods base
loaded via a namespace (and not attached):
[1] compiler_4.1.2
and for R-devel:
me@computer:~/git/mkin (main)$ Rscript-devel -e "sessionInfo()"
R Under development (unstable) (2022-03-02 r81842)
Platform: x86_64-pc-linux-gnu (64-bit)
Running under: Debian GNU/Linux 11 (bullseye)
Matrix products: default
BLAS/LAPACK: /usr/lib/x86_64-linux-gnu/openblas-pthread/libopenblasp-r0.3.13.so
locale:
[1] LC_CTYPE=de_DE.UTF-8 LC_NUMERIC=C
[3] LC_TIME=de_DE.UTF-8 LC_COLLATE=de_DE.UTF-8
[5] LC_MONETARY=de_DE.UTF-8 LC_MESSAGES=de_DE.UTF-8
[7] LC_PAPER=de_DE.UTF-8 LC_NAME=C
[9] LC_ADDRESS=C LC_TELEPHONE=C
[11] LC_MEASUREMENT=de_DE.UTF-8 LC_IDENTIFICATION=C
attached base packages:
[1] stats graphics grDevices utils datasets methods base
loaded via a namespace (and not attached):
[1] compiler_4.2.0
You can try to reproduce this from my latest commit (increase cloning depth if necessary)
git clone git@github.com:jranke/mkin --depth=10
cd mkin
git checkout 77c248ca40b82ec00a756cd82f12968131f78959
Stripping down the setup script to what's really needed to run the tests from this particular file reduces the time difference:
$ git pull origin stackoverflow_71340826
$ Rscript -e "testthat::test_file('tests/testthat/test_tests.R', reporter = 'Progress')"
Loading required package: mkin
Loading required package: parallel
✔ | F W S OK | Context
✔ | 9 | Hypothesis tests [7.8s]
══ Results ═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
Duration: 7.8 s
[ FAIL 0 | WARN 0 | SKIP 0 | PASS 9 ]
as compared to
$ Rscript-devel -e "testthat::test_file('tests/testthat/test_tests.R', reporter = 'Progress')"
Loading required package: mkin
Loading required package: parallel
✔ | F W S OK | Context
✔ | 9 | Hypothesis tests [13.9s]
══ Results ═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
Duration: 14.0 s
[ FAIL 0 | WARN 0 | SKIP 0 | PASS 9 ]
Any hints are appreciated.
This was caused by some bug fixes in the DLL info interface in R, which resulted in slower execution of the many calls to getLoadedDLLs() in my mkin code for compiled models. Thanks to a suggestion by Thomas Kalibera on r-pkg-devel I could reduce these calls to the necessary minimum, so the problem went away in mkin v1.1.1.