How to measure time in spawned process?

I’m trying to parallelize my code, and find it useful to measure the elapsed CPU time for a single process. However, I find that using @time the output is garbled. Here is a MWE, minimal.jl:

using Distributed

@everywhere module minimal

using Distributed

function do_something(x)
    @time x=5+x
    return x
end

function main()
    n = 5
    futures = Array{Any}(fill(NaN, n))

    # start processes
    for i=1:n
        futures[i] = @spawn do_something(i)
    end

    # collect answers
    for i=1:n
        result = fetch(futures[i])
        @show result
    end
end

end

minimal.main()

Then, even with no parallel execution starting Julia simply as julia I get

julia> include("minimal.jl");
          00000.....000000000000000000000000000000 seconds seconds seconds seconds seconds




result = 6
result = 7
result = 8
result = 9
result = 10

And similar when using multiple processes, e.g. starting Julia as julia -p2.

I was wondering what @time is doing differently than, say, println(), which does not have this problem? How can I measure serial execution time?

What’s happening here is that @time uses base.print_time which uses @printf which uses multiple print invocations, one for each part of the output. IO can cause a task switch, and they’re all writing to stdout together so pieces end up interleaved. (Furthermore these compete with the REPL task which is also writing to stdout!)

To reproduce the behavior:

$ julia -e 'using Distributed; for i=1:10; @spawn (print(stdout, "a") ; print(stdout, "b")) ; end ; sleep(1)'
aaaaaaaaaabbbbbbbbbb

You could use @timed and manage the formatting of the output yourself, gathering this information back to the main task and doing the IO there.

1 Like

Yes.

See the thread below for an example using this technique to benchmark function calls that are distributed with pmap:

Thank you @c42f @ffevotte! I guess I was mostly stumped that @time behaved differently than println(). The explanation makes sense, though. Thanks, again!