# How to measure time in spawned process?

**URL:** <https://discourse.julialang.org/t/how-to-measure-time-in-spawned-process/25383>\
**Category:** New to Julia\
**Tags:** parallel\
**Created:** [June 18, 2019, 1:56am UTC](https://discourse.julialang.org/t/how-to-measure-time-in-spawned-process/25383 "2019-06-18T01:56:00Z")\
**Posts on this page:** 4\
**Page:** 1

<div class="post-metadata">

**Author:** ![hsgg](https://avatars.discourse-cdn.com/v4/letter/h/838e76/32.png) [@hsgg](https://discourse.julialang.org/u/hsgg)\
**Post date:** [June 18, 2019, 1:56am UTC](https://discourse.julialang.org/t/how-to-measure-time-in-spawned-process/25383/1 "2019-06-18T01:56:00Z")

</div>

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`:

```julia
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
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?

---

<div class="post-metadata">

**Author:** ![c42f](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/c42f/32/52842_2.png) [@c42f](https://discourse.julialang.org/u/c42f)\
**Post date:** [June 18, 2019, 4:45am UTC](https://discourse.julialang.org/t/how-to-measure-time-in-spawned-process/25383/2 "2019-06-18T04:45:22Z")

</div>

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
$ 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.

---

<div class="post-metadata">

**Author:** ![ffevotte](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/ffevotte/32/6587_2.png) [@ffevotte](https://discourse.julialang.org/u/ffevotte)\
**Post date:** [June 18, 2019, 10:52am UTC](https://discourse.julialang.org/t/how-to-measure-time-in-spawned-process/25383/3 "2019-06-18T10:52:33Z")

</div>

> [@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?](https://discourse.julialang.org/t/how-to-benchmark-distributed-function-calls/21319/2):
>
> 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 …

---

<div class="post-metadata">

**Author:** ![hsgg](https://avatars.discourse-cdn.com/v4/letter/h/838e76/32.png) [@hsgg](https://discourse.julialang.org/u/hsgg)\
**Post date:** [June 18, 2019, 11:55am UTC](https://discourse.julialang.org/t/how-to-measure-time-in-spawned-process/25383/4 "2019-06-18T11:55:50Z")

</div>

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