{
"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_pct | stackframe |
---|
1 | 99.89 | execute_request(::ZMQ.Socket, ::IJulia.Msg) at execute_request.jl:154 |
---|
2 | 99.89 | anonymous at <missing>:? |
---|
3 | 99.89 | macro expansion at FProfile.jl:52 [inlined] |
---|
4 | 99.89 | (::IJulia.##14#17)() at task.jl:335 |
---|
5 | 99.89 | eventloop(::ZMQ.Socket) at eventloop.jl:8 |
---|
6 | 99.89 | macro expansion at profile.jl:23 [inlined] |
---|
7 | 99.89 | include_string(::Module, ::String, ::String) at Compat.jl:464 |
---|
8 | 99.89 | include_string(::String, ::String) at loading.jl:515 |
---|
9 | 99.67 | macro expansion at FProfile.jl:67 [inlined] |
---|
10 | 99.23 | second_derivative(::Function, ::Float64) at derivative.jl:71 |
---|
11 | 53.63 | derivative(::Function, ::Symbol, ::Symbol) at derivative.jl:3 |
---|
12 | 18.35 | finite_difference_hessian(::Function, ::Function, ::Float64, ::Symbol) at finite_difference.jl:224 |
---|
13 | 11.43 | finite_difference(::Calculus.##1#3{Base.#sin,Symbol}, ::Float64, ::Symbol) at finite_difference.jl:55 |
---|
14 | 6.26 | sin at math.jl:419 [inlined] |
---|
15 | 6.15 | finite_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_pct | stackframe |
---|
1 | 53.63 | derivative(::Function, ::Symbol, ::Symbol) at derivative.jl:3 |
---|
2 | 0.66 | derivative(::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_pct | self_pct | stackframe |
---|
1 | 100.0 | 0.0 | do_computation(::Int64) at In[5]:1 |
---|
2 | 100.0 | 100.0 | sum_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_pct | function |
---|
1 | 99.89 | IJulia.execute_request |
---|
2 | 99.89 | include_string |
---|
3 | 99.89 | IJulia.eventloop |
---|
4 | 99.89 | IJulia.#14 |
---|
5 | 99.89 | FProfile.MissingInfo.missing_info |
---|
6 | 99.45 | Calculus.second_derivative |
---|
7 | 54.29 | Calculus.derivative |
---|
8 | 18.9 | Calculus.finite_difference_hessian |
---|
9 | 14.95 | Calculus.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_1 | count_pct_2 | count_pct_diff | function |
---|
1 | 14.95 | 16.21 | 1.26 | Calculus.finite_difference |
---|
2 | 18.9 | 19.96 | 1.06 | Calculus.finite_difference_hessian |
---|
3 | 99.45 | 99.56 | 0.11 | Calculus.second_derivative |
---|
4 | 99.89 | 99.78 | -0.11 | IJulia.execute_request |
---|
5 | 99.89 | 99.78 | -0.11 | include_string |
---|
6 | 99.89 | 99.78 | -0.11 | IJulia.eventloop |
---|
7 | 99.89 | 99.78 | -0.11 | IJulia.#14 |
---|
8 | 99.89 | 99.78 | -0.11 | FProfile.MissingInfo.missing_info |
---|
9 | 54.29 | 52.48 | -1.81 | Calculus.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
}