[help] Strange printing behaviour running a dynamic target

[kendonB]

Help

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

Description

No reprex yet as I don't have time to whittle it down.

I run a large pipeline that ends up running a dynamic target and I see this after tar_make()

✔ skip target printedskippedtarget

Then it starts running in the background, then I interrupt using Ctrl+C and it prints the remaining info after the interrupt:

✔ skip target otherskippedtarget
✔ skip target otherskippedtarget
✔ skip target otherskippedtarget
▶ start branch startedtarget_bee8d6df

Any advice to make the troubleshooting/bug hunting simpler?

[kendonB]

To be clear, by 'it starts running', I mean the memory and CPU usage is consistent with it actually running the dynamic target. Furthermore, I see this a few minutes after starting the pipeline:

> targets::tar_progress_summary()
# A tibble: 1 × 6
  skipped started built errored canceled since
    <int>   <int> <int>   <int>    <int> <chr>
1       0       0     0       0        0 5.199 minutes

I wasn't seeing this behaviour when running my last project a couple of weeks ago and I did update to the latest github versions of crew, crew.cluster, and targets.

[kendonB]

Problem exists in 12948f1 but not in 3aa2261.

[kendonB]

hopefully this helps narrow it down!

[kendonB]

@wlandau I think I've ID'd the commit in which the problem turns up

[wlandau]

I am almost positive this is part of a feature, not a bug. In the upcoming release of targets, tar_make() appends to the R console and the metadata files in batches. That means it accumulates a backlog of messages, then prints them out all at once at fixed time intervals. This behavior is a significant reduction in overhead, and it is much kinder to shared/slow file systems which are sensitive to high IOPS. The seconds_reporter and seconds_meta arguments control it, and you can set both to 0 to disable it. In practice, the intervals may be longer than seconds_reporter or seconds_meta if a target is blocking the main process, but you can make sure time-consuming operations happen on workers using crew along with deployment = "worker", storage = "worker", and retrieval = "worker".

[wlandau]

If you have a reprex, I can take a look. seconds_reporter controls the buffering of console messages.

[walrossker]

@wlandau Below is a screenshot of a currently running pipeline of my actual work with seconds_reporter = 0 where it's not printing which target has started, but it's clearly running something.

Strangely, when I run the toy example below with tar_make(example_2, seconds_reporter = 0), it behaves normally and reports the starts and ends of both targets as they occur. Maybe it needs to be a sufficiently large or computationally intensive target to block printing?

  tar_target(example_1, {
    Sys.sleep(20)
    rnorm(1e6)
  }),
  tar_target(example_2, {
    Sys.sleep(20)
    rnorm(1e6) + example_1
  })

[walrossker]

Hi @wlandau, any thoughts on what might be causing print delays here? The vast majority of the time, tar_make() still just shows me the last target that was skipped or built

[wlandau]

I ran the example you posted above:

# _targets.R:
library(targets)

list(
  tar_target(
    example_1, {
      Sys.sleep(20)
      rnorm(1e6)
    }
  ),
  tar_target(
    example_2, {
      Sys.sleep(20)
      rnorm(1e6) + example_1
    }
  )
)

And I see the right printed messages at the right times:

> tar_make()
▶ start target example_1
● built target example_1 [20.048 seconds]
▶ start target example_2
● built target example_2 [20.066 seconds]
▶ end pipeline [40.669 seconds]

So I can't say what's happening on your end. Some speculation:

• Do you have a non-default reporter set in _targets.yaml? You can make sure you have the right reporter using tar_make(reporter = "verbose").
• Are you running an old commit of targets? Maybe try the latest CRAN and latest GitHub versions.

[wlandau]

c.f. https://books.ropensci.org/targets/help.html#write-a-reprex