Slow (in terms of CRAN policy) R examples

[StrikerRUS]

The most recent master build fails on macOS with the following error (we treat NOTEs as errors):

* checking examples ... � � � � � NOTE
Examples with CPU or elapsed time > 5s
                   user system elapsed
lgb.model.dt.tree 0.196  0.021   5.728

Full logs: https://github.com/microsoft/LightGBM/runs/2039644445

cc @jameslamb

[jameslamb]

Just saw this again on #4053, on https://github.com/microsoft/LightGBM/pull/4053/checks?check_run_id=2062786320, on the job r-package (macOS-latest, clang, R 3.6, cmake).

This time, complaining about a different example.

* checking examples ... � � � � � NOTE
Examples with CPU or elapsed time > 5s
        user system elapsed
lgb.cv 0.278  0.044   5.444

R CMD check logs

* using R version 3.6.3 (2020-02-29)
* using platform: x86_64-apple-darwin15.6.0 (64-bit)
* using session charset: UTF-8
* using options ‘--run-donttest --as-cran’
* checking for file ‘lightgbm/DESCRIPTION’ ... OK
* checking extension type ... Package
* this is package ‘lightgbm’ version ‘3.1.1.99’
* package encoding: UTF-8
* checking CRAN incoming feasibility ... Note_to_CRAN_maintainers
Maintainer: ‘Guolin Ke <guolin.ke@microsoft.com>’
* checking package namespace information ... OK
* checking package dependencies ... � OK
* checking if this is a source package ... OK
* checking if there is a namespace ... OK
* checking for executable files ... � OK
* checking for hidden files and directories ... OK
* checking for portable file names ... OK
* checking for sufficient/correct file permissions ... OK
* checking whether package ‘lightgbm’ can be installed ... � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � � OK
* checking installed package size ... OK
* checking package directory ... OK
* checking for future file timestamps ... OK
* checking DESCRIPTION meta-information ... OK
* checking top-level files ... � OK
* checking for left-over files ... OK
* checking index information ... OK
* checking package subdirectories ... OK
* checking R files for non-ASCII characters ... OK
* checking R files for syntax errors ... OK
* checking whether the package can be loaded ... OK
* checking whether the package can be loaded with stated dependencies ... � OK
* checking whether the package can be unloaded cleanly ... OK
* checking whether the namespace can be loaded with stated dependencies ... � OK
* checking whether the namespace can be unloaded cleanly ... OK
* checking loading without being on the library search path ... OK
* checking use of S3 registration ... � OK
* checking dependencies in R code ... OK
* checking S3 generic/method consistency ... � OK
* checking replacement functions ... OK
* checking foreign function calls ... � OK
* checking R code for possible problems ... � � OK
* checking Rd files ... OK
* checking Rd metadata ... OK
* checking Rd line widths ... OK
* checking Rd cross-references ... OK
* checking for missing documentation entries ... OK
* checking for code/documentation mismatches ... � OK
* checking Rd \usage sections ... � OK
* checking Rd contents ... OK
* checking for unstated dependencies in examples ... OK
* checking contents of ‘data’ directory ... OK
* checking data for non-ASCII characters ... � OK
* checking data for ASCII and uncompressed saves ... OK
* checking line endings in C/C++/Fortran sources/headers ... OK
* checking line endings in Makefiles ... OK
* checking compilation flags in Makevars ... OK
* checking for GNU extensions in Makefiles ... OK
* checking for portable use of $(BLAS_LIBS) and $(LAPACK_LIBS) ... OK
* checking use of SHLIB_OPENMP_*FLAGS in Makefiles ... OK
* checking pragmas in C/C++ headers and code ... OK
* checking compilation flags used ... OK
* checking compiled code ... OK
* checking examples ... � � � � � NOTE
Examples with CPU or elapsed time > 5s
        user system elapsed
lgb.cv 0.278  0.044   5.444
* checking for unstated dependencies in ‘tests’ ... OK
* checking tests ...
  Running ‘testthat.R’ [19s/34s]
 � � � � � � � OK
* checking PDF version of manual ... � OK
* checking for detritus in the temp directory ... OK
* DONE

Status: 1 NOTE
See
  ‘/Users/runner/work/LightGBM/LightGBM/lightgbm.Rcheck/00check.log’
for details.


R CMD check build logs:
* installing *source* package ‘lightgbm’ ...
** using staged installation
** libs
installing via 'install.libs.R' to /Users/runner/work/LightGBM/LightGBM/lightgbm.Rcheck/00LOCK-lightgbm/00new/lightgbm
-- The C compiler identification is AppleClang 12.0.0.12000032
-- The CXX compiler identification is AppleClang 12.0.0.12000032
-- Detecting C compiler ABI info
-- Detecting C compiler ABI info - done
-- Check for working C compiler: /Applications/Xcode_12.4.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/cc - skipped
-- Detecting C compile features
-- Detecting C compile features - done
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- Check for working CXX compiler: /Applications/Xcode_12.4.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/c++ - skipped
-- Detecting CXX compile features
-- Detecting CXX compile features - done
-- R version passed into FindLibR.cmake: 3.6.3
-- Found LibR: /Library/Frameworks/R.framework/Versions/3.6/Resources  
-- LIBR_EXECUTABLE: /Library/Frameworks/R.framework/Resources/R
-- LIBR_INCLUDE_DIRS: /Library/Frameworks/R.framework/Versions/3.6/Resources/include
-- LIBR_CORE_LIBRARY: /Library/Frameworks/R.framework
-- Found OpenMP_C: -Xclang -fopenmp (found version "4.5") 
-- Found OpenMP_CXX: -Xclang -fopenmp (found version "4.5") 
-- Found OpenMP: TRUE (found version "4.5")  
-- Performing Test MM_PREFETCH
-- Performing Test MM_PREFETCH - Success
-- Using _mm_prefetch
-- Performing Test MM_MALLOC
-- Performing Test MM_MALLOC - Success
-- Using _mm_malloc
-- Configuring done
-- Generating done
-- Build files have been written to: /Users/runner/work/LightGBM/LightGBM/lightgbm.Rcheck/00_pkg_src/lightgbm/src/build
Building lib_lightgbm
Scanning dependencies of target _lightgbm
[  2%] Building CXX object CMakeFiles/_lightgbm.dir/src/boosting/boosting.cpp.o
[  5%] Building CXX object CMakeFiles/_lightgbm.dir/src/boosting/gbdt.cpp.o
[  8%] Building CXX object CMakeFiles/_lightgbm.dir/src/boosting/gbdt_model_text.cpp.o
[ 11%] Building CXX object CMakeFiles/_lightgbm.dir/src/boosting/gbdt_prediction.cpp.o
[ 14%] Building CXX object CMakeFiles/_lightgbm.dir/src/boosting/prediction_early_stop.cpp.o
[ 17%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/bin.cpp.o
[ 20%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/config.cpp.o
[ 22%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/config_auto.cpp.o
[ 25%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/dataset.cpp.o
[ 28%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/dataset_loader.cpp.o
[ 31%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/file_io.cpp.o
[ 34%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/json11.cpp.o
[ 37%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/metadata.cpp.o
[ 40%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/parser.cpp.o
[ 42%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/train_share_states.cpp.o
[ 45%] Building CXX object CMakeFiles/_lightgbm.dir/src/io/tree.cpp.o
[ 48%] Building CXX object CMakeFiles/_lightgbm.dir/src/metric/dcg_calculator.cpp.o
[ 51%] Building CXX object CMakeFiles/_lightgbm.dir/src/metric/metric.cpp.o
[ 54%] Building CXX object CMakeFiles/_lightgbm.dir/src/network/ifaddrs_patch.cpp.o
[ 57%] Building CXX object CMakeFiles/_lightgbm.dir/src/network/linker_topo.cpp.o
[ 60%] Building CXX object CMakeFiles/_lightgbm.dir/src/network/linkers_mpi.cpp.o
[ 62%] Building CXX object CMakeFiles/_lightgbm.dir/src/network/linkers_socket.cpp.o
[ 65%] Building CXX object CMakeFiles/_lightgbm.dir/src/network/network.cpp.o
[ 68%] Building CXX object CMakeFiles/_lightgbm.dir/src/objective/objective_function.cpp.o
[ 71%] Building CXX object CMakeFiles/_lightgbm.dir/src/treelearner/cuda_tree_learner.cpp.o
[ 74%] Building CXX object CMakeFiles/_lightgbm.dir/src/treelearner/data_parallel_tree_learner.cpp.o
[ 77%] Building CXX object CMakeFiles/_lightgbm.dir/src/treelearner/feature_parallel_tree_learner.cpp.o
[ 80%] Building CXX object CMakeFiles/_lightgbm.dir/src/treelearner/gpu_tree_learner.cpp.o
[ 82%] Building CXX object CMakeFiles/_lightgbm.dir/src/treelearner/linear_tree_learner.cpp.o
[ 85%] Building CXX object CMakeFiles/_lightgbm.dir/src/treelearner/serial_tree_learner.cpp.o
[ 88%] Building CXX object CMakeFiles/_lightgbm.dir/src/treelearner/tree_learner.cpp.o
[ 91%] Building CXX object CMakeFiles/_lightgbm.dir/src/treelearner/voting_parallel_tree_learner.cpp.o
[ 94%] Building CXX object CMakeFiles/_lightgbm.dir/src/c_api.cpp.o
[ 97%] Building CXX object CMakeFiles/_lightgbm.dir/src/lightgbm_R.cpp.o
[100%] Linking CXX shared library ../lib_lightgbm.so
[100%] Built target _lightgbm
Found library file: /Users/runner/work/LightGBM/LightGBM/lightgbm.Rcheck/00_pkg_src/lightgbm/src/lib_lightgbm.so to move to /Users/runner/work/LightGBM/LightGBM/lightgbm.Rcheck/00LOCK-lightgbm/00new/lightgbm/libs
Removing 'build/' directory
** R
** data
** demo
** inst
** byte-compile and prepare package for lazy loading
** help
*** installing help indices
*** copying figures
** building package indices
** testing if installed package can be loaded from temporary location
** checking absolute paths in shared objects and dynamic libraries
** testing if installed package can be loaded from final location
** testing if installed package keeps a record of temporary installation path
* DONE (lightgbm)
NOTEs, WARNINGs, or ERRORs have been found by R CMD check
Error: Process completed with exit code 255.

I suspect that using --run-donttest together with --as-cran can lead to this issue:

LightGBM/.ci/test_r_package.sh

Lines 152 to 154 in 3a5e3c0

	R CMD check ${PKG_TARBALL} \
	--as-cran \
	--run-donttest \

On CRAN, we shouldn't run into this problem because all examples in the documentation are wrapped in @donttest (added in #3338 in response to CRAN submission feedback).

I'm going to test that theory right now with a small test package.

[jameslamb]

ok yeah! I'm very confident now that this is true:

R CMD check --as-cran will not complain about long-running examples, but R CMD check --as-cran --run-donttest will

I created a very very simple package then checked it. That package has a single function with a long-running example wrapped in \donttest{}.

#' @title add_numbers
#' @name add_numbers
#' @description Add two numbers
#' @param x a number
#' @param y a number
#' @export
#' @examples
#' \donttest{
#'    Sys.sleep(30)
#' }
add_numbers <- function(x, y){
    return(x + y)
}

With R CMD check --as-cran slowexamples_0.1.tar.gz:

* checking examples ... OK
* checking examples with --run-donttest ... OK
* checking PDF version of manual ... OK
* checking for non-standard things in the check directory ... OK
* checking for detritus in the temp directory ... OK
* DONE

With R CMD check --as-cran --run-donttest slowexamples_0.1.tar.gz

* checking examples ... NOTE
Examples with CPU (user + system) or elapsed time > 5s
            user system elapsed
add_numbers    0      0  30.011
* checking PDF version of manual ... OK
* checking for non-standard things in the check directory ... OK
* checking for detritus in the temp directory ... OK
* DONE

I saw in https://github.com/wch/r-source/blob/6f8c8c6b9cf1639359dc6bb3abc94a3283ccd673/src/library/tools/R/check.R#L3850 that you can optionally change the threshold for how long examples run with environment variables _R_CHECK_EXAMPLE_TIMING_THRESHOLD_.

with export _R_CHECK_EXAMPLE_TIMING_THRESHOLD_=31; R CMD check --as-cran --run-donttest slowexamples_0.1.tar.gz

* checking examples ... OK
* checking PDF version of manual ... OK
* checking for non-standard things in the check directory ... OK
* checking for detritus in the temp directory ... OK
* DONE

with export _R_CHECK_EXAMPLE_TIMING_THRESHOLD_=29; R CMD check --as-cran --run-donttest slowexamples_0.1.tar.gz

* checking examples ... NOTE
Examples with CPU (user + system) or elapsed time > 29s
             user system elapsed
add_numbers 0.001      0  30.002
* checking PDF version of manual ... OK
* checking for non-standard things in the check directory ... OK
* checking for detritus in the temp directory ... OK
* DONE

So I think we could prevent this test from occasionally failing by setting _R_CHECK_EXAMPLE_TIMING_THRESHOLD_ to a value higher than 5. I also think it would be a good idea to only do that when BUILD_TYPE = "cmake", just in case the behavior of R CMD check --as-cran changes in the future (like how it started running \donttest{} examples automatically in R 4.0.0, https://cran.r-project.org/doc/manuals/r-devel/NEWS.html).

[github-actions]

This issue has been automatically locked since there has not been any recent activity since it was closed. To start a new related discussion, open a new issue at https://github.com/microsoft/LightGBM/issues including a reference to this.