diff --git a/Project.toml b/Project.toml index 4122336d9..d5c7a6d4b 100644 --- a/Project.toml +++ b/Project.toml @@ -10,12 +10,14 @@ OrderedCollections = "bac558e1-5e72-5ebc-8fee-abe8a469f55d" Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f" Serialization = "9e88b42a-f829-5b0c-bbe9-9e923198166b" SnoopCompileCore = "e2b509da-e806-4183-be48-004708413034" +YAML = "ddb6d928-2868-570f-bddf-ab3f9cf99eb6" [compat] Cthulhu = "1.2" FlameGraphs = "0.2" OrderedCollections = "1" SnoopCompileCore = "~2.1.2" +YAML = "0.4" julia = "1" [extras] diff --git a/SnoopCompileCore/src/SnoopCompileCore.jl b/SnoopCompileCore/src/SnoopCompileCore.jl index 6eb73d059..032dd8a8a 100644 --- a/SnoopCompileCore/src/SnoopCompileCore.jl +++ b/SnoopCompileCore/src/SnoopCompileCore.jl @@ -19,4 +19,8 @@ if VERSION >= v"1.6.0-DEV.154" include("snoopr.jl") end +if VERSION >= v"1.6.0-DEV.1192" # https://github.com/JuliaLang/julia/pull/37136 + include("snoopl.jl") +end + end diff --git a/SnoopCompileCore/src/snoopl.jl b/SnoopCompileCore/src/snoopl.jl new file mode 100644 index 000000000..26e0832b4 --- /dev/null +++ b/SnoopCompileCore/src/snoopl.jl @@ -0,0 +1,54 @@ +export @snoopl + +using Serialization + +""" +``` +@snoopl "func_names.csv" "llvm_timings.yaml" begin + # Commands to execute, in a new process +end +``` +causes the julia compiler to log timing information for LLVM optimization during the +provided commands to the files "func_names.csv" and "llvm_timings.yaml". These files can +be used for the input to `SnoopCompile.read_snoopl("func_names.csv", "llvm_timings.yaml")`. + +The logs contain the amount of time spent optimizing each "llvm module", and information +about each module, where a module is a collection of functions being optimized together. +""" +macro snoopl(flags, func_file, llvm_file, commands) + return :(snoopl($(esc(flags)), $(esc(func_file)), $(esc(llvm_file)), $(QuoteNode(commands)))) +end +macro snoopl(func_file, llvm_file, commands) + return :(snoopl(String[], $(esc(func_file)), $(esc(llvm_file)), $(QuoteNode(commands)))) +end + +function snoopl(flags, func_file, llvm_file, commands) + println("Launching new julia process to run commands...") + # addprocs will run the unmodified version of julia, so we + # launch it as a command. + code_object = """ + using Serialization + while !eof(stdin) + Core.eval(Main, deserialize(stdin)) + end + """ + process = open(`$(Base.julia_cmd()) $flags --eval $code_object`, stdout, write=true) + serialize(process, quote + let func_io = open($func_file, "w"), llvm_io = open($llvm_file, "w") + ccall(:jl_dump_emitted_mi_name, Nothing, (Ptr{Nothing},), func_io.handle) + ccall(:jl_dump_llvm_opt, Nothing, (Ptr{Nothing},), llvm_io.handle) + try + $commands + finally + ccall(:jl_dump_emitted_mi_name, Nothing, (Ptr{Nothing},), C_NULL) + ccall(:jl_dump_llvm_opt, Nothing, (Ptr{Nothing},), C_NULL) + close(func_io) + close(llvm_io) + end + end + exit() + end) + wait(process) + println("done.") + nothing +end diff --git a/src/SnoopCompile.jl b/src/SnoopCompile.jl index 1b61fa448..385f9be4d 100644 --- a/src/SnoopCompile.jl +++ b/src/SnoopCompile.jl @@ -9,9 +9,13 @@ end if isdefined(SnoopCompileCore, Symbol("@snoopr")) export @snoopr, uinvalidated, invalidation_trees, filtermod, findcaller, ascend end +if isdefined(SnoopCompileCore, Symbol("@snoopl")) + export @snoopl, read_snoopl +end using Core: MethodInstance, CodeInfo using Serialization, OrderedCollections +import YAML # For @snoopl # Parcel Regex const anonrex = r"#{1,2}\d+#{1,2}\d+" # detect anonymous functions @@ -31,6 +35,8 @@ if VERSION >= v"1.6.0-DEV.1190" # https://github.com/JuliaLang/julia/pull/37749 include("parcel_snoopi_deep.jl") end +include("parcel_snoopl.jl") + if isdefined(SnoopCompileCore, Symbol("@snoopr")) include("invalidations.jl") end diff --git a/src/parcel_snoopl.jl b/src/parcel_snoopl.jl new file mode 100644 index 000000000..f0a8109cf --- /dev/null +++ b/src/parcel_snoopl.jl @@ -0,0 +1,98 @@ +""" + times, info = SnoopCompile.read_snoopl("func_names.csv", "llvm_timings.yaml"; tmin_secs=0.0) + +Reads the log file produced by the compiler and returns the structured representations. + +The results will only contain modules that took longer than `tmin_secs` to optimize. + +## Return value +- `times` contains the time spent optimizing each module, as a Pair from the time to an +array of Strings, one for every MethodInstance in that llvm module. +- `info` is a Dict containing statistics for each MethodInstance encountered, from before +and after optimization, including number of instructions and number of basicblocks. + +## Example +```julia +julia> @snoopl "func_names.csv" "llvm_timings.yaml" begin + using InteractiveUtils + @eval InteractiveUtils.peakflops() + end +Launching new julia process to run commands... +done. + +julia> times, info = SnoopCompile.read_snoopl("func_names.csv", "llvm_timings.yaml", tmin_secs = 0.025); + +julia> times +3-element Vector{Pair{Float64, Vector{String}}}: + 0.028170923 => ["Tuple{typeof(LinearAlgebra.copy_transpose!), Array{Float64, 2}, Base.UnitRange{Int64}, Base.UnitRange{Int64}, Array{Float64, 2}, Base.UnitRange{Int64}, Base.UnitRange{Int64}}"] + 0.031356962 => ["Tuple{typeof(Base.copyto!), Array{Float64, 2}, Base.UnitRange{Int64}, Base.UnitRange{Int64}, Array{Float64, 2}, Base.UnitRange{Int64}, Base.UnitRange{Int64}}"] + 0.149138788 => ["Tuple{typeof(LinearAlgebra._generic_matmatmul!), Array{Float64, 2}, Char, Char, Array{Float64, 2}, Array{Float64, 2}, LinearAlgebra.MulAddMul{true, true, Bool, Bool}}"] + +julia> info +Dict{String, NamedTuple{(:before, :after), Tuple{NamedTuple{(:instructions, :basicblocks), Tuple{Int64, Int64}}, NamedTuple{(:instructions, :basicblocks), Tuple{Int64, Int64}}}}} with 3 entries: + "Tuple{typeof(LinearAlgebra.copy_transpose!), Ar… => (before = (instructions = 651, basicblocks = 83), after = (instructions = 348, basicblocks = 40… + "Tuple{typeof(Base.copyto!), Array{Float64, 2}, … => (before = (instructions = 617, basicblocks = 77), after = (instructions = 397, basicblocks = 37… + "Tuple{typeof(LinearAlgebra._generic_matmatmul!)… => (before = (instructions = 4796, basicblocks = 824), after = (instructions = 1421, basicblocks =… +``` +""" +function read_snoopl(func_csv_file, llvm_yaml_file; tmin_secs=0.0) + func_csv = _read_snoopl_csv(func_csv_file) + llvm_yaml = YAML.load_file(llvm_yaml_file) + + jl_names = Dict(r[1]::String => r[2]::String for r in func_csv) + + try_get_jl_name(name) = if name in keys(jl_names) + jl_names[name] + else + @warn "Couldn't find $name" + name + end + + time_secs(llvm_module) = llvm_module["time_ns"] / 1e9 + + times = [ + time_secs(llvm_module) => [ + try_get_jl_name(name) + for (name,_) in llvm_module["before"] + ] for llvm_module in llvm_yaml + if time_secs(llvm_module) > tmin_secs + ] + + info = Dict( + try_get_jl_name(name) => (; + before = (; + instructions = before_stats["instructions"], + basicblocks = before_stats["basicblocks"], + ), + after = (; + instructions = after_stats["instructions"], + basicblocks = after_stats["basicblocks"], + ), + ) + for llvm_module in llvm_yaml + for (name, before_stats) in llvm_module["before"] + for (name, after_stats) in llvm_module["after"] + if time_secs(llvm_module) > tmin_secs + ) + + + # sort times so that the most costly items are displayed last + return (sort(times), info) +end + + +""" +`SnoopCompile._read_snoopl_csv("compiledata.csv")` reads the log file produced by the +compiler and returns the function names as an array of pairs. +""" +function _read_snoopl_csv(filename) + data = Vector{Pair{String,String}}() + # Format is [^\t]+\t[^\t]+. That is, tab-separated entries. No quotations or other + # whitespace are considered. + for line in eachline(filename) + c_name, jl_type = split2(line, '\t') + (length(c_name) < 2 || length(jl_type) < 2) && continue + push!(data, c_name => jl_type) + end + return data +end \ No newline at end of file diff --git a/test/runtests.jl b/test/runtests.jl index 6467ebf22..a8b11c7b3 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -10,6 +10,12 @@ if VERSION >= v"1.6.0-DEV.1190" # https://github.com/JuliaLang/julia/pull/37749 end end +if VERSION >= v"1.6.0-DEV.1192" # https://github.com/JuliaLang/julia/pull/37136 + @testset "snoopl" begin + include("snoopl.jl") + end +end + using SnoopCompile # issue #26 diff --git a/test/snoopl.jl b/test/snoopl.jl new file mode 100644 index 000000000..356570734 --- /dev/null +++ b/test/snoopl.jl @@ -0,0 +1,21 @@ +using Test + +using SnoopCompile + +@testset "@snoopl" begin + + @snoopl "func_names.csv" "llvm_timings.yaml" begin + @eval module M + i(x) = x+5 + h(a::Array) = i(a[1]::Integer) + 2 + g(y::Integer) = h(Any[y]) + end; + @eval M.g(3) + end; + + times, info = SnoopCompile.read_snoopl("func_names.csv", "llvm_timings.yaml") + + @test length(times) == 3 # i(), h(), g() + @test length(info) == 3 # i(), h(), g() + +end \ No newline at end of file