{ "cells": [ { "cell_type": "markdown", "metadata": {}, "source": [ "[FProfile.jl](https://github.com/cstjean/FProfile.jl) provides an alternative interface for Julia's sampling profiler (`@profile`). If you've never used a sampling profiler before, please read [the introduction of this document](https://docs.julialang.org/en/latest/manual/profile/) before proceeding ." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Profiling\n", "\n", "You can build a profile by calling `@fprofile(code, delay=0.001, n_samples=1000000)`:" ] }, { "cell_type": "code", "execution_count": 1, "metadata": {}, "outputs": [ { "data": { "text/plain": [ "ProfileData(49 backtraces)" ] }, "execution_count": 1, "metadata": {}, "output_type": "execute_result" } ], "source": [ "using FProfile, Calculus\n", "\n", "pd = @fprofile second_derivative(sin, 1.0)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "`@fprofile(N, ...)` is shorthand for `@fprofile(for _ in 1:N ... end)`:" ] }, { "cell_type": "code", "execution_count": 2, "metadata": {}, "outputs": [ { "data": { "text/plain": [ "ProfileData(910 backtraces)" ] }, "execution_count": 2, "metadata": {}, "output_type": "execute_result" } ], "source": [ "pd = @fprofile 1000000 second_derivative(sin, 1.0)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Do not forget that Julia compiles code the first time a function is run; if you do not want to measure compilation time, execute your code once before profiling." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Flat view\n", "\n", "FProfile's `flat` report is a [dataframe](http://juliadata.github.io/DataFrames.jl/stable/man/getting_started/#Getting-Started-1). No particular knowledge of dataframes is necessary. I'll provide a few common operations below." ] }, { "cell_type": "code", "execution_count": 21, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
count_pctstackframe
199.89execute_request(::ZMQ.Socket, ::IJulia.Msg) at execute_request.jl:154
299.89anonymous at <missing>:?
399.89macro expansion at FProfile.jl:52 [inlined]
499.89(::IJulia.##14#17)() at task.jl:335
599.89eventloop(::ZMQ.Socket) at eventloop.jl:8
699.89macro expansion at profile.jl:23 [inlined]
799.89include_string(::Module, ::String, ::String) at Compat.jl:464
899.89include_string(::String, ::String) at loading.jl:515
999.67macro expansion at FProfile.jl:67 [inlined]
1099.23second_derivative(::Function, ::Float64) at derivative.jl:71
1153.63derivative(::Function, ::Symbol, ::Symbol) at derivative.jl:3
1218.35finite_difference_hessian(::Function, ::Function, ::Float64, ::Symbol) at finite_difference.jl:224
1311.43finite_difference(::Calculus.##1#3{Base.#sin,Symbol}, ::Float64, ::Symbol) at finite_difference.jl:55
146.26sin at math.jl:419 [inlined]
156.15finite_difference(::Calculus.##1#3{Base.#sin,Symbol}, ::Float64, ::Symbol) at finite_difference.jl:27
" ], "text/plain": [ "15×2 DataFrames.DataFrame\n", "│ Row │ count_pct │\n", "├─────┼───────────┤\n", "│ 1 │ 99.89 │\n", "│ 2 │ 99.89 │\n", "│ 3 │ 99.89 │\n", "│ 4 │ 99.89 │\n", "│ 5 │ 99.89 │\n", "│ 6 │ 99.89 │\n", "│ 7 │ 99.89 │\n", "│ 8 │ 99.89 │\n", "│ 9 │ 99.67 │\n", "│ 10 │ 99.23 │\n", "│ 11 │ 53.63 │\n", "│ 12 │ 18.35 │\n", "│ 13 │ 11.43 │\n", "│ 14 │ 6.26 │\n", "│ 15 │ 6.15 │\n", "\n", "│ Row │ stackframe │\n", "├─────┼───────────────────────────────────────────────────────────────────────────────────────────────────────┤\n", "│ 1 │ execute_request(::ZMQ.Socket, ::IJulia.Msg) at execute_request.jl:154 │\n", "│ 2 │ anonymous at :? │\n", "│ 3 │ macro expansion at FProfile.jl:52 [inlined] │\n", "│ 4 │ (::IJulia.##14#17)() at task.jl:335 │\n", "│ 5 │ eventloop(::ZMQ.Socket) at eventloop.jl:8 │\n", "│ 6 │ macro expansion at profile.jl:23 [inlined] │\n", "│ 7 │ include_string(::Module, ::String, ::String) at Compat.jl:464 │\n", "│ 8 │ include_string(::String, ::String) at loading.jl:515 │\n", "│ 9 │ macro expansion at FProfile.jl:67 [inlined] │\n", "│ 10 │ second_derivative(::Function, ::Float64) at derivative.jl:71 │\n", "│ 11 │ derivative(::Function, ::Symbol, ::Symbol) at derivative.jl:3 │\n", "│ 12 │ finite_difference_hessian(::Function, ::Function, ::Float64, ::Symbol) at finite_difference.jl:224 │\n", "│ 13 │ finite_difference(::Calculus.##1#3{Base.#sin,Symbol}, ::Float64, ::Symbol) at finite_difference.jl:55 │\n", "│ 14 │ sin at math.jl:419 [inlined] │\n", "│ 15 │ finite_difference(::Calculus.##1#3{Base.#sin,Symbol}, ::Float64, ::Symbol) at finite_difference.jl:27 │" ] }, "execution_count": 21, "metadata": {}, "output_type": "execute_result" } ], "source": [ "using DataFrames\n", "\n", "df = flat(pd)\n", "head(df, 15) # show only the first 15 rows (the 15 rows with the highest counts)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "(REPL note: if the output of `flat` is [incomplete](https://github.com/JuliaData/DataFrames.jl/issues/1272), try `showall(flat(pd))` or `Matrix(flat(pd))`)\n", "\n", "The first column shows what fraction of backtraces (in %) go through the `method at file:line_number` in the `stackframe` column. It's the same quantity as in `Base.Profile.print()`, except for recursive calls: if `factorial(2)` calls `factorial(1)`, that's 2 counts in Base's report, but only 1 count in FProfile.\n", "\n", "You can select a subset of the dataframe by using one of the five accessors: `get_specialization, get_method, get_file, get_function` and `get_module`." ] }, { "cell_type": "code", "execution_count": 4, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
count_pctstackframe
153.63derivative(::Function, ::Symbol, ::Symbol) at derivative.jl:3
20.66derivative(::Function, ::Symbol, ::Symbol) at derivative.jl:0
" ], "text/plain": [ "2×2 DataFrames.DataFrame\n", "│ Row │ count_pct │\n", "├─────┼───────────┤\n", "│ 1 │ 53.63 │\n", "│ 2 │ 0.66 │\n", "\n", "│ Row │ stackframe │\n", "├─────┼───────────────────────────────────────────────────────────────┤\n", "│ 1 │ derivative(::Function, ::Symbol, ::Symbol) at derivative.jl:3 │\n", "│ 2 │ derivative(::Function, ::Symbol, ::Symbol) at derivative.jl:0 │" ] }, "execution_count": 4, "metadata": {}, "output_type": "execute_result" } ], "source": [ "df[get_function.(df[:stackframe]) .== derivative, :] # select the `derivative` rows" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "It is common to focus optimization efforts on one or more modules at a time (... the ones you're developing). `flat(pd, MyModule)` filters out other modules and adds a useful column: `self_pct` measures how much `MyModule`-specific work is done on that line.\n", "\n", "For instance, in the code below, while the `do_computation()` call takes a long time (it has a high `count_percent`), it merely calls another `Main` function, so it has a low `self_pct`. `sum_of_sin` has `self_pct = 100%` because while it calls `sum` and `sin`, those are defined in another module (`Base`), and counted as external to `Main`. \n", "\n", "`flat(pd, (Module1, Module2, ...))` is also accepted." ] }, { "cell_type": "code", "execution_count": 5, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
count_pctself_pctstackframe
1100.00.0do_computation(::Int64) at In[5]:1
2100.0100.0sum_of_sin(::Int64) at In[5]:2
" ], "text/plain": [ "2×3 DataFrames.DataFrame\n", "│ Row │ count_pct │ self_pct │ stackframe │\n", "├─────┼───────────┼──────────┼────────────────────────────────────┤\n", "│ 1 │ 100.0 │ 0.0 │ do_computation(::Int64) at In[5]:1 │\n", "│ 2 │ 100.0 │ 100.0 │ sum_of_sin(::Int64) at In[5]:2 │" ] }, "execution_count": 5, "metadata": {}, "output_type": "execute_result" } ], "source": [ "@noinline do_computation(n) = sum_of_sin(n)\n", "@noinline sum_of_sin(n) = sum(sin, 1:n)\n", "pd2 = @fprofile do_computation(10000000)\n", "flat(pd2, Main)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "It pays to make sure that functions with a high `self_pct` are [well optimized](https://docs.julialang.org/en/latest/manual/performance-tips/).\n", "\n", "Another way to reduce the level of detail is to aggregate by `:specialization, :method, :file, :function`, or `:module`." ] }, { "cell_type": "code", "execution_count": 14, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
count_pctfunction
199.89IJulia.execute_request
299.89include_string
399.89IJulia.eventloop
499.89IJulia.#14
599.89FProfile.MissingInfo.missing_info
699.45Calculus.second_derivative
754.29Calculus.derivative
818.9Calculus.finite_difference_hessian
914.95Calculus.finite_difference
" ], "text/plain": [ "9×2 DataFrames.DataFrame\n", "│ Row │ count_pct │ function │\n", "├─────┼───────────┼────────────────────────────────────┤\n", "│ 1 │ 99.89 │ IJulia.execute_request │\n", "│ 2 │ 99.89 │ include_string │\n", "│ 3 │ 99.89 │ IJulia.eventloop │\n", "│ 4 │ 99.89 │ IJulia.#14 │\n", "│ 5 │ 99.89 │ FProfile.MissingInfo.missing_info │\n", "│ 6 │ 99.45 │ Calculus.second_derivative │\n", "│ 7 │ 54.29 │ Calculus.derivative │\n", "│ 8 │ 18.9 │ Calculus.finite_difference_hessian │\n", "│ 9 │ 14.95 │ Calculus.finite_difference │" ] }, "execution_count": 14, "metadata": {}, "output_type": "execute_result" } ], "source": [ "df_by_fn = flat(pd, combineby=:function)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "You can see the context (caller/called functions) around each of these rows by passing it to `tree`:" ] }, { "cell_type": "code", "execution_count": 15, "metadata": {}, "outputs": [ { "data": { "text/plain": [ " 136 .../finite_difference.jl:224; finite_difference_hessian(::Funct...\n", " 104 .../finite_difference.jl:55; finite_difference(::Calculus.##1#...\n", " 65 .../finite_difference.jl:55; finite_difference(::Base.#sin, ::...\n", " 57 ./math.jl:419; FProfile.MissingInfo.missing_info\n", " 27 .../finite_difference.jl:27; finite_difference(::Base.#sin, ::...\n", " 3 .../finite_difference.jl:0; finite_difference(::Base.#sin, ::...\n", " 1 .../finite_difference.jl:54; finite_difference(::Base.#sin, ::...\n", " 29 .../finite_difference.jl:27; finite_difference(::Calculus.##1#...\n", " 3 .../finite_difference.jl:0; finite_difference(::Calculus.##1#...\n" ] }, "execution_count": 15, "metadata": {}, "output_type": "execute_result" } ], "source": [ "tree(pd, df_by_fn, 9) # show the context of the 9th row of `df_by_method`" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Other useful dataframe commands:\n", "\n", "```julia\n", "sort(df, :self_pct, rev=true) # sort by self_pct\n", "showall(df) # show the whole dataframe\n", "```\n", "\n", "See `?flat` for more options." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "#### Comparing results\n", "\n", "Pass two `ProfileData` objects to `flat` to compare them. The results are sorted with the biggest regressions (in absolute terms) at the top and the biggest improvements at the bottom (see `?DataFrames.tail`)." ] }, { "cell_type": "code", "execution_count": 8, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
count_pct_1count_pct_2count_pct_difffunction
114.9516.211.26Calculus.finite_difference
218.919.961.06Calculus.finite_difference_hessian
399.4599.560.11Calculus.second_derivative
499.8999.78-0.11IJulia.execute_request
599.8999.78-0.11include_string
699.8999.78-0.11IJulia.eventloop
799.8999.78-0.11IJulia.#14
899.8999.78-0.11FProfile.MissingInfo.missing_info
954.2952.48-1.81Calculus.derivative
" ], "text/plain": [ "9×4 DataFrames.DataFrame\n", "│ Row │ count_pct_1 │ count_pct_2 │ count_pct_diff │\n", "├─────┼─────────────┼─────────────┼────────────────┤\n", "│ 1 │ 14.95 │ 16.21 │ 1.26 │\n", "│ 2 │ 18.9 │ 19.96 │ 1.06 │\n", "│ 3 │ 99.45 │ 99.56 │ 0.11 │\n", "│ 4 │ 99.89 │ 99.78 │ -0.11 │\n", "│ 5 │ 99.89 │ 99.78 │ -0.11 │\n", "│ 6 │ 99.89 │ 99.78 │ -0.11 │\n", "│ 7 │ 99.89 │ 99.78 │ -0.11 │\n", "│ 8 │ 99.89 │ 99.78 │ -0.11 │\n", "│ 9 │ 54.29 │ 52.48 │ -1.81 │\n", "\n", "│ Row │ function │\n", "├─────┼────────────────────────────────────┤\n", "│ 1 │ Calculus.finite_difference │\n", "│ 2 │ Calculus.finite_difference_hessian │\n", "│ 3 │ Calculus.second_derivative │\n", "│ 4 │ IJulia.execute_request │\n", "│ 5 │ include_string │\n", "│ 6 │ IJulia.eventloop │\n", "│ 7 │ IJulia.#14 │\n", "│ 8 │ FProfile.MissingInfo.missing_info │\n", "│ 9 │ Calculus.derivative │" ] }, "execution_count": 8, "metadata": {}, "output_type": "execute_result" } ], "source": [ "pd2 = @fprofile 1000000 second_derivative(sin, 1.0)\n", "flat(pd, pd2, combineby=:function)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Of course, this is most useful when comparing different algorithms or commits (use `reload` or [Revise.jl](https://github.com/timholy/Revise.jl) to update your code). The differences in the above table are just noise." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Tree view\n", "\n", "FProfile's tree view looks the same as `Base.Profile.print(format=:tree)`. The numbers represent raw counts. (If some branches seem out of place, see [this issue](https://github.com/JuliaLang/julia/issues/9689))" ] }, { "cell_type": "code", "execution_count": 9, "metadata": {}, "outputs": [ { "data": { "text/plain": [ " 909 ./task.jl:335; (::IJulia.##14#17)()\n", " 909 ...Julia/src/eventloop.jl:8; eventloop(::ZMQ.Socket)\n", " 909 ...rc/execute_request.jl:154; execute_request(::ZMQ.Socket, ::...\n", " 909 ...Compat/src/Compat.jl:464; include_string(::Module, ::Stri...\n", " 909 ./loading.jl:515; include_string(::String, ::String)\n", " 909 ./:?; FProfile.MissingInfo.missing_info\n", " 909 ...ile/src/FProfile.jl:52; FProfile.MissingInfo.missing_info\n", " 909 ./profile.jl:23; FProfile.MissingInfo.missing_info\n", " 907 ...ile/src/FProfile.jl:67; FProfile.MissingInfo.missing_info\n", " 903 .../src/derivative.jl:71; second_derivative(::Function...\n", " 488 ...src/derivative.jl:3; derivative(::Function, ::Sy...\n", " 167 ...ite_difference.jl:224; finite_difference_hessian(:...\n", " 104 ...ite_difference.jl:55; finite_difference(::Calculu...\n", " 65 ...ite_difference.jl:55; finite_difference(::Base.#s...\n", " 57 ./math.jl:419; FProfile.MissingInfo.missi...\n", " 1 ./math.jl:300; FProfile.MissingInfo.missi...\n", " 27 ...ite_difference.jl:27; finite_difference(::Base.#s...\n", " 3 ...ite_difference.jl:0; finite_difference(::Base.#s...\n", " 1 ...ite_difference.jl:54; finite_difference(::Base.#s...\n", " 29 ...ite_difference.jl:27; finite_difference(::Calculu...\n", " 3 ...ite_difference.jl:0; finite_difference(::Calculu...\n", " 5 ...ite_difference.jl:0; finite_difference_hessian(:...\n", " 5 ...src/derivative.jl:0; derivative(::Function, ::Sy...\n", " 2 .../src/derivative.jl:0; second_derivative(::Function...\n", " 1 ...lus/src/derivative.jl:0; derivative(::Function, ::Symbol, ...\n" ] }, "execution_count": 9, "metadata": {}, "output_type": "execute_result" } ], "source": [ "tr = tree(pd)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Like `flat` reports, trees can be aggregated by `:specialization, :method, :file, :function`, or `:module`:" ] }, { "cell_type": "code", "execution_count": 10, "metadata": {}, "outputs": [ { "data": { "text/plain": [ " 909 IJulia\n", " 909 Compat\n", " 909 Base\n", " 909 FProfile.MissingInfo\n", " 905 Calculus\n", " 57 FProfile.MissingInfo\n", " 1 Calculus\n" ] }, "execution_count": 10, "metadata": {}, "output_type": "execute_result" } ], "source": [ "tree(pd, combineby=:module)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "If you're only interested in a particular module/file/method/function, you can pass it to `tree`, along with an optional _neighborhood range_." ] }, { "cell_type": "code", "execution_count": 11, "metadata": {}, "outputs": [ { "data": { "text/plain": [ " 905 ...rofile/src/FProfile.jl:67; FProfile.MissingInfo.missing_info\n", " 903 ...lus/src/derivative.jl:71; second_derivative(::Function, ::F...\n", " 488 ...lus/src/derivative.jl:3; derivative(::Function, ::Symbol,...\n", " 167 .../finite_difference.jl:224; finite_difference_hessian(::Func...\n", " 5 .../finite_difference.jl:0; finite_difference_hessian(::Func...\n", " 5 ...lus/src/derivative.jl:0; derivative(::Function, ::Symbol,...\n", " 2 ...lus/src/derivative.jl:0; second_derivative(::Function, ::F...\n" ] }, "execution_count": 11, "metadata": {}, "output_type": "execute_result" } ], "source": [ "tr_deriv = tree(pd, second_derivative, -1:1) # -1:1 = show one level of callers and one level of called functions" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Trees are an indexable, prunable (use `prune(tree, depth)`) and filterable datastructure. Use the accessors (see above) and `is_inline/is_C_call` in your `filter` predicate." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# ProfileView integration\n", "\n", "`ProfileData` objects can be passed to `ProfileView.view`. This is purely a convenience; it's equivalent to normal ProfileView usage. See [ProfileView.jl](https://github.com/timholy/ProfileView.jl) for details.\n", "\n", "```julia\n", "using ProfileView\n", "pd = @fprofile ...\n", "ProfileView.view(pd)\n", "```" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Backtraces\n", "\n", "(if you want to build your own analysis)\n", "\n", "The raw profiler data is available either through `Base.Profile.retrieve()`, or through `pd.data` and `pd.lidict`. However, you might find `FProfile.backtraces(::ProfileData)` more immediately useful. " ] }, { "cell_type": "code", "execution_count": 12, "metadata": {}, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "count = 2\n" ] }, { "data": { "text/plain": [ "8-element Array{StackFrame,1}:\n", " (::IJulia.##14#17)() at task.jl:335 \n", " eventloop(::ZMQ.Socket) at eventloop.jl:8 \n", " execute_request(::ZMQ.Socket, ::IJulia.Msg) at execute_request.jl:154\n", " include_string(::Module, ::String, ::String) at Compat.jl:464 \n", " include_string(::String, ::String) at loading.jl:515 \n", " anonymous at :? \n", " macro expansion at FProfile.jl:52 [inlined] \n", " macro expansion at profile.jl:23 [inlined] " ] }, "execution_count": 12, "metadata": {}, "output_type": "execute_result" } ], "source": [ "count, trace = backtraces(pd)[1] # get the first unique backtrace\n", "@show count # the number of times that trace occurs in the raw data\n", "trace" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Use the `get_method, get_file, ...` functions on `StackFrame` objects (see above). `tree(pd::ProfileData)` is defined as `tree(backtraces(pd))`, and similarly for `flat`, so you can modify the backtraces and get a tree/flat view of the results." ] } ], "metadata": { "kernelspec": { "display_name": "Julia 0.6.0 (Programa)", "language": "julia", "name": "julia-0.6-programa" }, "language_info": { "file_extension": ".jl", "mimetype": "application/julia", "name": "julia", "version": "0.6.0" } }, "nbformat": 4, "nbformat_minor": 2 }