Busy loop on profiling external Cmd's

[binarybana]

julia> require("Profile")
julia> using SProfile 
julia> function test()
       run(`echo hi`)
       end
# methods for generic function test
test() at none:2

julia> test()
hi
julia> @sprofile test() 

Where the last line hangs at 100% CPU for (at least) several minutes on my Ubuntu 13.04 system running a recent version of Julia 0.2-.

Thanks!

[timholy]

Sorry for the delay, I had no laptop or internet for several days.

I can indeed replicate this, although it's intermittent: once I got it to run through fine. A simple workaround is to increase the delay, e.g., sprofile_init(10^6,10^7).

It's hanging at the ccall to :jl_spawn in _jl_spawn. This is not an area of Julia that I know well, so I'm CCing others @vtjnash, @loladiro, @JeffBezanson.

A gist to facilitate debugging is here: https://gist.github.com/timholy/5782437. I can trigger with

require("Profile"); using SProfile
include("/tmp/newspawn.jl")
@sprofile newspawn(`echo hi`)

If there's no other way, this can presumably be fixed by disabling the profiling timer upon entry into the C function jl_spawn. But only once SProfile gets merged into base. JuliaLang/julia#2597.

[timholy]

As a very minor update, it's not dependent upon console output: @sprofile run(sleep 1) can also hang. But the intermittency puzzles me, as I've gotten that to both work and fail multiple times on my own laptop. Even launching an scp sometimes worked and sometimes didn't.

When one of these works, you get a successful profile out of it (lots of samples inside uv__epoll_wait, line 54).

[binarybana]

Thanks for the workaround, sadly I know even less of Julia internals so I'm not of much help here.

[timholy]

Jameson, thanks very much for looking into this!

I see that your fix is in the julia 0.3 branch. Any thoughts about whether this can be applied to master? (Note I haven't tested, but it sure looks promising.)

[vtjnash]

The julia0.3 branch is the current head for julia. We just need to update the sha1 in the julia repository.

Note that it seems to me that you in fact found a linux kernel bug -- it appears that the linux scheduler refuses to run any more code after returning from the clone syscall as part of the libc call to fork. (The exact mechanism of this failure is not apparent to me -- whether it is the SIGUSR1 interruption, or the timer & alarm reset and disable that is supposed to occur.)

[timholy]

Wow. Should I report this somewhere? I'd need a simple testcase (may have to bug you for pointers).

Or if it's just too complicated we can work around it...

[vtjnash]

The trick would be in building a simple testcase -- might be enough to just setup a timer as you do here, call fork() then exit().

The patch to libuv also just works around it by disabling all signals upon entry to and re-enabling them upon exit from uv_spawn(), this is probably a good idea anyways for making spawn robust against signals.

[timholy]

Alright, let's just use the workaround, and if I'm feeling ambitious I'll make a weekend project out of the kernel bug report. (I'm sure they'll want me to test on the current kernel, etc.)

[timholy]

@vtjnash, your fix has now been merged and works great for me. Thanks again!