diff --git a/.travis.yml b/.travis.yml index abc5220..f508dbb 100644 --- a/.travis.yml +++ b/.travis.yml @@ -2,12 +2,18 @@ language: julia os: - linux julia: - - 0.5 - - 0.6 + - 0.7 + - 1.0 - nightly notifications: email: false +addons: + apt: + packages: + - xvfb + - xauth + - libgtk-3-0 script: - if [[ -a .git/shallow ]]; then git fetch --unshallow; fi - - julia -e 'Pkg.clone(pwd()); Pkg.build("ProfileView")' - - xvfb-run julia --check-bounds=yes -e 'Pkg.test("ProfileView"; coverage=true)' + - julia -e 'using Pkg; Pkg.clone(pwd()); Pkg.build("ProfileView")' + - xvfb-run julia --check-bounds=yes -e 'using Pkg; Pkg.test("ProfileView"; coverage=true)' diff --git a/README.md b/README.md index 096690e..359b03c 100644 --- a/README.md +++ b/README.md @@ -2,25 +2,8 @@ [![Build Status](https://travis-ci.org/timholy/ProfileView.jl.svg)](https://travis-ci.org/timholy/ProfileView.jl) -# NEWS - -Version 0.2 of ProfileView has several major changes: - -- Red highlighting has been restored; it now highlights - type-instabilities, not garbage collection, as a means to better - distinguish legitimate uses of allocation from ones that might be - avoidable. - -- For users of the Gtk version, ProfileView has switched from - [GtkUtilities](https://github.com/timholy/GtkUtilities.jl) to - [GtkReactive](https://github.com/JuliaGizmos/GtkReactive.jl). One - consequence is that you now need to hold down Ctrl for any zoom - operation. You can now shift the displayed region by click-dragging - on the image. - -- Also for users of the Gtk version, Ctrl-q and Ctrl-w close the - window. You can also use `ProfileView.closeall()` to close all - windows opened by ProfileView. +Note this README is for users of Julia 0.7 and higher; users of earlier versions +should see [this page](https://github.com/timholy/ProfileView.jl/tree/julia0.6). # Introduction @@ -51,16 +34,16 @@ function profile_test(n) for i = 1:n A = randn(100,100,20) m = maximum(A) - Afft = fft(A) - Am = mapslices(sum, A, 2) + Am = mapslices(sum, A; dims=2) B = A[:,:,5] - Bsort = mapslices(sort, B, 1) + Bsort = mapslices(sort, B; dims=1) b = rand(100) C = B.*b end end profile_test(1) # run once to trigger compilation +using Profile Profile.clear() # in case we have any previous profiling data @profile profile_test(10) ``` @@ -74,14 +57,21 @@ If you're following along, you should see something like this: ![ProfileView](readme_images/pv1.jpg) -This plot is a visual representation of the *call graph* of the code that you just profiled. The "root" of the tree is at the bottom; if you move your mouse over the long horizontal magenta bar at the bottom, you'll see it's an anonymous function in `REPL.jl`; the orangish one above that is `eval_user_input` in the same function. As is explained [elsewhere](http://docs.julialang.org/en/latest/stdlib/profile/), these are what run your code in the REPL. If you move your mouse upwards, you'll eventually get to the function(s) you ran with `@profile`. +(Note that collected profiles can vary from run-to-run, so don't be alarmed +if you get something different.) +This plot is a visual representation of the *call graph* of the code that you just profiled. +The "root" of the tree is at the bottom; if you move your mouse the long horizontal +bars near the bottom, you should fine one for `eval_user_input` in REPL.jl. +As is explained [elsewhere](http://docs.julialang.org/en/latest/stdlib/profile/), +these are what run your code in the REPL. +If you move your mouse upwards, you'll eventually get to the function(s) you ran with `@profile`. While the vertical axis therefore represents nesting depth, the horizontal axis represents the amount of time (more precisely, the number of backtraces) spent at each line. One sees on the 4th line from the bottom, there are several differently-colored bars, each corresponding to a different line of `profile_test`. The fact that -they are all positioned on top of the lower magenta bar means that all +they are all positioned on top of the lower peach-colored bar means that all of these lines are called by the same "parent" function. Within a block of code, they are sorted in order of increasing line number, to make it easier for you to compare to the source code. @@ -89,68 +79,38 @@ make it easier for you to compare to the source code. From this visual representation, we can very quickly learn several things about this function: -- The most deeply-nested line corresponds to `mapslices(sort, B, 1)`, - resulting in the tall "stack" of bars on the right edge. However, - this call does not take much time, because these bars are narrow - horizontally. +- The most deeply-nested call corresponds to the `mapslices(sort, B; dims=1)` call. + (If you hover over the top-most bars you will see they correspond to lines in `sort.jl`.) + In contrast, the call to `maximum` (the lowest blue bar) resolves to just two (non-inlined) calls. -- In contrast, the two most time-consuming operations are the calls to - `fft` and `mapslices(sum, A, 2)`. (This is more time-consuming than - the `mapslices(sort,...)` simply because it has to process more +- `mapslices(sum, A; dims=2)` is considerably more expensive than + `mapslices(sort, B; dims=1)`. (This is because it has to process more data.) -One thing we haven't yet discussed is the difference between the red -bars and the more pastel-colored bars. To explore this difference, -let's consider a different function: - -```julia -unstable(x) = x > 0.5 ? true : 0.0 - -function profile_unstable_test(m, n) - s = s2 = 0 - for i = 1:n - for k = 1:m - s += unstable(rand()) - end - x = collect(1:20) - s2 += sum(x) - end - s, s2 -end - -profile_unstable_test(1, 1) -Profile.clear() -@profile profile_unstable_test(10, 10^6) -ProfileView.view() -``` - -The main thing to note about this function is that the function -`unstable` does not have inferrable return type (a.k.a., it is -type-unstable); it can return either a `Bool` or a `Float64` depending -on the *value* (not type) of `x`. When we visualize the profiling -results for this function, we see something like the following: - -![ProfileView](readme_images/pv2.jpg) - -In this plot, red is a special color: it is reserved for function -calls that are deduced to be non-inferrable (by virtue of their +It is also worth noting that red is a special color: it is reserved for function +calls that have to be resolved at run-time (by virtue of their execution of the C functions `jl_invoke` or -`jl_apply_generic`). Because type-instability often has a significant +`jl_apply_generic`). Because run-time dispatch (aka, run-time method lookup or +a virtual call) often has a significant impact on performance, we highlight the problematic call in red. It's worth noting that some red is unavoidable; for example, the REPL can't predict in advance the return types from what users type at the -prompt. Red bars are problematic only when they account for a sizable +prompt, and so `eval_user_input` is red. +Red bars are problematic only when they account for a sizable fraction of the top "row," as only in such cases are they likely to be -the source of a significant performance bottleneck. In our first -example, we can see that `mapslices` is (internally) non-inferrable; +the source of a significant performance bottleneck. +We can see that `mapslices` relies on run-time dispatch; from the absence of pastel-colored bars above much of the red, we -might guess that this type-instability makes a substantial +might guess that this makes a substantial contribution to its total run time. ## GUI features ### Gtk Interface +- Ctrl-q and Ctrl-w close the window. You can also use + `ProfileView.closeall()` to close all windows opened by ProfileView. + - Left-clicking on a bar will cause information about this line to be printed in the REPL. This can be a convenient way to "mark" lines for later investigation. @@ -164,7 +124,7 @@ contribution to its total run time. with CTRL-scroll. You can also use your keyboard (arrow keys, plus SHIFT and CTRL modifiers). Double-click to restore the full view. -- To use the Gtk interface in IJulia, set `PROFILEVIEW_USEGTK = true` in +- To use the Gtk interface in Juno or IJulia, set `PROFILEVIEW_USEGTK = true` in the `Main` module before `using ProfileView`. - The toolbar at the top contains two icons to load and save profile diff --git a/REQUIRE b/REQUIRE index a4c0f68..eb3934a 100644 --- a/REQUIRE +++ b/REQUIRE @@ -1,7 +1,7 @@ -julia 0.5 +julia 0.7 Gtk -GtkReactive 0.0.3 -Cairo 0.5.1 +GtkReactive 0.5.1 +Cairo 0.5.6 Colors Graphics 0.2 FileIO diff --git a/readme_images/pv1.jpg b/readme_images/pv1.jpg index 2aa20d4..7d44149 100644 Binary files a/readme_images/pv1.jpg and b/readme_images/pv1.jpg differ diff --git a/readme_images/pv2.jpg b/readme_images/pv2.jpg deleted file mode 100644 index 9c807a3..0000000 Binary files a/readme_images/pv2.jpg and /dev/null differ diff --git a/src/ProfileView.jl b/src/ProfileView.jl index 7466e63..da41257 100644 --- a/src/ProfileView.jl +++ b/src/ProfileView.jl @@ -1,10 +1,9 @@ -__precompile__() - module ProfileView +using Profile, UUIDs using Colors -import Base: contains, isequal, show, mimewritable +import Base: isequal, show include("tree.jl") include("pvtree.jl") @@ -14,13 +13,13 @@ using .PVTree include("svgwriter.jl") -immutable TagData +struct TagData ip::UInt status::Int end const TAGNONE = TagData(UInt(0), -1) -type ProfileData +mutable struct ProfileData img lidict imgtags @@ -33,35 +32,37 @@ const gccolor = colorant"red" const colors = distinguishable_colors(13, [bkg,fontcolor,gccolor], lchoices=Float64[65, 70, 75, 80], cchoices=Float64[0, 50, 60, 70], - hchoices=linspace(0, 330, 24))[4:end] + hchoices=range(0, stop=330, length=24))[4:end] function have_display() - !is_unix() && return true - is_apple() && return true + !Sys.isunix() && return true + Sys.isapple() && return true return haskey(ENV, "DISPLAY") end function __init__() - push!(LOAD_PATH, splitdir(@__FILE__)[1]) if (isdefined(Main, :IJulia) && !isdefined(Main, :PROFILEVIEW_USEGTK)) || !have_display() - eval(Expr(:import, :ProfileViewSVG)) + # @eval import ProfileViewSVG + include(joinpath(@__DIR__, "ProfileViewSVG.jl")) + @eval import .ProfileViewSVG @eval begin view(data = Profile.fetch(); C = false, lidict = nothing, colorgc = true, fontsize = 12, combine = true, pruned = []) = ProfileViewSVG.view(data; C=C, lidict=lidict, colorgc=colorgc, fontsize=fontsize, combine=combine, pruned=pruned) end else - eval(Expr(:import, :ProfileViewGtk)) + # @eval import ProfileViewGtk + include(joinpath(@__DIR__, "ProfileViewGtk.jl")) + @eval import .ProfileViewGtk @eval begin view(data = Profile.fetch(); C = false, lidict = nothing, colorgc = true, fontsize = 12, combine = true, pruned = []) = ProfileViewGtk.view(data; C=C, lidict=lidict, colorgc=colorgc, fontsize=fontsize, combine=combine, pruned=pruned) - closeall() = ProfileViewGtk.closeall() @doc """ closeall() Closes all windows opened by ProfileView. -""" -> closeall +""" + closeall() = ProfileViewGtk.closeall() end end - pop!(LOAD_PATH) end function prepare(data; C = false, lidict = nothing, colorgc = true, combine = true, pruned = []) @@ -70,7 +71,7 @@ function prepare(data; C = false, lidict = nothing, colorgc = true, combine = tr end function prepare_data(data, lidict) - bt, counts = Profile.tree_aggregate(data) + bt, counts = tree_aggregate(data) if isempty(counts) Profile.warning_empty() error("Nothing to view") @@ -97,7 +98,7 @@ function prepare_data(data, lidict) # Do code address lookups on all unique instruction pointers uip = unique(vcat(bt...)) if lidict == nothing - lkup = Vector{StackFrame}[Profile.lookup(ip) for ip in uip] + lkup = Vector{StackTraces.StackFrame}[Profile.lookup(ip) for ip in uip] lidict = Dict(zip(uip, lkup)) else lkup = [lidict[ip] for ip in uip] @@ -105,7 +106,7 @@ function prepare_data(data, lidict) bt, uip, counts, lidict, lkup end -prepare_data(::Void, ::Void) = nothing, nothing, nothing, nothing, nothing +prepare_data(::Nothing, ::Nothing) = nothing, nothing, nothing, nothing, nothing function prepare_image(bt, uip, counts, lidict, lkup, C, colorgc, combine, pruned) @@ -156,21 +157,28 @@ function prepare_image(bt, uip, counts, lidict, lkup, C, colorgc, combine, img, lidict, imgtags end -function svgwrite(filename::AbstractString, data, lidict; C = false, colorgc = true, fontsize = 12, combine = true, pruned = []) +function svgwrite(io::IO, data, lidict; C = false, colorgc = true, fontsize = 12, combine = true, pruned = []) img, lidict, imgtags = prepare(data, C=C, lidict=lidict, colorgc=colorgc, combine=combine, pruned=pruned) pd = ProfileData(img, lidict, imgtags, fontsize) + show(io, "image/svg+xml", pd) +end +function svgwrite(filename::AbstractString, data, lidict; kwargs...) open(filename, "w") do file - show(file, "image/svg+xml", pd) + svgwrite(file, data, lidict; kwargs...) end nothing end +function svgwrite(io::IO; kwargs...) + data, lidict = Profile.retrieve() + svgwrite(io, data, lidict; kwargs...) +end function svgwrite(filename::AbstractString; kwargs...) data, lidict = Profile.retrieve() svgwrite(filename, data, lidict; kwargs...) end -mimewritable(::MIME"image/svg+xml", pd::ProfileData) = true +Base.showable(::MIME"image/svg+xml", pd::ProfileData) = true function show(f::IO, ::MIME"image/svg+xml", pd::ProfileData) img = pd.img @@ -189,9 +197,9 @@ function show(f::IO, ::MIME"image/svg+xml", pd::ProfileData) ystep = (height - (topmargin + botmargin)) / nrows avgcharwidth = 6 # for Verdana 12 pt font function eschtml(str) - s = replace(str, '<', "<") - s = replace(s, '>', ">") - s = replace(s, '&', "&") + s = replace(str, '<' => "<") + s = replace(s, '>' => ">") + s = replace(s, '&' => "&") s end function printrec(f, samples, xstart, xend, y, tag, rgb) @@ -216,7 +224,7 @@ function show(f::IO, ::MIME"image/svg+xml", pd::ProfileData) # end end - fig_id = string("fig-", replace(string(Base.Random.uuid4()), "-", "")) + fig_id = string("fig-", replace(string(uuid4()), "-" => "")) svgheader(f, fig_id, width=width, height=height) # rectangles are on a grid and split across multiple columns (must span similar adjacent ones together) for r in 1:nrows @@ -267,7 +275,7 @@ function buildtags!(rowtags, parent, level) end t = rowtags[level] for c in parent - t[c.data.hspan] = TagData(c.data.ip, c.data.status) + t[c.data.hspan] .= Ref(TagData(c.data.ip, c.data.status)) buildtags!(rowtags, c, level+1) end end @@ -318,10 +326,10 @@ end function fillrow!(img, j, rng::UnitRange{Int}, colorindex, colorlen, regcolor, gccolor, status) if status > 0 - img[rng,j] = gccolor + img[rng,j] .= gccolor return colorindex else - img[rng,j] = regcolor + img[rng,j] .= regcolor return mod1(colorindex+1, colorlen) end end @@ -407,4 +415,27 @@ function pushpruned!(pruned_ips, pruned, lidict) end end +## A tree representation +# Identify and counts repetitions of all unique backtraces +function tree_aggregate(data::Vector{UInt64}) + iz = findall(iszero, data) # find the breaks between backtraces + treecount = Dict{Vector{UInt64},Int}() + istart = 1 + for iend in iz + tmp = data[iend - 1 : -1 : istart] + treecount[tmp] = get(treecount, tmp, 0) + 1 + istart = iend + 1 + end + bt = Vector{Vector{UInt64}}(undef, 0) + counts = Vector{Int}(undef, 0) + for (k, v) in treecount + if !isempty(k) + push!(bt, k) + push!(counts, v) + end + end + return (bt, counts) +end + + end diff --git a/src/ProfileViewGtk.jl b/src/ProfileViewGtk.jl index 227c8a5..abbe885 100644 --- a/src/ProfileViewGtk.jl +++ b/src/ProfileViewGtk.jl @@ -1,20 +1,19 @@ -__precompile__() - module ProfileViewGtk +using InteractiveUtils using Gtk.ShortNames, GtkReactive, Colors, FileIO, IntervalSets import Cairo using Graphics using Gtk.GConstants.GdkModifierType: SHIFT, CONTROL, MOD1 -type ZoomCanvas +mutable struct ZoomCanvas bb::BoundingBox # in user-coordinates c::Canvas end function __init__() - eval(Expr(:import, :ProfileView)) + @eval import ProfileView end function closeall() @@ -24,13 +23,13 @@ function closeall() nothing end -const window_wrefs = WeakKeyDict{Gtk.GtkWindowLeaf,Void}() +const window_wrefs = WeakKeyDict{Gtk.GtkWindowLeaf,Nothing}() function view(data = Profile.fetch(); lidict=nothing, kwargs...) bt, uip, counts, lidict, lkup = ProfileView.prepare_data(data, lidict) # Display in a window c = canvas(UserUnit) - setproperty!(widget(c), :expand, true) + set_gtk_property!(widget(c), :expand, true) f = Frame(c) tb = Toolbar() bx = Box(:v) @@ -40,8 +39,8 @@ function view(data = Profile.fetch(); lidict=nothing, kwargs...) tb_save_as = ToolButton("gtk-save-as") push!(tb, tb_open) push!(tb, tb_save_as) - signal_connect(open_cb, tb_open, "clicked", Void, (), false, (widget(c),kwargs)) - signal_connect(save_as_cb, tb_save_as, "clicked", Void, (), false, (widget(c),data,lidict,kwargs)) + signal_connect(open_cb, tb_open, "clicked", Nothing, (), false, (widget(c),kwargs)) + signal_connect(save_as_cb, tb_save_as, "clicked", Nothing, (), false, (widget(c),data,lidict,kwargs)) win = Window(bx, "Profile") GtkReactive.gc_preserve(win, c) # Register the window with closeall @@ -57,17 +56,17 @@ function view(data = Profile.fetch(); lidict=nothing, kwargs...) # Ctrl-w and Ctrl-q destroy the window signal_connect(win, "key-press-event") do w, evt if evt.state == CONTROL && (evt.keyval == UInt('q') || evt.keyval == UInt('w')) - @schedule destroy(w) + @async destroy(w) nothing end end - showall(win) + Gtk.showall(win) end function viewprof(c, bt, uip, counts, lidict, lkup; C = false, colorgc = true, fontsize = 12, combine = true, pruned=[]) img, lidict, imgtags = ProfileView.prepare_image(bt, uip, counts, lidict, lkup, C, colorgc, combine, pruned) - img24 = UInt32[reinterpret(UInt32, convert(RGB24, img[i,j])) for i = 1:size(img,1), j = size(img,2):-1:1]' + img24 = Matrix(UInt32[reinterpret(UInt32, convert(RGB24, img[i,j])) for i = 1:size(img,1), j = size(img,2):-1:1]') fv = XY(0.0..size(img24,2), 0.0..size(img24,1)) zr = Signal(ZoomRegion(fv, fv)) sigrb = init_zoom_rubberband(c, zr) diff --git a/src/ProfileViewSVG.jl b/src/ProfileViewSVG.jl index e8c8e07..8c0efc5 100644 --- a/src/ProfileViewSVG.jl +++ b/src/ProfileViewSVG.jl @@ -1,9 +1,7 @@ -__precompile__() - module ProfileViewSVG function __init__() - eval(Expr(:import, :ProfileView)) + @eval import ProfileView end function view(data = Profile.fetch(); C = false, lidict = nothing, colorgc = true, fontsize = 12, combine = true, pruned = true) diff --git a/src/pvtree.jl b/src/pvtree.jl index 7a60cae..d48b257 100644 --- a/src/pvtree.jl +++ b/src/pvtree.jl @@ -5,7 +5,7 @@ using ..Tree export PVData, buildgraph!, prunegraph! # ProfileView data we need attached to each node of the graph: -type PVData +mutable struct PVData ip::UInt # the instruction pointer hspan::UnitRange{Int} # horizontal span (used as the x-axis in display) status::Int # nonzero for special handling, (e.g., gc events) @@ -37,9 +37,9 @@ function buildgraph!(parent::Node, bt::Vector{Vector{UInt}}, counts::Vector{Int} end end ngroups = length(dorder) - group = Vector{Vector{Int}}(ngroups) # indices in bt that have the same sortorder - n = Array{Int}(ngroups) # aggregated counts for this group - order = Array{Int}(ngroups) + group = Vector{Vector{Int}}(undef, ngroups) # indices in bt that have the same sortorder + n = Array{Int}(undef, ngroups) # aggregated counts for this group + order = Array{Int}(undef, ngroups) i = 1 for (key, v) in dorder order[i] = key diff --git a/src/svgwriter.jl b/src/svgwriter.jl index e6e115d..e25338c 100644 --- a/src/svgwriter.jl +++ b/src/svgwriter.jl @@ -1,8 +1,8 @@ -const snapsvgjs = joinpath(dirname(@__FILE__), "..", "templates", "snap.svg-min.js") -const viewerjs = joinpath(dirname(@__FILE__), "viewer.js") +const snapsvgjs = joinpath(@__DIR__, "..", "templates", "snap.svg-min.js") +const viewerjs = joinpath(@__DIR__, "viewer.js") function escape_script(js::AbstractString) - return replace(js, "]]", "] ]") + return replace(js, "]]" => "] ]") end function svgheader(f::IO, fig_id::AbstractString; width=1200, height=706, font="Verdana") @@ -37,9 +37,9 @@ end function svgfinish(f::IO, fig_id) print(f, """ - +