Compilation Time reporting is broken on Julia 1.7, due to Task Migration

[NHDaly]

Consider this small example, which @times within a Task, allows the Task to migrate threads, and then shows that the results are garbage when it switches threads:

# compilation-task-migration-17-example.jl
@sync begin
    # Start a long task that yields a lot, and is likely to switch tasks
    # Run a `@time` measurement in there, to report the compilation time.
    Threads.@spawn begin
        @time begin
            Core.println("start thread: ",Threads.threadid())
            for _ in 1:5
                sleep(0.2)  # might switch threads
            end
            @eval module M ; f(x,y) = x+y; end
            @eval M.f(1,2)
            Core.println("end thread: ",Threads.threadid())
        end
    end
    # Start some heavy work to occupy the thread that the above task started on.
    @sync for _ in 1:Threads.nthreads()
        Threads.@spawn for _ in 1:10 peakflops() end
    end
end

One time it reported 0% compilation time, the next time it reports 4327426979.58% compilation time 😅

julia> versioninfo()
Julia Version 1.7.0-beta3
Commit e76c9dad42 (2021-07-07 08:12 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin19.6.0)
  CPU: Intel(R) Core(TM) i9-8950HK CPU @ 2.90GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-12.0.0 (ORCJIT, skylake)
Environment:
  JULIA_NUM_THREADS = 4
  
julia> include("compilation-task-migration-17-example.jl")
start thread: 1
WARNING: replacing module M.
end thread: 3
  4.352289 seconds (18.97 k allocations: 2.391 GiB, 6.06% gc time)

julia> include("compilation-task-migration-17-example.jl")
start thread: 2
WARNING: replacing module M.
end thread: 3
  4.262751 seconds (18.97 k allocations: 2.391 GiB, 5.35% gc time, 4327426979.58% compilation time)

(For completeness, here's the same test on julia 1.6):

julia> versioninfo()
Julia Version 1.6.2
Commit 1b93d53fc4 (2021-07-14 15:36 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin19.6.0)
  CPU: Intel(R) Core(TM) i9-8950HK CPU @ 2.90GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-11.0.1 (ORCJIT, skylake)
Environment:
  JULIA_NUM_THREADS = 4

julia> include("compilation-task-migration-17-example.jl")
start thread: 2
end thread: 2
  5.200354 seconds (3.24 M allocations: 2.563 GiB, 6.75% gc time, 0.33% compilation time)

julia> include("compilation-task-migration-17-example.jl")
start thread: 2
WARNING: replacing module M.
end thread: 2
  5.840806 seconds (18.27 k allocations: 2.391 GiB, 8.02% gc time, 0.05% compilation time)

[NHDaly]

So, it seems to me that:

1. Per-thread measurements of compilation time are just not very useful, at least certainly aren't what a user wants when they call @time.
2. It's hard to get useful per-task measurements, since you have the problem that anything that happens in child tasks is not attributed to you (as we discussed yesterday).
3. Since all of the other metrics that we currently report (allocations, bytes, time, gc time) are all global measurements, that we should just make this a global metric as well.

Does that seem like a reasonable approach to everyone? Remove the per-thread aspect of this measurement, make it global, and protect it with atomics, similar to what was done in #41612?

(I'll probably make that change by adapting #41733 to this purpose, and then use atomic increment/decrement for the feature, to make it reentrant.)

Sound good?
CC: @IanButterworth, @vtjnash, @vchuravy
CC: @rgankema, @ElSeidy, since this is related to #41271.

[vchuravy]

Jep sounds sensible to me. Without the ability to inherit data from your parent, which is a whole other can of worms, this seems like the best solution for now.

…

On Fri, Jul 30, 2021, 23:34 Nathan Daly ***@***.***> wrote: So, it seems to me that: 1. Per-thread measurements of compilation time are just not very useful, at least certainly aren't what a user wants when they call @time. 2. It's hard to get useful per-task measurements, since you have the problem that anything that happens in *child tasks* is not attributed to you (as we discussed yesterday). 3. Since all of the other metrics that we currently report (allocations, bytes, time, gc time) are all global measurements, that we should just make this a global metric as well. Does that seem like a reasonable approach to everyone? Remove the per-thread aspect of this measurement, make it global, and protect it with atomics, similar to what was done in #41612 <#41612>? (I'll probably make that change by adapting #41733 <#41733> to this purpose, and then use atomic increment/decrement for the feature, to make it reentrant.) Sound good? CC: @IanButterworth <https://github.com/IanButterworth>, @vtjnash <https://github.com/vtjnash>, @vchuravy <https://github.com/vchuravy> CC: @rgankema <https://github.com/rgankema>, @ElSeidy <https://github.com/ElSeidy>, since this is related to #41271 <#41271>. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#41739 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABDO2S6O3M434HMMDMDV3DT2MLFLANCNFSM5BJCH4MQ> .

[rgankema]

3. Since all of the other metrics that we currently report (allocations, bytes, time, gc time) are all global measurements, that we should just make this a global metric as well.

I guess this makes sense, but for the specific performance measurements I'd like to do, global allocation and compilation time measurements are not very useful. Can I hope for additional task-level measurements at some point in time, or would that be unrealistic?

[ElSeidy]

1. Since all of the other metrics that we currently report (allocations, bytes, time, gc time) are all global measurements, that we should just make this a global metric as well.

I guess this makes sense, but for the specific performance measurements I'd like to do, global allocation and compilation time measurements are not very useful. Can I hope for additional task-level measurements at some point in time, or would that be unrealistic?

I would second @rgankema in that too. I am also interested in per-task metrics (alongside with global metrics). I can imagine lots of profiling applications (other than mine) that would prefer to rely on this level of abstraction.

I hope thats feasible too :)

[NHDaly]

The trouble is that, like I said in 2., it's not super clear how well-defined per-task measurements are..

Like, do you really only want the compilation time in that single task? Or do you want compilation time in that task and all tasks that it spawned? Or that task + all the tasks that it waited on? Or only the tasks that it waited on, that were spawned by it?

I think the main thing blocking support for this feature is just deciding as a group what we want the semantics to mean. I think it should be okay to implement it, we just need to decide what we want to measure.

That said, ++ i think we all want to have some task-accounting for things like this, yeah. 👍 👍

[ElSeidy]

The trouble is that, like I said in 2., it's not super clear how well-defined per-task measurements are..

Like, do you really only want the compilation time in that single task? Or do you want compilation time in that task and all tasks that it spawned? Or that task + all the tasks that it waited on? Or only the tasks that it waited on, that were spawned by it?

I think the main thing blocking support for this feature is just deciding as a group what we want the semantics to mean. I think it should be okay to implement it, we just need to decide what we want to measure.

That said, ++ i think we all want to have some task-accounting for things like this, yeah. 👍 👍

@NHDaly , thats a good point.

In my opinion, the way I think about it is similar to execution time (total/breakdowns). I would define it as the total time for compilation taken for a task to finish (including any subtasks spawned by it and it waited on). I think, its up to the developer/instrumenter to be able to extract the any breakdowns (just like we do in the tracers' execution time).

[ElSeidy]

@NHDaly, to be accurate, I am also assuming here that I can compute the compilation time for a portion within a single task too like @time (to be able to extract the breakdowns):
something like this (excuse my pseudocode)

# task 1
@compilation_time begin. # block1
     #some computations for block1 (in task1)
     ....
     @compilation_time begin # block2
             # some other computation for block2 (in task1)
             .....
     end
     
     # task 2
     @sync @spawn begin 
          @compilation_time begin # block3
             # some other computation for block3 (in task2)
             ....
          end
     end
end

here the compilation time for block1 would include both block2 and block3. But I can still retrieve the compilation times for block2 and block3 independently too.

[rgankema]

@NHDaly That's a great point, I should have been more precise :) I'd be interested in compilation time for that task and all tasks it spawned. Of course, if that's feasible at all!

To express that more high-level: when I run a piece of code, I want to know all the compilation costs that were incurred as a result of running that code. So that means that if that code spawns new tasks, those tasks are interesting as well. But other tasks that just happen to be running at the same time (which I guess is what we'd measure with global measurements), are tasks I don't want to measure.