dplyr and mid-pipe messages

user_3358272 0
Viewed 103

I occasionally have long-running pipes, and I'd like a quick message as stages progress. I'm trying

log_midpipe <- function(x, expr) { expr; x; }

(and have also tried force(expr)), but the message timing is all wrong.

library(dplyr)
sleep <- function(x, time=3) { Sys.sleep(3); x; }
message(Sys.time(), " start"); 
mtcars %>%
  log_midpipe(message(Sys.time(), " hello1")) %>%
  sleep(.) %>%
  log_midpipe(message(Sys.time(), " hello2")) %>%
  sleep(.) %>%
  head(3)
message(Sys.time(), " done")
# 2021-04-16 08:51:09 start
# 2021-04-16 08:51:12 hello2
# 2021-04-16 08:51:15 hello1
# 2021-04-16 08:51:15 done
#                mpg cyl disp  hp drat    wt  qsec vs am gear carb
# Mazda RX4     21.0   6  160 110 3.90 2.620 16.46  0  1    4    4
# Mazda RX4 Wag 21.0   6  160 110 3.90 2.875 17.02  0  1    4    4
# Datsun 710    22.8   4  108  93 3.85 2.320 18.61  1  1    4    1

The out-of-order is (I believe) because of how the arguments are evaluated: lazily, and once converted from a pipe to a nested "parenthetic-like" stack of commands, the "hello1" messaging is the outer-most, which means it is evaluated last.

Is there an easy way to get mid-pipe logging, in real time?

I'm hoping to get

# 2021-04-16 08:51:09 start
# 2021-04-16 08:51:09 hello1
# 2021-04-16 08:51:12 hello2
# 2021-04-16 08:51:15 done
dplyr r
1 Answers

You can get them into the right order by forcing log_midpipe to evaluate x first.

This should work for real examples where the long running code is part of the x in sleep and not a separate call beforehand since Sys.sleep doesn't need any parts of x evaluated.

log_midpipe <- function(x, expr) {
  result <- x
  expr 
  result
}

A sleep that needs x as an input to do its long running process would look like this and prints in the right intervals:

sleep <- function(x, time=3) { 
  result <- x
  Sys.sleep(3)
  result
}
user_54269090
Related