stdout doesn't flush correctly

[randy3k]

ccall((:printf, "libc"), Int, (Ptr{Uint8},), "abc");

It happens when I select "run all". It works fine if I only run that cell. It may be also related to #172.

Edit:

It also seems that flushing doesn't help.

[stevengj]

What operating system do you have? This may be a libc problem.

[randy3k]

I am using Mac OS X 10.10, julia 0.3.1.

[randy3k]

interesting enough, if i set IJulia.set_verbose(), it works expertedly.

[stevengj]

I think that this is an IPython issue. The basic problem here is that stdio output is sent to IPython via stream messages which aren't attached to any particular output cell. So, when you execute many cells in quick succession, there is a race condition that occurs: depending on when the stream message arrives at IPython, that determines where it is displayed.

Turning on verbose mode probably slows things down just enough that the stream message arrives before IPython moves on to the next code cell.

cc: @minrk

[minrk]

There shouldn't be any race condition on the frontend. The kernel decides where output goes by setting the parent_header of output messages. Are there race conditions or async events happening in the kernel itself? Can the idle message that indicates a cell is complete be sent before an output message?

[randy3k]

so, is it possible to attach stream message to a output cell?

[randy3k]

After some preliminary investigation, I found that the reader never works. takebuf_string(read_stdout.buffer) is always empty no matter what.
The flushing of stdout is done by the watcher. Since the watcher is running async. It also explains why the output is out of async.

[randy3k]

Sorry for the multiple references...I kept doing stupid things...you should check this one https://github.com/randy3k/IJulia.jl/commit/9104817dde3f7cb24e66d10d3ee15c8c74dd351f

[randy3k]

It seems that the fix only relief the problem but not solve the problem. If display invokes a c call to printf, we should also flush the stdout.

[randy3k]

Check https://github.com/JuliaLang/IJulia.jl/pull/239/files I believe I solved it.

[vtjnash]

This is tough, since Julia uses async io everywhere (like JavaScript/nodejs) unlike more traditional languages, which sometimes are more synchronous. flush is an extremely weak guarantee ("make sure my libc file buffers are emptied"), but for something small and local also happens to be enough, since the kernel likes to transfer small amounts of data eagerly. Readavailable is the equivalent of flush on the receive side ("give me everything that was in my libc buffer already"). Both of these fail to acknowledge that io needs actual external structure (such as a \0 inserted into the stream), not timing-based assumptions.

[stevengj]

(Note that, if I recall correctly, IPython does not even attempt to capture stdout from external C code, only Python stdout, so we are being a bit more ambitious here and life is a bit harder here because we are dependent on libc.)

[vtjnash]

What does IPython do with data printed from a thread? That is quite similar to life in Julia

[minrk]

What does IPython do with data printed from a thread?

Routing is handled entirely by the msg_id in the parent_header. Each msg_id is associated with an output area. Since IPython stores the parent in a single location that is looked up when output messages are constructed, background thread IO will be associated with the most recently executed cell.

[stevengj]

IJulia also stores the parent in a single location (the global execute_msg) that is looked up when output messages are constructed, so the behavior is similar.

The issue here is just to make sure that buffers are flushed at the end of an execute request, so that we capture all available I/O to send at that time. If the I/O system decides not to make the bytes available to read until later (e.g. because of some hidden buffering?) then the output will get attached to a later execution cell... IJulia has no way of knowing where stdio should go except via the time that the bytes are available.

[randy3k]

it seems that flush_cstdio() is not synchronized, we have to add a little delay. https://github.com/randy3k/IJulia.jl/commit/a7a2d96b98fcc38c325f3820f3041640e528b19c

edit: also, we have to flush again after pyout for something like the first cell.

[stevengj]

Adding some arbitrary delay seems quite fragile to me. I would rather call some (platform-specific?) "really flush this stream" library routine, but that might not always be possible. (e.g. consider the case of an external library that uses a custom buffering I/O library ... for example, some Fortran implementations might do this).

[randy3k]

i agree, it is just to demonstrate what was causing the problem.

[randy3k]

thing gets more complicated if we want to align the "foo" and "a" in the above example, since ipython doesn't know the order of execution..

[stevengj]

Julia doesn't know the order of execution either: it doesn't know when or where anything in the stdout buffer came from, especially output originating in external libraries. The basic issue is that there are multiple I/O buffers involved here, some of which are not under Julia's control.