incorrect timing report

[yizhang-yiz]

Describe the bug
fit$time() reports wrong elapsed time. It is significantly different from csv. More importantly, it reports NA for sampling time when fixed_param=TRUE is used.

To Reproduce
Use radon example from posteriordb(I've ported it here: https://github.com/metrumresearchgroup/cmdstan/tree/cross_chain_warmup/examples/radon)

file <- file.path(cmdstan_path(), "examples", "radon", "radon.stan")
mod <- cmdstan_model(file)
fit <- mod$sample(data=file.path(cmdstan_path(), "examples", "radon", "radon.data.R"), 
                  iter_sampling=1, 
                  seed=987, 
                  output_dir=file.path(cmdstan_path(), "examples", "radon"), 
                  fixed_param=TRUE,
                  chains=1,
                  validate_csv=FALSE)
fit$time()
$total
[1] 0.204582

$chains
  chain_id    warmup sampling     total
1        1 0.1101098       NA 0.1733599

CSV file output:

bash-3.2$ grep -A2 "Elapsed" radon-202009291121-1-b07bb3.csv
#  Elapsed Time: 0 seconds (Warm-up)
#                0.000178 seconds (Sampling)
#                0.000178 seconds (Total)

Expected behavior
When fixed_param=TRUE, I expect warmup time = 0, while post-warmup time > 0. I also expect them consistent with what's reported in csv.

Operating system

> sessionInfo()
R version 3.6.2 (2019-12-12)
Platform: x86_64-apple-darwin15.6.0 (64-bit)
Running under: macOS Mojave 10.14.6

Matrix products: default
BLAS:   /Library/Frameworks/R.framework/Versions/3.6/Resources/lib/libRblas.0.dylib
LAPACK: /Library/Frameworks/R.framework/Versions/3.6/Resources/lib/libRlapack.dylib

locale:
[1] en_US.UTF-8/en_US.UTF-8/en_US.UTF-8/C/en_US.UTF-8/en_US.UTF-8

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base     

other attached packages:
[1] cmdstanr_0.1.3

loaded via a namespace (and not attached):
[1] compiler_3.6.2 jsonlite_1.6  

[yizhang-yiz]

Note that in general what fit$time() reports is different from what csv reports. fixed_param=TRUE giving NA sampling time for this example makes it stand out.

I'm also curious why CmdStanRun employs its own timing function(in which I suspect the current issue is rooted) instead of taking in what's in csv.

[rok-cesnovar]

Thanks @yizhang-yiz!

$time() currently reports the time measured in R by Sys.time(), so it's not unexpected that it is not the same as the one in the CSV.

I'm also curious why CmdStanRun employs its own timing function(in which I suspect the current issue is rooted) instead of taking in what's in csv.

The reasoning was mainly because pre-2.24 cmdstan did not report wall time but rather CPU time and the cmdstan timing does not include reading the input data.

In 2.24 we switched to wall time so I would not oppose to moving to just parsing CSV reported times. I/O time not being included also probably only has a marginal effect on execution time in the majority of cases. And those that care for I/O can Sys.time() the $sample() call.

@jgabry what do you think?

[rok-cesnovar]

So times not matching is "by design" and the main design reason is gone, so I am happy to move that back. The fixed_param not working is a bug that we can fix easily or will be gone if we decide to switch to parsing CSV.

[jgabry]

In 2.24 we switched to wall time so I would not oppose to moving to just parsing CSV reported times. I/O time not being included also probably only has a marginal effect on execution time in the majority of cases. And those that care for I/O can Sys.time() the $sample() call.

@jgabry what do you think?

Yeah that sounds good to me.