Display printed output while code is still running

[takluyver]

The current implementation buffers printed output in a textConnection() until the user code has finished executing, then sends a single stream message with all the text. So you see no output until the cell finishes.

If we can implement an object suitable to pass to sink, output can be displayed as it is printed.

[karthik]

We'll need to replace textConnection at some point. More when I'm back at the laptop.

On Tue, Mar 25, 2014 at 6:49 PM, Thomas Kluyver notifications@github.com
wrote:

The current implementation buffers printed output in a textConnection() until the user code has finished executing, then sends a single stream message with all the text. So you see no output until the cell finishes.

If we can implement an object suitable to pass to sink, output can be displayed as it is printed.

Reply to this email directly or view it on GitHub:
#3

[takluyver]

I hoped that this would be fixed by the switch to evaluate, but it looks like simply printing doesn't fire an event that causes it to process output. If I run this, all the output is still delayed until it finishes:

for (x in 1:10) {
    print(x)
    Sys.sleep(1)
}

[flying-sheep]

here is info about the internals

for reference: the code for connections is in /src/main/connections.c (do_writelines())

the function needs an Rconnection arg, which is a quite huge struct. do we have to instantiate one of those?

/edit: the API is private, so this isn’t the way to go…

[flying-sheep]

we could maybe use watchout from evaluate or similar code.

[takluyver]

See also discussion on #55.

[jankatins]

Not, that the python side also doesn't send any printed output during the evaluation until some sys.stdout.flush() is happening (which seems to be done at some place, but not always)

[takluyver]

In most cases, IPython can update output ~live. I think it flushes based on the time between successive writes to stdout.

[jankatins]

@takluyver I just had jupyter/jupyter_client#7, where without the flush nothing is displayed :-)

[takluyver]

I suspect there's a corner case where there's a short burst of things being written, followed by a long gap where nothing is printed. That's harder to resolve without using threads.

[stevengj]

In Julia, we run a green thread that blocks on the file descriptor of stdout, flushes the output to a stream message when something is available to read, and then sleeps for 100ms to allow output to accumulate before blocking again.

Since this is a green thread, however, it can only wake up when something in Julia calls yield() (e.g. most I/O will do this).

[jankatins]

More examples in #230 -> it seems that this is only happening when you use a loop and the blocking process is in the loop. Also flushing the stdout doesn't matter:

for (i in 1:5){
    print("text")
    flush.console()
    flush(stdout())
    Sys.sleep(1)
    }

Could it be that evaluate caches stdout?

Update:

for (i in 1:5){
  print("text")
  Sys.sleep(1)
}
print("break")
for (i in 1:5){
  print("text")
  Sys.sleep(1)
}

-> it prints stdout in two bursts: the first 5 "text" lines + "break" and then the next 5 lines "text". This looks like evaluate only releases the text output once a "unit" of code (aka a line or multiple lines in case of a loop) is evaluated.

[jankatins]

Ok, looks like an evaluate issue:

library(evaluate)

code <- "for (i in 1:5){
print(\"text\")
message('message')
Sys.sleep(1)
}
print(\"break\")
for (i in 1:5){
  print(\"text\")
  Sys.sleep(1)
}"


l = list()
txt <- function(o, type) {
  t <- paste(o, collapse = '\n')
  t <- paste("OUT: ", t)
  l[length(l)+1] <<- paste("T: ",Sys.time()," type: ", type, "  -> ", t)
}
oh <- new_output_handler(source = identity, 
                         text = function(o) txt(o, "text"), 
                         graphics = identity,
                         message = function(o) txt(o, "message"), 
                         warning = function(o) txt(o, "warn"), 
                         error = function(o) txt(o, "error"), 
                         value = identity)



x <- evaluate(code, output_handler = oh)
l

[[1]]
[1] "T:  2015-12-15 17:44:36  type:  text   ->  OUT:  [1] \"text\"\n"

[[2]]
[1] "T:  2015-12-15 17:44:36  type:  message   ->  OUT:  simpleMessage in message(\"message\"): message\n\n"

[[3]]
[1] "T:  2015-12-15 17:44:37  type:  text   ->  OUT:  [1] \"text\"\n"

[[4]]
[1] "T:  2015-12-15 17:44:37  type:  message   ->  OUT:  simpleMessage in message(\"message\"): message\n\n"

[[5]]
[1] "T:  2015-12-15 17:44:38  type:  text   ->  OUT:  [1] \"text\"\n"

[[6]]
[1] "T:  2015-12-15 17:44:38  type:  message   ->  OUT:  simpleMessage in message(\"message\"): message\n\n"

[[7]]
[1] "T:  2015-12-15 17:44:39  type:  text   ->  OUT:  [1] \"text\"\n"

[[8]]
[1] "T:  2015-12-15 17:44:39  type:  message   ->  OUT:  simpleMessage in message(\"message\"): message\n\n"

[[9]]
[1] "T:  2015-12-15 17:44:40  type:  text   ->  OUT:  [1] \"text\"\n"

[[10]]
[1] "T:  2015-12-15 17:44:40  type:  message   ->  OUT:  simpleMessage in message(\"message\"): message\n\n"

[[11]]
[1] "T:  2015-12-15 17:44:41  type:  text   ->  OUT:  [1] \"break\"\n"

[[12]]
[1] "T:  2015-12-15 17:44:46  type:  text   ->  OUT:  [1] \"text\"\n[1] \"text\"\n[1] \"text\"\n[1] \"text\"\n[1] \"text\"\n"

-> the second 5 "text" things come in in one message

[jankatins]

And here is the problem: https://github.com/hadley/evaluate/blob/eb304135a5370a1ffad80717c50fe152ebeb7b4f/R/eval.r#L148

• each expression in a code block (=each line or in case of a loop the complete loop?) is evaluated one after another in a loop
• messages (and errors) are handled directly when they come up thanks to withCallingHandlers(..., message = mHandler)) (line 149) and trigger mhandler which calls handle_condition which calls handle_output which compares the current output with the previous and sends the diff to the text handler which was defined in the output_handler object which we passed to evaluate.
• if no message/... was handled, the rest of the output will now be handled in L152

So unless there is any way to "observe" the content of a variable (threads? something in withCallingHandlers?) I don't think there is any way to make this work while still using evaluate.

RStudio uses a rsession.exe, not sure how hard it is to build the kernel around that... Probably because we lose the rich display system :-/

[flying-sheep]

great detective work!

[takluyver]

We have a plan to facilitate this at some point for all kernels by running them inside a wrapper process that captures stdout/stderr at the OS level. As and when we do that, we won't need to worry about capturing printed output in R; we can just write it to the process' real stdout, and it will get captured externally.

[jankatins]

Just tried if there is a way to observe the inputs to a connection: http://biostatmatt.com/R/R-conn-ints.pdf So making this work in the current system would require:

• a new callbackTextConnection type which needs to be implemented in C?
• r must have the ability to call r code from the c code which seems to be possible: http://stackoverflow.com/questions/7457635/calling-r-function-from-c
• Adding a patch to evaluate to use this...

[takluyver]

I'm not keen on the idea of maintaining anything written in C.

[jankatins]

Hm, wild idea: if evaluate would overwrite flush.console() or flush(stdout()) with a version which would trigger handle_output, that would be a nice workaround...

[jankatins]

I opened r-lib/evaluate#61 for the "overwrite flush.console idea".

[jankatins]

r-lib/evaluate#62 has the PR which implements flushing... After (and if...) that is released, we need to add enable_flush=TRUE to all evaluate calls and adjust our deps...

[jankatins]

Unfortunately no reply yet in r-lib/evaluate#62 :-( Has anybody here any connections to the devs? My last interaction with R devs left me a little scared, so I won't do a simple "ping" in the PR ... :-/

[takluyver]

Hadley Wickham is really nice, but I haven't met the person who now maintains evaluate. I've risked a ping on the PR anyway ;-)

[flying-sheep]

i know noone there 😐

[alexvpickering]

I don't know if its the same cause, but I'm getting a similar sort of bug with a loop that prints some text then draws a plot. Instead of getting the expected behaviour (text --> plot --> text --> plot --> etc.), it all gets jumbled up (text --> text --> plot --> text --> plot --> etc). Very similar effect in IPython was fixed with sys.stdout.flush()

[jankatins]

@alexvpickering Yep, this is the same cause... See also #295 for even more fun with this kind of things...

[ghost]

As far as I remember, this could now be closed by adding this code before calling evaluate: r-lib/evaluate#62 (comment)

evaluate::inject_funs(
  flush.console = function() { base::flush.console(); evaluate::flush_console() },
  flush = function(con) { base::flush(con); evaluate::flush_console() }
)

[flying-sheep]

oh nice! anyone want to do a PR or should we do it?

[flying-sheep]

fixed in c5daa14