From 52e910fb2a155a0271bc458b6831523dea465d37 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 20 Oct 2022 17:27:53 -0600 Subject: [PATCH 1/8] WIP - Reentrant concurrent snoopi_deep profiles. --- SnoopCompileCore/src/snoopi_deep.jl | 191 ++++++++++++++++++++++++++-- test/snoopi_deep.jl | 30 +++++ 2 files changed, 211 insertions(+), 10 deletions(-) diff --git a/SnoopCompileCore/src/snoopi_deep.jl b/SnoopCompileCore/src/snoopi_deep.jl index 3719cf84e..69edc0c8c 100644 --- a/SnoopCompileCore/src/snoopi_deep.jl +++ b/SnoopCompileCore/src/snoopi_deep.jl @@ -70,28 +70,199 @@ function addchildren!(parent::InferenceTimingNode, t::Core.Compiler.Timings.Timi end end +module SnoopiDeepParallelism + +# Mutex ordering: MUTEX > jl_typeinf_lock +const MUTEX = ReentrantLock() + +mutable struct Invocation + # start_idx is mutated when older invocations are deleted and the profile is shifted. + start_idx::Int + stop_idx::Int + start_time::UInt64 +end +function Invocation(start_idx) + # Start at the current time. + return Invocation(start_idx, 0, time_ns()) +end + +""" +Global (locked) vector tracking running snoopi calls, and when they started. +- When one finishes, we lock(inference), export results, clear the inference profiles up to +the next oldest snoopi call, then unlock(inference). + +Imagine this is an ongoing inference profile, where each letter is another inference profile +result, and we start two profiles, 1 and 2, at the times indicated below: + ABCDEFGHIJKLMNOPQRSTUVWX + 1> 2> <1 <2 + + - invocations: [(1,A), (2,D)] + - 1 ends: + copy out ABCDEFGHIJKLMNOPQRSTU + pop (1,A) from invocations + read oldest invocation: (2,D) + delete up to D. + - New profile: + DEFGHIJKLMNOPQRSTUVWX + 2> <2 + + - 2 ends: + copy out DEFGHIJKLMNOPQRSTUVWX + pop (2,D) from invocations + no active invocations, so ... + ... delete up to X (end of this profile). +""" +const invocations = Invocation[] + +function _current_profile_length_locked() + ccall(:jl_typeinf_lock_begin, Cvoid, ()) + try + inference_root_timing = Core.Compiler.Timings._timings[1] + children = inference_root_timing.children + return length(children) + finally + ccall(:jl_typeinf_lock_end, Cvoid, ()) + end +end + +function _fetch_profile_buffer_locked(start_idx, stop_idx) + ccall(:jl_typeinf_lock_begin, Cvoid, ()) + try + inference_root_timing = Core.Compiler.Timings._timings[1] + children = inference_root_timing.children + return children[start_idx:stop_idx] + finally + ccall(:jl_typeinf_lock_end, Cvoid, ()) + end +end + +function start_timing_invocation() + # Locking respects mutex ordering. + Base.@lock MUTEX begin + profile_start_idx = _current_profile_length_locked() + 1 + @show profile_start_idx + invocation = Invocation(profile_start_idx) + push!(invocations, invocation) + return invocation + end +end + +function stop_timing_invocation!(invocation) + invocation.stop_idx = _current_profile_length_locked() +end + +function finish_timing_invocation_and_clear_profile(invocation) + # Locking respects mutex ordering. + Base.@lock MUTEX begin + # Check if this invocation was the oldest. If so, we'll want to clear the parts of + # the profile only it was using. + if invocations[1] !== invocation + idx = findfirst(==(invocation), invocations) + @assert idx !== nothing "invocation wasn't found in invocations: $invocation." + @show idx + deleteat!(invocations, idx) + return + end + + # Clear this invocation from the invocations vector. + popfirst!(invocations) + + @show invocations + + # Now clear the global inference profile up to the start of the next invocation. + # If no next invocations, clear them all. + if isempty(invocations) + ccall(:jl_typeinf_lock_begin, Cvoid, ()) + try + Core.Compiler.Timings.reset_timings() + finally + ccall(:jl_typeinf_lock_end, Cvoid, ()) + end + return + end + + # Else, we stop at the next oldest invocation. + next_oldest = invocations[1] + start_idx = next_oldest.start_idx + to_delete = start_idx - 1 + if to_delete == 0 + return + end + # Shift back the indices for all the running invocations + for running_invocation in invocations + running_invocation.start_idx -= to_delete + running_invocation.stop_idx -= to_delete + end + # Clear the profile up to the start of the new oldest invocation. + ccall(:jl_typeinf_lock_begin, Cvoid, ()) + try + inference_root_timing = Core.Compiler.Timings._timings[1] + children = inference_root_timing.children + @show to_delete + deleteat!(children, 1:to_delete) + finally + ccall(:jl_typeinf_lock_end, Cvoid, ()) + end + end +end + +end # module + function start_deep_timing() - Core.Compiler.Timings.reset_timings() Core.Compiler.__set_measure_typeinf(true) + return SnoopiDeepParallelism.start_timing_invocation() end -function stop_deep_timing() +function stop_deep_timing!(invocation) Core.Compiler.__set_measure_typeinf(false) - Core.Compiler.Timings.close_current_timer() + return SnoopiDeepParallelism.stop_timing_invocation!(invocation) end -function finish_snoopi_deep() - return InferenceTimingNode(Core.Compiler.Timings._timings[1]) +function finish_snoopi_deep(invocation) + buffer = SnoopiDeepParallelism._fetch_profile_buffer_locked(invocation.start_idx, invocation.stop_idx) + + @show invocation, buffer + + # Clean up the profile buffer, so that we don't leak memory. + SnoopiDeepParallelism.finish_timing_invocation_and_clear_profile(invocation) + + root_node = _create_finished_ROOT_Timing(invocation, buffer) + return InferenceTimingNode(root_node) end +# The MethodInstance for ROOT(), and default empty values for other fields. +# Copied from julia typeinf +const root_inference_frame_info = + Core.Compiler.Timings.InferenceFrameInfo(Core.Compiler.Timings.ROOTmi, 0x0, Any[], Any[Core.Const(Core.Compiler.Timings.ROOT)], 1) + +function _create_finished_ROOT_Timing(invocation, buffer) + total_time = time_ns() - invocation.start_time + + # Create a new ROOT() node, specific to this profiling invocation, which wraps the + # current profile buffer, and contains the total time for the profile. + return Core.Compiler.Timings.Timing( + root_inference_frame_info, + invocation.start_time, + 0, + # TODO: This is wrong, this is supposed to be the total exclusive ROOT time. + # we should get this off the ROOT() timing when we stop!() the invocation. + total_time, + # Use the copied-out section of the profile buffer as the children of ROOT() + buffer, + ) +end + + + function _snoopi_deep(cmd::Expr) return quote - start_deep_timing() + invocation = start_deep_timing() try $(esc(cmd)) finally - stop_deep_timing() + stop_deep_timing!(invocation) end - finish_snoopi_deep() + # return the timing result: + finish_snoopi_deep(invocation) end end @@ -134,5 +305,5 @@ end # These are okay to come at the top-level because we're only measuring inference, and # inference results will be cached in a `.ji` file. precompile(start_deep_timing, ()) -precompile(stop_deep_timing, ()) -precompile(finish_snoopi_deep, ()) +precompile(stop_deep_timing!, (SnoopiDeepParallelism.Invocation,)) +precompile(finish_snoopi_deep, (SnoopiDeepParallelism.Invocation,)) diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl index c07598ba2..ed8625916 100644 --- a/test/snoopi_deep.jl +++ b/test/snoopi_deep.jl @@ -863,6 +863,7 @@ end # pgdsgui(axs[2], rit; bystr="Inclusive", consts=true, interactive=false) end + @testset "Stale" begin cproj = Base.active_project() cd(joinpath("testmodules", "Stale")) do @@ -958,3 +959,32 @@ if Base.VERSION >= v"1.7" @test isempty(SnoopCompile.JET.get_reports(report_caller(itrigs[end]))) end end + +@testset "reentrant concurrent profiles - 1" begin + # Warmup + @eval foo1(x) = x+2 + @eval foo1(2) + + # Test: + t1 = SnoopCompileCore.start_deep_timing() + + @eval foo1(x) = x+2 + @eval foo1(2) + + t2 = SnoopCompileCore.start_deep_timing() + + @eval foo2(x) = x+2 + foo2(2) + + SnoopCompileCore.stop_deep_timing!(t1) + SnoopCompileCore.stop_deep_timing!(t2) + + prof1 = SnoopCompileCore.finish_snoopi_deep(t1) + prof2 = SnoopCompileCore.finish_snoopi_deep(t2) + + # [ROOT, foo1, foo2] + @test length(SnoopCompile.flatten(prof1)) == 3 + + # [ROOT, foo2] + @test length(SnoopCompile.flatten(prof2)) == 2 +end From 4e3c77acc90781b297620f6a1b707fdf25694563 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 20 Oct 2022 21:51:19 -0600 Subject: [PATCH 2/8] Add more tests, fix up some small things --- SnoopCompileCore/src/snoopi_deep.jl | 7 +- test/snoopi_deep.jl | 194 +++++++++++++++++++++++++++- 2 files changed, 192 insertions(+), 9 deletions(-) diff --git a/SnoopCompileCore/src/snoopi_deep.jl b/SnoopCompileCore/src/snoopi_deep.jl index 69edc0c8c..6eaeacb6b 100644 --- a/SnoopCompileCore/src/snoopi_deep.jl +++ b/SnoopCompileCore/src/snoopi_deep.jl @@ -209,8 +209,9 @@ end end # module function start_deep_timing() + invocation = SnoopiDeepParallelism.start_timing_invocation() Core.Compiler.__set_measure_typeinf(true) - return SnoopiDeepParallelism.start_timing_invocation() + return invocation end function stop_deep_timing!(invocation) Core.Compiler.__set_measure_typeinf(false) @@ -231,7 +232,7 @@ end # The MethodInstance for ROOT(), and default empty values for other fields. # Copied from julia typeinf -const root_inference_frame_info = +root_inference_frame_info() = Core.Compiler.Timings.InferenceFrameInfo(Core.Compiler.Timings.ROOTmi, 0x0, Any[], Any[Core.Const(Core.Compiler.Timings.ROOT)], 1) function _create_finished_ROOT_Timing(invocation, buffer) @@ -240,7 +241,7 @@ function _create_finished_ROOT_Timing(invocation, buffer) # Create a new ROOT() node, specific to this profiling invocation, which wraps the # current profile buffer, and contains the total time for the profile. return Core.Compiler.Timings.Timing( - root_inference_frame_info, + root_inference_frame_info(), invocation.start_time, 0, # TODO: This is wrong, this is supposed to be the total exclusive ROOT time. diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl index ed8625916..19e59045e 100644 --- a/test/snoopi_deep.jl +++ b/test/snoopi_deep.jl @@ -960,7 +960,144 @@ if Base.VERSION >= v"1.7" end end -@testset "reentrant concurrent profiles - 1" begin +_name(frame::SnoopCompileCore.InferenceTiming) = frame.mi_info.mi.def.name + +@testset "reentrant concurrent profiles 1 - overlap" begin + # Warmup + @eval foo1(x) = x+2 + @eval foo1(2) + + # Test: + t1 = SnoopCompileCore.start_deep_timing() + + @eval foo1(x) = x+2 + @eval foo1(2) + + t2 = SnoopCompileCore.start_deep_timing() + + @eval foo2(x) = x+2 + @eval foo2(2) + + SnoopCompileCore.stop_deep_timing!(t1) + SnoopCompileCore.stop_deep_timing!(t2) + + prof1 = SnoopCompileCore.finish_snoopi_deep(t1) + prof2 = SnoopCompileCore.finish_snoopi_deep(t2) + + @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2]) + @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2]) + + # Test Cleanup + @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) + @test isempty(Core.Compiler.Timings._timings[1].children) +end + +@testset "reentrant concurrent profiles 2 - interleaved" begin + # Warmup + @eval foo1(x) = x+2 + @eval foo1(2) + + # Test: + t1 = SnoopCompileCore.start_deep_timing() + + @eval foo1(x) = x+2 + @eval foo1(2) + + t2 = SnoopCompileCore.start_deep_timing() + + @eval foo2(x) = x+2 + @eval foo2(2) + + SnoopCompileCore.stop_deep_timing!(t1) + + @eval foo3(x) = x+2 + @eval foo3(2) + + SnoopCompileCore.stop_deep_timing!(t2) + + @eval foo4(x) = x+2 + @eval foo4(2) + + prof1 = SnoopCompileCore.finish_snoopi_deep(t1) + + @eval foo5(x) = x+2 + @eval foo5(2) + + prof2 = SnoopCompileCore.finish_snoopi_deep(t2) + + @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2]) + @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2, :foo3]) + + # Test Cleanup + @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) + @test isempty(Core.Compiler.Timings._timings[1].children) +end + +@testset "reentrant concurrent profiles 3 - nested" begin + # Warmup + @eval foo1(x) = x+2 + @eval foo1(2) + + # Test: + local prof1, prof2, prof3 + prof1 = SnoopCompileCore.@snoopi_deep begin + @eval foo1(x) = x+2 + @eval foo1(2) + prof2 = SnoopCompileCore.@snoopi_deep begin + @eval foo2(x) = x+2 + @eval foo2(2) + prof3 = SnoopCompileCore.@snoopi_deep begin + @eval foo3(x) = x+2 + @eval foo3(2) + end + @eval foo4(x) = x+2 + @eval foo4(2) + end + @eval foo5(x) = x+2 + @eval foo5(2) + end + + @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2, :foo3, :foo4, :foo5]) + @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2, :foo3, :foo4]) + @test Set(_name.(SnoopCompile.flatten(prof3))) == Set([:ROOT, :foo3]) + + # Test Cleanup + @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) + @test isempty(Core.Compiler.Timings._timings[1].children) +end +_name(frame::SnoopCompileCore.InferenceTiming) = frame.mi_info.mi.def.name + +@testset "reentrant concurrent profiles 1 - overlap" begin + # Warmup + @eval foo1(x) = x+2 + @eval foo1(2) + + # Test: + t1 = SnoopCompileCore.start_deep_timing() + + @eval foo1(x) = x+2 + @eval foo1(2) + + t2 = SnoopCompileCore.start_deep_timing() + + @eval foo2(x) = x+2 + @eval foo2(2) + + SnoopCompileCore.stop_deep_timing!(t1) + SnoopCompileCore.stop_deep_timing!(t2) + + prof1 = SnoopCompileCore.finish_snoopi_deep(t1) + prof2 = SnoopCompileCore.finish_snoopi_deep(t2) + + @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2]) + @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2]) + + # Test Cleanup + @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) + @test isempty(Core.Compiler.Timings._timings[1].children) +end + +@testset "reentrant concurrent profiles 2 - interleaved" begin # Warmup @eval foo1(x) = x+2 @eval foo1(2) @@ -974,17 +1111,62 @@ end t2 = SnoopCompileCore.start_deep_timing() @eval foo2(x) = x+2 - foo2(2) + @eval foo2(2) SnoopCompileCore.stop_deep_timing!(t1) + + @eval foo3(x) = x+2 + @eval foo3(2) + SnoopCompileCore.stop_deep_timing!(t2) + @eval foo4(x) = x+2 + @eval foo4(2) + prof1 = SnoopCompileCore.finish_snoopi_deep(t1) + + @eval foo5(x) = x+2 + @eval foo5(2) + prof2 = SnoopCompileCore.finish_snoopi_deep(t2) - # [ROOT, foo1, foo2] - @test length(SnoopCompile.flatten(prof1)) == 3 + @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2]) + @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2, :foo3]) + + # Test Cleanup + @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) + @test isempty(Core.Compiler.Timings._timings[1].children) +end + +@testset "reentrant concurrent profiles 3 - nested" begin + # Warmup + @eval foo1(x) = x+2 + @eval foo1(2) + + # Test: + local prof1, prof2, prof3 + prof1 = SnoopCompileCore.@snoopi_deep begin + @eval foo1(x) = x+2 + @eval foo1(2) + prof2 = SnoopCompileCore.@snoopi_deep begin + @eval foo2(x) = x+2 + @eval foo2(2) + prof3 = SnoopCompileCore.@snoopi_deep begin + @eval foo3(x) = x+2 + @eval foo3(2) + end + @eval foo4(x) = x+2 + @eval foo4(2) + end + @eval foo5(x) = x+2 + @eval foo5(2) + end + + @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2, :foo3, :foo4, :foo5]) + @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2, :foo3, :foo4]) + @test Set(_name.(SnoopCompile.flatten(prof3))) == Set([:ROOT, :foo3]) - # [ROOT, foo2] - @test length(SnoopCompile.flatten(prof2)) == 2 + # Test Cleanup + @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) + @test isempty(Core.Compiler.Timings._timings[1].children) end From 9d0e0dfb1ebffecd0d1d9c7bb333a422d1bfe36a Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 20 Oct 2022 22:01:32 -0600 Subject: [PATCH 3/8] =?UTF-8?q?Add=20parallelism=20test.=20I=20think=20thi?= =?UTF-8?q?ngs=20are=20mostly=20working!=20=F0=9F=8E=89?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- test/snoopi_deep.jl | 35 +++++++++++++++++++++++++++++++++++ 1 file changed, 35 insertions(+) diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl index 19e59045e..4ba9210b3 100644 --- a/test/snoopi_deep.jl +++ b/test/snoopi_deep.jl @@ -1170,3 +1170,38 @@ end @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) @test isempty(Core.Compiler.Timings._timings[1].children) end + +@testset "reentrant concurrent profiles 3 - parallelism" begin + # Warmup + @eval foo1(x) = x+2 + @eval foo1(2) + + # Test: + local ts + # Run it twice to ensure we warmup the eval block + for _ in 1:2 + @sync begin + ts = [ + Threads.@spawn begin + sleep(i-1) + SnoopCompile.@snoopi_deep @eval begin + $(Symbol("foo$i"))(x) = x + 1 + sleep(1.5) + $(Symbol("foo$i"))(2) + end + end + for i in 1:4 + ] + end + end + profs = fetch.(ts) + + @test Set(_name.(SnoopCompile.flatten(profs[1]))) == Set([:ROOT, :foo1]) + @test Set(_name.(SnoopCompile.flatten(profs[2]))) == Set([:ROOT, :foo1, :foo2]) + @test Set(_name.(SnoopCompile.flatten(profs[3]))) == Set([:ROOT, :foo2, :foo3]) + @test Set(_name.(SnoopCompile.flatten(profs[4]))) == Set([:ROOT, :foo3, :foo4]) + + # Test Cleanup + @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) + @test isempty(Core.Compiler.Timings._timings[1].children) +end From d9fc8757c6cbda52c4b6ff1fc39413976ab702dc Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 20 Oct 2022 22:03:20 -0600 Subject: [PATCH 4/8] Remove the printouts --- SnoopCompileCore/src/snoopi_deep.jl | 7 ------- 1 file changed, 7 deletions(-) diff --git a/SnoopCompileCore/src/snoopi_deep.jl b/SnoopCompileCore/src/snoopi_deep.jl index 6eaeacb6b..5f21d1e6b 100644 --- a/SnoopCompileCore/src/snoopi_deep.jl +++ b/SnoopCompileCore/src/snoopi_deep.jl @@ -140,7 +140,6 @@ function start_timing_invocation() # Locking respects mutex ordering. Base.@lock MUTEX begin profile_start_idx = _current_profile_length_locked() + 1 - @show profile_start_idx invocation = Invocation(profile_start_idx) push!(invocations, invocation) return invocation @@ -159,7 +158,6 @@ function finish_timing_invocation_and_clear_profile(invocation) if invocations[1] !== invocation idx = findfirst(==(invocation), invocations) @assert idx !== nothing "invocation wasn't found in invocations: $invocation." - @show idx deleteat!(invocations, idx) return end @@ -167,8 +165,6 @@ function finish_timing_invocation_and_clear_profile(invocation) # Clear this invocation from the invocations vector. popfirst!(invocations) - @show invocations - # Now clear the global inference profile up to the start of the next invocation. # If no next invocations, clear them all. if isempty(invocations) @@ -198,7 +194,6 @@ function finish_timing_invocation_and_clear_profile(invocation) try inference_root_timing = Core.Compiler.Timings._timings[1] children = inference_root_timing.children - @show to_delete deleteat!(children, 1:to_delete) finally ccall(:jl_typeinf_lock_end, Cvoid, ()) @@ -221,8 +216,6 @@ end function finish_snoopi_deep(invocation) buffer = SnoopiDeepParallelism._fetch_profile_buffer_locked(invocation.start_idx, invocation.stop_idx) - @show invocation, buffer - # Clean up the profile buffer, so that we don't leak memory. SnoopiDeepParallelism.finish_timing_invocation_and_clear_profile(invocation) From eac22c91aa2cf5490342f4e8ee44530670614470 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 20 Oct 2022 22:38:14 -0600 Subject: [PATCH 5/8] Implement correct exclusive times for the ROOT() nodes. --- SnoopCompileCore/src/snoopi_deep.jl | 28 ++++++++++++++++++---------- test/snoopi_deep.jl | 23 +++++++++++++++++++---- 2 files changed, 37 insertions(+), 14 deletions(-) diff --git a/SnoopCompileCore/src/snoopi_deep.jl b/SnoopCompileCore/src/snoopi_deep.jl index 5f21d1e6b..c569d5984 100644 --- a/SnoopCompileCore/src/snoopi_deep.jl +++ b/SnoopCompileCore/src/snoopi_deep.jl @@ -80,10 +80,12 @@ mutable struct Invocation start_idx::Int stop_idx::Int start_time::UInt64 + root_start_excl_time::UInt64 + root_stop_excl_time::UInt64 end -function Invocation(start_idx) +function Invocation(start_idx, start_root_excl_time) # Start at the current time. - return Invocation(start_idx, 0, time_ns()) + return Invocation(start_idx, 0, time_ns(), start_root_excl_time, 0) end """ @@ -114,12 +116,18 @@ result, and we start two profiles, 1 and 2, at the times indicated below: """ const invocations = Invocation[] -function _current_profile_length_locked() +function _current_profile_stats_locked() ccall(:jl_typeinf_lock_begin, Cvoid, ()) try inference_root_timing = Core.Compiler.Timings._timings[1] children = inference_root_timing.children - return length(children) + # Since we were able to grab the lock, we must not be in an inference profile, + # meaning we are in ROOT(). So to get an accurate ROOT timing, we have to add the + # accumulated time since the ROOT was last updated: + accum_root_time = time_ns() - inference_root_timing.cur_start_time + current_root_time = inference_root_timing.time + accum_root_time + + return length(children), current_root_time finally ccall(:jl_typeinf_lock_end, Cvoid, ()) end @@ -139,15 +147,16 @@ end function start_timing_invocation() # Locking respects mutex ordering. Base.@lock MUTEX begin - profile_start_idx = _current_profile_length_locked() + 1 - invocation = Invocation(profile_start_idx) + current_profile_length, current_root_time = _current_profile_stats_locked() + profile_start_idx = current_profile_length + 1 + invocation = Invocation(profile_start_idx, current_root_time) push!(invocations, invocation) return invocation end end function stop_timing_invocation!(invocation) - invocation.stop_idx = _current_profile_length_locked() + invocation.stop_idx, invocation.root_stop_excl_time = _current_profile_stats_locked() end function finish_timing_invocation_and_clear_profile(invocation) @@ -237,9 +246,8 @@ function _create_finished_ROOT_Timing(invocation, buffer) root_inference_frame_info(), invocation.start_time, 0, - # TODO: This is wrong, this is supposed to be the total exclusive ROOT time. - # we should get this off the ROOT() timing when we stop!() the invocation. - total_time, + # Total exclusive time spent in ROOT during the lifetime of this node. + invocation.root_stop_excl_time - invocation.root_start_excl_time, # Use the copied-out section of the profile buffer as the children of ROOT() buffer, ) diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl index 4ba9210b3..8f13a6edf 100644 --- a/test/snoopi_deep.jl +++ b/test/snoopi_deep.jl @@ -1171,24 +1171,27 @@ end @test isempty(Core.Compiler.Timings._timings[1].children) end -@testset "reentrant concurrent profiles 3 - parallelism" begin +@testset "reentrant concurrent profiles 3 - parallelism + accurate timing" begin # Warmup @eval foo1(x) = x+2 @eval foo1(2) # Test: local ts + snoop_times = Float64[0.0, 0.0, 0.0, 0.0] # Run it twice to ensure we warmup the eval block for _ in 1:2 @sync begin ts = [ Threads.@spawn begin - sleep(i-1) - SnoopCompile.@snoopi_deep @eval begin + sleep((i-1) / 10) # (Divide by 10 so the test isn't too slow) + snoop_time = @timed SnoopCompile.@snoopi_deep @eval begin $(Symbol("foo$i"))(x) = x + 1 - sleep(1.5) + sleep(1.5 / 10) $(Symbol("foo$i"))(2) end + snoop_times[i] = snoop_time.time + return snoop_time.value end for i in 1:4 ] @@ -1201,6 +1204,18 @@ end @test Set(_name.(SnoopCompile.flatten(profs[3]))) == Set([:ROOT, :foo2, :foo3]) @test Set(_name.(SnoopCompile.flatten(profs[4]))) == Set([:ROOT, :foo3, :foo4]) + # Test the sanity of the reported Timings + @testset for i in eachindex(profs) + prof = profs[i] + # Test that the time for the inference is accounted for + @test prof.mi_timing.exclusive_time < prof.mi_timing.inclusive_time + # Test that the inclusive time (the total time reported by snoopi_deep) matches + # the actual time to do the snoopi_deep, as measured by `@time`. + # These should both be approximately ~0.15 seconds. + @info prof.mi_timing.inclusive_time + @test prof.mi_timing.inclusive_time <= snoop_times[i] + end + # Test Cleanup @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) @test isempty(Core.Compiler.Timings._timings[1].children) From 29e9c32afa2ea4b0bb53518d310aacde942065c8 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 20 Oct 2022 22:40:07 -0600 Subject: [PATCH 6/8] Reorder tests: keep JET tests last --- test/snoopi_deep.jl | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl index 8f13a6edf..8c3d1bf80 100644 --- a/test/snoopi_deep.jl +++ b/test/snoopi_deep.jl @@ -945,21 +945,6 @@ end Pkg.activate(cproj) end -if Base.VERSION >= v"1.7" - @testset "JET integration" begin - f(c) = sum(c[1]) - c = Any[Any[1,2,3]] - tinf = @snoopi_deep f(c) - rpt = SnoopCompile.JET.@report_call f(c) - @test isempty(SnoopCompile.JET.get_reports(rpt)) - itrigs = inference_triggers(tinf) - irpts = report_callees(itrigs) - @test only(irpts).first == last(itrigs) - @test !isempty(SnoopCompile.JET.get_reports(only(irpts).second)) - @test isempty(SnoopCompile.JET.get_reports(report_caller(itrigs[end]))) - end -end - _name(frame::SnoopCompileCore.InferenceTiming) = frame.mi_info.mi.def.name @testset "reentrant concurrent profiles 1 - overlap" begin @@ -1220,3 +1205,18 @@ end @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) @test isempty(Core.Compiler.Timings._timings[1].children) end + +if Base.VERSION >= v"1.7" + @testset "JET integration" begin + f(c) = sum(c[1]) + c = Any[Any[1,2,3]] + tinf = @snoopi_deep f(c) + rpt = SnoopCompile.JET.@report_call f(c) + @test isempty(SnoopCompile.JET.get_reports(rpt)) + itrigs = inference_triggers(tinf) + irpts = report_callees(itrigs) + @test only(irpts).first == last(itrigs) + @test !isempty(SnoopCompile.JET.get_reports(only(irpts).second)) + @test isempty(SnoopCompile.JET.get_reports(report_caller(itrigs[end]))) + end +end From 2e1d5cddac2ca94655b99e1e0eb181188bed2ca7 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Fri, 21 Oct 2022 14:37:49 -0600 Subject: [PATCH 7/8] Delete accidentally duplicated tests --- test/snoopi_deep.jl | 105 -------------------------------------------- 1 file changed, 105 deletions(-) diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl index 8c3d1bf80..76a3949b2 100644 --- a/test/snoopi_deep.jl +++ b/test/snoopi_deep.jl @@ -1018,111 +1018,6 @@ end @test isempty(Core.Compiler.Timings._timings[1].children) end -@testset "reentrant concurrent profiles 3 - nested" begin - # Warmup - @eval foo1(x) = x+2 - @eval foo1(2) - - # Test: - local prof1, prof2, prof3 - prof1 = SnoopCompileCore.@snoopi_deep begin - @eval foo1(x) = x+2 - @eval foo1(2) - prof2 = SnoopCompileCore.@snoopi_deep begin - @eval foo2(x) = x+2 - @eval foo2(2) - prof3 = SnoopCompileCore.@snoopi_deep begin - @eval foo3(x) = x+2 - @eval foo3(2) - end - @eval foo4(x) = x+2 - @eval foo4(2) - end - @eval foo5(x) = x+2 - @eval foo5(2) - end - - @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2, :foo3, :foo4, :foo5]) - @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2, :foo3, :foo4]) - @test Set(_name.(SnoopCompile.flatten(prof3))) == Set([:ROOT, :foo3]) - - # Test Cleanup - @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) - @test isempty(Core.Compiler.Timings._timings[1].children) -end -_name(frame::SnoopCompileCore.InferenceTiming) = frame.mi_info.mi.def.name - -@testset "reentrant concurrent profiles 1 - overlap" begin - # Warmup - @eval foo1(x) = x+2 - @eval foo1(2) - - # Test: - t1 = SnoopCompileCore.start_deep_timing() - - @eval foo1(x) = x+2 - @eval foo1(2) - - t2 = SnoopCompileCore.start_deep_timing() - - @eval foo2(x) = x+2 - @eval foo2(2) - - SnoopCompileCore.stop_deep_timing!(t1) - SnoopCompileCore.stop_deep_timing!(t2) - - prof1 = SnoopCompileCore.finish_snoopi_deep(t1) - prof2 = SnoopCompileCore.finish_snoopi_deep(t2) - - @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2]) - @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2]) - - # Test Cleanup - @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) - @test isempty(Core.Compiler.Timings._timings[1].children) -end - -@testset "reentrant concurrent profiles 2 - interleaved" begin - # Warmup - @eval foo1(x) = x+2 - @eval foo1(2) - - # Test: - t1 = SnoopCompileCore.start_deep_timing() - - @eval foo1(x) = x+2 - @eval foo1(2) - - t2 = SnoopCompileCore.start_deep_timing() - - @eval foo2(x) = x+2 - @eval foo2(2) - - SnoopCompileCore.stop_deep_timing!(t1) - - @eval foo3(x) = x+2 - @eval foo3(2) - - SnoopCompileCore.stop_deep_timing!(t2) - - @eval foo4(x) = x+2 - @eval foo4(2) - - prof1 = SnoopCompileCore.finish_snoopi_deep(t1) - - @eval foo5(x) = x+2 - @eval foo5(2) - - prof2 = SnoopCompileCore.finish_snoopi_deep(t2) - - @test Set(_name.(SnoopCompile.flatten(prof1))) == Set([:ROOT, :foo1, :foo2]) - @test Set(_name.(SnoopCompile.flatten(prof2))) == Set([:ROOT, :foo2, :foo3]) - - # Test Cleanup - @test isempty(SnoopCompileCore.SnoopiDeepParallelism.invocations) - @test isempty(Core.Compiler.Timings._timings[1].children) -end - @testset "reentrant concurrent profiles 3 - nested" begin # Warmup @eval foo1(x) = x+2 From f86ce5b8456efecf24b717366edc49fad3d2d74d Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Sun, 23 Oct 2022 19:54:26 -0600 Subject: [PATCH 8/8] Add another tiny test --- test/snoopi_deep.jl | 1 + 1 file changed, 1 insertion(+) diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl index 76a3949b2..d5d6a8dbf 100644 --- a/test/snoopi_deep.jl +++ b/test/snoopi_deep.jl @@ -1088,6 +1088,7 @@ end @testset for i in eachindex(profs) prof = profs[i] # Test that the time for the inference is accounted for + @test 0.15 < prof.mi_timing.exclusive_time @test prof.mi_timing.exclusive_time < prof.mi_timing.inclusive_time # Test that the inclusive time (the total time reported by snoopi_deep) matches # the actual time to do the snoopi_deep, as measured by `@time`.