Strange interaction with redirect_stdout

[jonathanBieler]

I'm trying to display Julia output in a GtkWidget but it's kind of slow and feels sluggish. I put together this minimal example (coming from IJulia):

function send_stream(rd::IO, name::AbstractString)
    nb = nb_available(rd)
    if nb > 0
        d = readbytes(rd, nb)
        s = try
            bytestring(d)
        catch
        end
        #do something with s
    end
end

function watch_stream(rd::IO, name::AbstractString)
    try
        while !eof(rd) # blocks until something is available
            send_stream(rd, name)
            sleep(0.01) # a little delay to accumulate output
        end
    catch e
        # the IPython manager may send us a SIGINT if the user
        # chooses to interrupt the kernel; don't crash on this
        if isa(e, InterruptException)
            watch_stream(rd, name)
        else
            rethrow()
        end
    end
end

global read_stdout
read_stdout, wr = redirect_stdout()
function watch_stdio()
    @async watch_stream(read_stdout, "stdout")
end
watch_stdio()

Calling a print command (e.g. print(randn(100))) in the REPL is very fast (after compilation). However as soon as you use Gtk (using Gtk) it becomes very slow (seems like 2 seconds on my computer). I've tried with a few other packages but Gtk seems to be the only one interacting.

Any idea what's going on and how to fix that?

[vtjnash]

what platform? I see no difference on OSX.

[jonathanBieler]

Windows 7.

I've been commenting out parts of Gtk.jl and the problem appears as soon as events.jl get included.

Edit: I did the same thing in events.jl and the slowdown appears as soon as __init__() is defined:

https://github.com/JuliaLang/Gtk.jl/blob/49f0cc2fb2225d91f96abe0467cfba1ec87dfc6a/src/events.jl#L9

Maybe not surprising since that starts gtk's main loop .

[vtjnash]

what happens if you change the 100 at https://github.com/JuliaLang/Gtk.jl/blob/49f0cc2fb2225d91f96abe0467cfba1ec87dfc6a/src/GLib/signals.jl#L358 to something smaller, like 10?

[jonathanBieler]

It does decrease the time a bit (and allocates more), I went down to 1 which seems to be the fastest:

@time println(rand(100))

1:
2.011359 seconds (3.64 M allocations: 55.695 MB, 0.11% gc time)
10:
2.047513 seconds (1.41 M allocations: 22.999 MB, 0.17% gc time)
100:
2.352942 seconds (939.67 k allocations: 14.448 MB, 0.05% gc time)

That said it does also depends on the sleep time in watch_stream, this is the same thing with sleep(0.05):

1:
0.450914 seconds (788.68 k allocations: 12.066 MB)
10:
2.853042 seconds (1.10 M allocations: 16.892 MB)

I ran the profiler on that last case, maybe there's something in there:

https://gist.github.com/jonathanBieler/1e6fd8b0e3df3d3d1411

[yakir12]

For what it's worth, putting yield() before line 82 in selectors.jl solves issue #297.

[tknopp]

have you tried open "Gtk.@sigatom open_dialog(...) " ?

[yakir12]

I have now (I first removed the yield), and it didn't help.

[jonathanBieler]

I don't really understand what's going on but I'm not sure the yield is really the proper solution. What I saw in the profiling above is that the lines

1391 ...0.4\Gtk\src\events.jl; gtk_main; line: 1
 1391 ...k\src\GLib\signals.jl; g_sigatom; line: 168
  1391 ...0.4\Gtk\src\events.jl; anonymous; line: 2

are called way more on windows than on OS X. This slows down everything. But in some cases it would even freeze completely, like if it was spending all its time switching between tasks or something like that. It seems like a performance or design issue. Since the issue doesn't occur in OS X, there's something to investigate there.

[tknopp]

Yes it would be great to have somebody that understands this better to resolve these issues. If I understand it correctly (@vtjnash may correct me) we do not use the Gtk event loop but have a dedicated task that draws everything on its own.