Accurately capturing timing of pipelines and targets with tar_make_clustermq()

[ajjitn]

When using tar_make_clustermq() to run a pipeline with dynamic branching, what is the appropriate way to access a) the total time the last pipeline build took and the b) time it took for individual target to build? For example, with this dummy _targets.R script:

## Load your packages
library(targets)
library(tidyverse)
library(stats)

## Set multicore options
options(clustermq.scheduler = "multicore")

## Destroy pipeline and define functions
tar_destroy()
add_one = function(x, secs = 0.1){
  Sys.sleep(secs)
  return(x + 1)
  
}

## Set plan
tar_plan(
  tar_target(x, 1:100,
             iteration = "vector"),
  tar_target(y, 
             add_one(x),
             pattern = map(x))

)

Running tar_make_clustermq(workers = 12) takes about 3.6 seconds for the full pipeline to run based on the console output.

Is this value of 3.6 stored somewhere in the targets metadata and accessible after the pipeline is run?

I know that tar_meta() contains a seconds column which measures the time for each target, but that column seems to represent the total computation time across all cores, not the actual human time that has passed. So no matter what value of workers I feed into tar_make_clustermq(), the output of tar_meta(names = y, fields = c("name", "type", "seconds")) always looks like:

Is there a way to see the actual human time it took to build a target instead of the total computation time across all cores?

[wlandau]

As you say, targets computes the elapsed runtime at a granular level. For a non-branching target or an individual branch, this is just the number of seconds it took to run the last time it was not skipped. For a branching target, the runtime is the sum of the last runtimes of all the branches. These results do not depend on which targets were skipped last, and they do not depend on the number of parallel workers, which could vary from run to run based on the user's choice. These decisions make the reported times more reliable and consistent than otherwise.

If you invoke tar_make_clustermq() from inside a script and run the script with R CMD BATCH, then the .Rout file will report the elapsed time at the bottom. The "Master: [3.6s 21.1% CPU]..." line is from clustermq directly, and the time may only reflect a fraction of the work that was completed if you have time-consuming targets with deployment = "main".

[ajjitn]

@wlandau This all makes sense! Can I submit a pull request to https://github.com/ropensci-books/targets to add this very helpful information on the secondscolumn in tar_meta()? Perhaps in section 2.7 on metadata or section 5.8 on performance? Or alternatively could this perhaps just live on the help page for tar_meta() (happy to open a PR for that as well)?

For context, I routinely use the results of tar_meta() to see which targets were slow to build and to see if I can make them faster, either with more performant/efficient R code or by throwing more cores at the pipeline. And it was confusing to see the amount of cores have no effect based on what I expected the seconds column to measure.

[wlandau]

Sure @ajjitn, a PR would be great. I would prefer to use the tar_meta() help file for this. We should explain that for targets of type "pattern", the "seconds" column is the sum of runtimes from all the branches, regardless of any parallelism used via tar_make_clustermq() or tar_make_future(). (On the other hand, if you do your own multicore parallelism inside an individual "stem" or branch targets, the recorded seconds may go down.)