[general] Troubleshooting strategy for branched pipelines

[jmiahjones-lilly]

Help

• I understand and agree to https://books.ropensci.org/targets/help.html.

Description

I wanted to start a rather open-ended discussion here. On my company's server, I've run the following:

library(targets)
library(tarchetypes)

tar_option_set(
  controller = crew::crew_controller_local(workers = 2)
)

long_running_function = function(idx){
  Sys.sleep(10)
  return(idx**2)
}

list(
  tar_target(idx, command = seq.int(2)),
  tar_target(
    name = result,
    command = long_running_function(idx),
    pattern = map(idx)
  )
)

After defining this as _targets.R, I've run tar_make(use_crew=TRUE) to build out the results. On three tries, I've gotten the following outputs:

1. Last error: ! Native call to processx_exec failed
2. Last error: {crew} worker 1 launched 5 times in a row without completing any tasks.
3. And finally, this one:

> tar_make(use_crew=T)
▶ start target idx
● built target idx [0.516 seconds]
▶ start branch result_5ef4ce3d
▶ start branch result_09b72aa2
● built branch result_09b72aa2 [10.651 seconds]
● built branch result_5ef4ce3d [10.538 seconds]
● built pattern result
▶ end pipeline [2.284 minutes]

Expectation: The pipeline should build in around 12-15 seconds after dispatching two forked processes that complete in 10 seconds each.

How should we make sense of what is going on?

[wlandau]

I tried your example on our on-prem installation of Posit Workbench, both in the regular R console in a fresh terminal tab, and the pipeline completes normally. You might have outdated or incompatible versions of nanonext, mirai, crew, and/or targets. Upgrading these packages to their current CRAN versions might solve the issue.

If that doesn't work, let's try to peel back layers. What happens using crew without targets?

long_running_function <- function(idx){
  Sys.sleep(10)
  return(idx**2)
}
controller <- crew::crew_controller_local(workers = 2)
controller$start()
results <- controller$map(
  command = long_running_function(ids),
  data = list(long_running_function = long_running_function),
  iterate = list(ids = seq_len(2L))
)
results
# # A tibble: 2 × 12
#   name  command result    seconds  seed algorithm error trace warnings launcher worker instance
#   <chr> <chr>   <list>      <dbl> <int> <chr>     <chr> <chr> <chr>    <chr>     <int> <chr>   
# 1 1     <NA>    <dbl [1]>    10.0    NA <NA>      <NA>  <NA>  <NA>     951fbdd…      2 16a0d2e…
# 2 2     <NA>    <dbl [1]>    10.0    NA <NA>      <NA>  <NA>  <NA>     951fbdd…      1 3c5679b…
unlist(results$result)
#> [1] 1 4
controller$terminate()

If targets errors out and crew succeeds, then it's a problem with targets. Otherwise, we might try narrowing it down further to mirai or processx, e.g.:

library(processx)
log <- tempfile()
process <- process$new(
  command = file.path(R.home("bin"), "R"),
  args = c("-e", "Sys.sleep(10)"),
  cleanup = TRUE,
  stdout = log,
  stderr = "2>&1"
)
process$wait()
readLines(log)
process$get_result()

[jmiahjones-lilly]

Thanks for getting back to me. I certainly seemed to be out of date as the messages changed, but this didn't seem to solve the problem.

> library(targets)
> tar_make(use_crew=T)
▶ dispatched target idx
● completed target idx [0.534 seconds]
▶ dispatched branch result_5ef4ce3d
▶ dispatched branch result_09b72aa2
● completed branch result_09b72aa2 [10.645 seconds]
● completed branch result_5ef4ce3d [10.516 seconds]
● completed pattern result
▶ completed pipeline [1.803 minutes]

Crew works without targets:

2 tasks in 22.3s
> results
# A tibble: 2 × 12
  name  command result    seconds  seed algorithm error trace warnings launcher 
  <chr> <chr>   <list>      <dbl> <int> <chr>     <chr> <chr> <chr>    <chr>    
1 1     NA      <dbl [1]>    10.0    NA NA        NA    NA    NA       54f440ed…
2 2     NA      <dbl [1]>    10.0    NA NA        NA    NA    NA       54f440ed…
# ℹ 2 more variables: worker <int>, instance <chr>

processx also works without issue. Is there a recommended way to troubleshoot storage?

[wlandau]

So you still get e.g. "Last error: ! Native call to processx_exec failed"? And the pipeline is taking too long. Maybe try turning on log files with local_log_directory in crew_controller_local(). The log files might reveal clues.

[wlandau]

Just a guess: maybe it's because you are on a busy node of the on-prem server that multiple people are using. That happens from time to time.

[jmiahjones-lilly]

Here we go, now I'm seeing something interesting. In the local log directory, I see several files made (apparently as additional attempts are made to launch a crew worker).

> crew::crew_worker(settings = list(url = "ws://127.0.0.1:40250/2/8e80145cd87b7fa0cd0f6371", autoexit = 15L, cleanup = 1L, output = TRUE, maxtasks = 1, idletime = Inf, walltime = Inf, timerstart = 0L, tls = NULL, rs = c(10407L, -1577515331L, -1619983777L, -1295115692L, -1243315874L, 1120231944L, -1847548930L)), launcher = "3634fd408c6d2c612e46decd", worker = 2L, instance = "8e80145cd87b7fa0cd0f6371")
Error in socket(protocol = "rep") : 2 | Out of memory
Calls: <Anonymous> -> do.call -> <Anonymous> -> socket
Execution halted

Interestingly enough, htop shows that there is plenty of memory available.

Edit: And just to add, I haven't seen either of the previous errors so far, so I think that is one issue resolved.

[wlandau]

Ah, that's something. targets sends global data from _targets.R to workers, whereas crew does not by default (it's opt-in). Maybe your project-level .Rprofile file or user-level ~/.Rprofile file loads a large object into global memory when every R session starts. Would be useful to inspect the the objects that are actually in the local R session, the background process created by tar_make() (print from inside _targets.R), and the objects accessible from each task (especially the global environment; print from inside a task and look at the logs). The lobstr package is helpful (but not perfect) for this.

[wlandau]

Could also be a problem where another user is loading several GB into memory and interfering with your R session on the same node. Happens sometimes.

In the scaled-up case for our environment, I recommend using the cluster instead of local processes. It's easier to reserve memory there. You could start with the example from https://github.com/ropensci/targets/blob/main/tests/hpc/test-crew_sge.R, but with fewer tasks and fewer workers. The script_lines statement is important for loading R as an environment module, and you could look at additional arguments to crew.cluster::crew_controller_sge() for memory and log files. If you use this, then job monitoring via https://wlandau.github.io/crew.cluster/#monitoring is also worth a look. (It's more convenient than qstat/qdel).

[jmiahjones-lilly]

Ah, that's something. targets sends global data from _targets.R to workers, whereas crew does not by default (it's opt-in). Maybe your project-level .Rprofile file or user-level ~/.Rprofile file loads a large object into global memory when every R session starts.

Tried this and got around 50Mb from lobstr::mem_used() running both within the function and in a fresh session. Now that we're on the subject of OOM, I would wonder if there's some sort of SELinux policy or something preventing the processes from forking, but I don't know why it would only occur sporadically.

In the scaled-up case for our environment, I recommend using the cluster instead of local processes.

Yes, I made this reproducible example because I originally noticed a similar pattern was happening with crew's sge clustering. Under tar_make, each individual batched target was taking ~1.5 minutes, and qstat -u $USER showed all the workers were running on the cluster. However, what should have taken a day at most ran through the weekend with minimal progress (~350 / 48,000 targets built). I suspect the same "out of memory" issues were silently occurring on most of those nodes.

[wlandau]

Tried this and got around 50Mb from lobstr::mem_used() running both within the function and in a fresh session. Now that we're on the subject of OOM, I would wonder if there's some sort of SELinux policy or something preventing the processes from forking, but I don't know why it would only occur sporadically.

50 MB seems pretty light. RStudio IDE / Posit Workbench do not allow forking, but thankfully processx does not strictly fork. There might be some restriction on the number of background processes though.

Yes, I made this reproducible example because I originally noticed a similar pattern was happening with crew's sge clustering. Under tar_make, each individual batched target was taking ~1.5 minutes, and qstat -u $USER showed all the workers were running on the cluster. However, what should have taken a day at most ran through the weekend with minimal progress (~350 / 48,000 targets built). I suspect the same "out of memory" issues were silently occurring on most of those nodes.

Upgrading to development crew, crew.cluster, and targets might solve your original problem. Those should be updated on CRAN by early next week. To reduce memory, you could try setting storage = "worker" and retrieval = "worker" as described at https://books.ropensci.org/targets/performance.html, and/or restricting each worker to run only one task as in #1217.

[jmiahjones-lilly]

Just wanted to provide an update for any future readers: shortly after I created this thread, there was a notification that my company's cluster had experienced a service degradation of some kind. After the outage, the code ran well. I would guess this was the root cause of this strange issue.