Drake slowing down as I build a larger plan

General
1

As I'm building a drake plan out to include more and more steps, I'm finding that make(plan) and vis_drake_graph() are taking longer to start executing.

For instance, to visualize the dependency graph in this example notebook takes about 1.25 seconds. My drake plan on the other hand has 35 targets and it takes 17 seconds to run the same command. There is a similar delay for targets for make(plan) to start creating targets.

I'm guessing the triggers are taking long to compute, but I'm not sure what to try here to confirm that without losing some large, cached targets. What would be your game plan on diagnosing this delay safely?

2

Since drake works with R objects instead of files, it needs to do more work than other build systems. It needs to read metadata to check if each target is up to date, it needs to load the required targets into memory, and it needs to store newly built targets and metadata in the cache. All these tiny interactions with the file system tend to add up.

I have been trying to speed up the preprocessing (profiling studies here) but much of the overhead is unavoidable. Dynamic branching reduces the number of static targets, which tends to make things faster to start up. (Currently only supported in the development version.)

But I am surprised that 35 targets takes so long for you. What kind of system are you using, and what does the plan look like? If you post a reproducible example here, I can profile it and try to speed it up.

Speaking more generally, you are likely to get faster responses about drake-related issues if you post to the issue tracker on GitHub. I get automatic notifications from GitHub, but not from targeted questions on this forum.

1 Like
3

Easier: let’s see if we can find the bottleneck in your 35-target plan. Would you run the following and then send me “your_samples.rprof”? (And the slow code too if you can?)

Rprof(filename = “your_samples.rprof”)

# Your slow code goes here.

Rprof(NULL)

Also, what system are you running?

4

Hi Will!

I appreciate the response! I pasted the results of running Rprof below. I couldn't upload the file because only images/pdf can be uploaded here. I am running Windows 10.

I cannot send the slow code as is, but if I worked through it and created a toy example I could try to recreate the issue. Let me know if that's a good idea. In general it's not straightforward for me to create a reproducible example because, in short, it's secret :wink:.

Rprof

structure(list(self.time = c(7.14, 4.3, 4.24, 3.58, 2.52, 2.46,
2.3, 2.22, 2.2, 2.08, 2.08, 2.04, 1.56, 1.44, 1.42, 1.38, 1.36,
1.24, 1.22, 1.22, 1.22, 1.1, 1.06, 1, 0.84, 0.72, 0.68, 0.66,
0.62, 0.52, 0.52, 0.48, 0.46, 0.44, 0.38, 0.34, 0.34, 0.28, 0.28,
0.26, 0.26, 0.26, 0.24, 0.24, 0.24, 0.24, 0.22, 0.2, 0.2, 0.2,
0.18, 0.16, 0.14, 0.14, 0.14, 0.14, 0.12, 0.12, 0.12, 0.12, 0.1,
0.1, 0.1, 0.1, 0.1, 0.1, 0.08, 0.08, 0.08, 0.08, 0.08, 0.08,
0.08, 0.08, 0.08, 0.08, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06,
0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06,
0.06, 0.06, 0.06, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04,
0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04,
0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04,
0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02), self.pct = c(10.2, 6.14,
6.06, 5.12, 3.6, 3.52, 3.29, 3.17, 3.14, 2.97, 2.97, 2.92, 2.23,
2.06, 2.03, 1.97, 1.94, 1.77, 1.74, 1.74, 1.74, 1.57, 1.51, 1.43,
1.2, 1.03, 0.97, 0.94, 0.89, 0.74, 0.74, 0.69, 0.66, 0.63, 0.54,
0.49, 0.49, 0.4, 0.4, 0.37, 0.37, 0.37, 0.34, 0.34, 0.34, 0.34,
0.31, 0.29, 0.29, 0.29, 0.26, 0.23, 0.2, 0.2, 0.2, 0.2, 0.17,
0.17, 0.17, 0.17, 0.14, 0.14, 0.14, 0.14, 0.14, 0.14, 0.11, 0.11,
0.11, 0.11, 0.11, 0.11, 0.11, 0.11, 0.11, 0.11, 0.09, 0.09, 0.09,
0.09, 0.09, 0.09, 0.09, 0.09, 0.09, 0.09, 0.09, 0.09, 0.09, 0.09,
0.09, 0.09, 0.09, 0.09, 0.09, 0.09, 0.09, 0.06, 0.06, 0.06, 0.06,
0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06,
0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06,
0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03),
total.time = c(7.14, 4.34, 5.12, 6.56, 47.2, 2.46, 2.36,
3.36, 3.92, 25.3, 2.08, 2.04, 2.48, 8.96, 1.44, 1.38, 3.92,
31.9, 8.68, 1.78, 1.22, 1.16, 1.06, 4.76, 1, 2.46, 0.72,
0.66, 2.94, 0.58, 0.52, 0.54, 0.52, 30.92, 0.38, 24.96, 0.36,
2.94, 2.14, 0.28, 0.26, 0.26, 0.36, 0.24, 0.24, 0.24, 0.22,
32.28, 1.7, 0.42, 0.26, 1.74, 2.6, 1.58, 0.16, 0.14, 1.6,
0.12, 0.12, 0.12, 0.3, 0.24, 0.14, 0.1, 0.1, 0.1, 3.34, 1.42,
0.8, 0.56, 0.32, 0.24, 0.16, 0.1, 0.1, 0.08, 4.88, 4.82,
4.8, 3.52, 1.6, 1.44, 0.86, 0.44, 0.28, 0.26, 0.24, 0.16,
0.14, 0.12, 0.12, 0.1, 0.08, 0.06, 0.06, 0.06, 0.06, 32.32,
32.3, 8.58, 3.24, 1.48, 1.36, 1.04, 0.86, 0.68, 0.66, 0.52,
0.46, 0.4, 0.2, 0.16, 0.12, 0.1, 0.08, 0.06, 0.06, 0.06,
0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.04,
0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 16.56, 11.5, 9.2, 2.56,
1.6, 1.58, 1.5, 1.42, 1.08, 1.02, 0.86, 0.72, 0.7, 0.66,
0.56, 0.56, 0.46, 0.34, 0.34, 0.26, 0.22, 0.2, 0.2, 0.18,
0.16, 0.16, 0.16, 0.16, 0.12, 0.12, 0.12, 0.12, 0.1, 0.1,
0.08, 0.08, 0.08, 0.06, 0.06, 0.06, 0.06, 0.06, 0.04, 0.04,
0.04, 0.04, 0.04, 0.04, 0.04, 0.04, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02,
0.02, 0.02, 0.02, 0.02), total.pct = c(10.2, 6.2, 7.32, 9.37,
67.45, 3.52, 3.37, 4.8, 5.6, 36.15, 2.97, 2.92, 3.54, 12.8,
2.06, 1.97, 5.6, 45.58, 12.4, 2.54, 1.74, 1.66, 1.51, 6.8,
1.43, 3.52, 1.03, 0.94, 4.2, 0.83, 0.74, 0.77, 0.74, 44.18,
0.54, 35.67, 0.51, 4.2, 3.06, 0.4, 0.37, 0.37, 0.51, 0.34,
0.34, 0.34, 0.31, 46.13, 2.43, 0.6, 0.37, 2.49, 3.72, 2.26,
0.23, 0.2, 2.29, 0.17, 0.17, 0.17, 0.43, 0.34, 0.2, 0.14,
0.14, 0.14, 4.77, 2.03, 1.14, 0.8, 0.46, 0.34, 0.23, 0.14,
0.14, 0.11, 6.97, 6.89, 6.86, 5.03, 2.29, 2.06, 1.23, 0.63,
0.4, 0.37, 0.34, 0.23, 0.2, 0.17, 0.17, 0.14, 0.11, 0.09,
0.09, 0.09, 0.09, 46.18, 46.16, 12.26, 4.63, 2.11, 1.94,
1.49, 1.23, 0.97, 0.94, 0.74, 0.66, 0.57, 0.29, 0.23, 0.17,
0.14, 0.11, 0.09, 0.09, 0.09, 0.06, 0.06, 0.06, 0.06, 0.06,
0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06,
0.06, 23.66, 16.43, 13.15, 3.66, 2.29, 2.26, 2.14, 2.03,
1.54, 1.46, 1.23, 1.03, 1, 0.94, 0.8, 0.8, 0.66, 0.49, 0.49,
0.37, 0.31, 0.29, 0.29, 0.26, 0.23, 0.23, 0.23, 0.23, 0.17,
0.17, 0.17, 0.17, 0.14, 0.14, 0.11, 0.11, 0.11, 0.09, 0.09,
0.09, 0.09, 0.09, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06, 0.06,
0.06, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03,
0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03, 0.03)), row.names = c(""writeBin"",
"".Call"", ""left_join_impl"", ""$"", """",
"".getClassesFromCache"", ""file"", ""readRDS"", ""digest::digest"",
""FUN"", ""serialize"", ""as.environment"", ""match.arg"",
""try_write_serialized_rds"", "".deparseOpts"", ""exists"",
""mutate_impl"", ""withCallingHandlers"", ""vapply"", ""::"",
""parse_lazy_arg"", ""factor"", ""gzfile"", ""%||%"",
""get"", ""readLines"", "".jnew"", ""rev"", ""file.exists"",
""as.list"", ""file.rename"", ""lazyLoadDBfetch"", ""NextMethod"",
""eval"", ""pmatch"", ""lapply"", ""replace_na.data.frame"",
""is"", ""manip_apply_syms"", ""is_quosure"", ""match.fun"",
""names"", ""is_symbol"", "".External2"", ""bind_rows_"",
""inDL"", ""is_string"", ""doTryCatch"", ""file.path"",
""%in%"", ""parse_vector_"", ""stopifnot"", ""getClassDef"",
""group_vars"", ""get0"", ""is_null"", ""structure"",
""as.character"", ""as.POSIXlt.POSIXct"", ""close.connection"",
""unique"", ""tbl_vars_dispatch"", ""groups"", ""isBaseNamespace"",
""logical"", ""sys.parent"", ""asNamespace"", ""map_mold"",
""endots"", ""getExportedValue"", ""call2"", ""arg_match"",
""sys.function"", "".identC"", ""unique.default"", ""file.info"",
""mutate"", ""mutate.tbl_df"", ""fun"", ""self$get_value"",
""self$name_key"", ""deparse_names"", ""evalq"", ""order"",
""getNamespace"", ""getGeneric"", ""match.call"", ""filter_impl"",
""c"", ""dynGet"", ""file.copy"", ""paste0"", ""isTRUE"",
"".External"", ""as.POSIXlt.Date"", ""is_logical"", ""list.files"",
""tryCatch"", ""tryCatchOne"", ""freduce"", ""namespaceImportFrom"",
""paste"", ""setdiff"", ""map_if"", ""map_chr"", ""probe"",
""writeLines"", ""sort.int"", ""as.vector"", ""hash"",
"".difftime"", ""close"", "".resetInheritedMethods"", ""unlist"",
""is_character"", "".getGenericFromCacheTable"", ""sys.call"",
""unlink"", ""class"", ""file.create"", ""findLocals1"",
""grepl"", ""groups.default"", ""importIntoEnv"", ""is_formulaish"",
""list"", ""ls"", ""mkenv"", ""node_cdr"", ""normalizePath"",
""parent.frame"", ""rank"", ""sample.int"", ""splice"",
""dcst_set"", ""self$set_value"", ""drake_meta_"", ""ifelse"",
""just_try"", ""extends"", ""tbl_vars"", ""methods::cacheMetaData"",
"".updateMethodsInTable"", ""tempfile"", ""enquos"", ""self$name_hash"",
""Ops.numeric_version"", ""split"", "".checkGroupSigLength"",
""base::setdiff"", ""month.default"", ""initialize"", ""registerS3methods"",
""getGroupMembers"", "".recMembers"", "".encode_numeric_version"",
""as_fun_list"", ""validObject"", "".registerS3method"",
""checkConflicts"", ""eval_bare"", ""purrr::map_chr"",
"".getGeneric"", ""as.igraph.vs"", ""rbind"", ""tbl_vars.data.frame"",
"".mergeMethodsTable"", ""as.numeric_version"", ""c.numeric_version"",
""methods::is"", ""setNamespaceInfo"", "".make_numeric_version"",
"">="", ""is_formula"", ""is_function"", ""set_names"",
""$<-"", "".findInheritedMethods"", ""assert_scalar"",
""assign"", ""checkSkipLoopCntxt"", ""environment"", ""filelock::lock"",
""which"", ""&"", "".assignOverBinding"", "".cacheGenericTable"",
"".getNamespaceInfo"", "".makeSortEnum"", ""["", ""[["",
""[[<-.data.frame"", ""any"", ""anyDuplicated"", ""as.Date.POSIXct"",
""as.list.default"", ""as.pairlist"", ""base::serialize"",
""character"", ""check_names_non_null"", ""colors"", ""delayedAssign"",
""dir.exists"", ""dots.or.missing"", ""exprs_auto_name"",
""file.append"", ""get_vs_graph"", ""getDLLRegisteredRoutines.DLLInfo"",
""grep"", ""gsub"", ""is.factor"", ""is.na"", ""is.numeric"",
""is_atomic"", ""is_fun_list"", ""is_grouped_df"", ""is_list"",
""is_scalar_vector"", ""isFALSE"", ""isGeneric"", ""isNamespace"",
""isS4"", ""length"", ""nzchar"", ""parent.env"", ""slot"",
""startsWith"", ""strrep"", ""Sys.info"", ""Sys.setenv"",
""utils::file_test"", ""withRestarts""), class = "data.frame")

5

Thanks Adam, I think we're on the right track. It would really help if you would post the toy example that recreates the issue. Unfortunately, I cannot read your Rprof() output into profile::read_rprof(). The format is somehow different. What version of R (and drake) are you using?) When I run Rprof(), the contents of the file look something like this.

sample.interval=20000
"lazyLoadDBfetch" "cmpCallSymFun" "cmpCall" "cmp" "cmpForBody" "h" "tryInline" "cmpCall" "cmp" "genCode" "compile" "doTryCatch" "tryCatchOne" "tryCatchList" "tryCatch" "compiler:::tryCompile" 
".deparseOpts" "deparse" "paste" "FUN" "vapply" "model.matrix.default" "model.matrix" "lm" 
"model.matrix.default" "model.matrix" "lm" 
"structure" "lm.fit" "lm" 
"paste" "FUN" "vapply" ".getXlevels" "lm" 
"length" "append" "FUN" "lapply" "FUN" "lapply" "findLocalsList1" "findLocalsList" "findLocals" "as.vector" "unique" "union" "addCenvVars" "compile" "doTryCatch" "tryCatchOne" "tryCatchList" "tryCatch" "compiler:::tryCompile" 
"dim.data.frame" "dim" "dim" "nrow" "logical" "na.omit.data.frame" "na.omit" ".External2" "model.frame.default" "stats::model.frame" "eval" "eval" "lm"

By the way, I did notice some extra slowness on Windows 10, and I tracked it down to storr: https://github.com/richfitz/storr/issues/116. I submitted a PR with a potential improvement: https://github.com/richfitz/storr/pull/117.

6

Oops. I should have tried it myself. Try again? I've edited it. The whole rprof exceeds the character limit so I've limited it to only the by.self output.

I'm using R 3.5.2 and drake 7.6.2.

7

Still getting an error.

> profile::read_rprof("rprof.txt")
Error in `$<-.data.frame`(`*tmp*`, "value", value = 1L) : 
  replacement has 1 row, data has 0
In addition: Warning messages:
1: In readLines(path) : incomplete final line found on 'rprof.txt'
2: Incomplete sampling information, increase bufsize in `Rprof()` or `start_profiler()` call

Would you open an issue at https://github.com/ropensci/drake/issues and attach the whole Rprof file as a zip archive?

8

Ah! That's a good alternative. Thanks for your patience Will. https://github.com/ropensci/drake/issues/1086

A side note: I was expecting you to execute that chunk of code (it's the output of a dput()) to recreate the rprof object, maybe that's why it didn't work? I've already uploaded the zip, but just curious.

9

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.