How to measure time in spawned process?

[hsgg]

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?

[c42f]

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.

[ffevotte]

@c42f

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.

Yes.

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

How to benchmark distributed function calls?

Most likely, you’re what you’re seeing here is only the memory consumption of some launching process (which has to wait for spawned tasks to complete, and can thus measure the correct elapsed time). In order to get a total memory consumption, I don’t know of any other way than to benchmark individual spawned tasks. Here is a complete example: Sequential version First, a plain, sequential version to be used as reference: julia> using BenchmarkTools julia> f_seq(n) = map(1:n) do i …

[hsgg]

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