From e278467a0e03aae7daf376042e9486e03a5b326e Mon Sep 17 00:00:00 2001 From: Cedric St-Jean <cedric.stjean@gmail.com> Date: Wed, 25 Oct 2017 05:10:36 -0400 Subject: [PATCH] Change filter to accept nodes --- Manual.ipynb | 280 +++++++++++++++++++----------------------------- src/FProfile.jl | 63 ++++++----- 2 files changed, 148 insertions(+), 195 deletions(-) diff --git a/Manual.ipynb b/Manual.ipynb index 528ea6a..4e73974 100644 --- a/Manual.ipynb +++ b/Manual.ipynb @@ -4,7 +4,7 @@ "cell_type": "markdown", "metadata": {}, "source": [ - "FProfile.jl provides an alternative interface around Julia's [sampling profiler](https://docs.julialang.org/en/latest/manual/profile/). Please read the introduction of that document before proceeding if you've never used `@profile`.\n", + "[FProfile.jl](https://github.com/cstjean/FProfile.jl) provides an alternative interface for [Julia's sampling profiler](https://docs.julialang.org/en/latest/manual/profile/). Please read the introduction of that document before proceeding if you've never used `@profile`.\n", "\n", "# Profiling\n", "\n", @@ -13,24 +13,16 @@ }, { "cell_type": "code", - "execution_count": 2, + "execution_count": 1, "metadata": {}, "outputs": [ - { - "name": "stderr", - "output_type": "stream", - "text": [ - "\u001b[1m\u001b[36mINFO: \u001b[39m\u001b[22m\u001b[36mRecompiling stale cache file /Users/cedric/.julia/lib/v0.6/FProfile.ji for module FProfile.\n", - "\u001b[39m" - ] - }, { "data": { "text/plain": [ - "ProfileData(43 backtraces)" + "ProfileData(44 backtraces)" ] }, - "execution_count": 2, + "execution_count": 1, "metadata": {}, "output_type": "execute_result" } @@ -56,7 +48,7 @@ { "data": { "text/plain": [ - "ProfileData(1007 backtraces)" + "ProfileData(983 backtraces)" ] }, "execution_count": 3, @@ -92,17 +84,17 @@ { "data": { "text/html": [ - "<table class=\"data-frame\"><thead><tr><th></th><th>count_percent</th><th>stackframe</th><th>specialization</th><th>method</th><th>file</th><th>function</th><th>module</th></tr></thead><tbody><tr><th>1</th><td>99.9</td><td>execute_request(::ZMQ.Socket, ::IJulia.Msg) at execute_request.jl:154</td><td>MethodInstance for execute_request(::ZMQ.Socket, ::IJulia.Msg)</td><td>execute_request(socket, msg) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl:115</td><td>/Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl</td><td>IJulia.execute_request</td><td>IJulia</td></tr><tr><th>2</th><td>99.9</td><td>anonymous at <missing>:?</td><td>MethodInstance for missing_info()</td><td>missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:364</td><td>/Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl</td><td>FProfile.missing_info</td><td>FProfile</td></tr><tr><th>3</th><td>99.9</td><td>(::IJulia.##14#17)() at task.jl:335</td><td>MethodInstance for (::IJulia.##14#17)()</td><td>(::IJulia.##14#17)() in IJulia at task.jl:335</td><td>task.jl</td><td>IJulia.#14</td><td>IJulia</td></tr><tr><th>4</th><td>99.9</td><td>eventloop(::ZMQ.Socket) at eventloop.jl:8</td><td>MethodInstance for eventloop(::ZMQ.Socket)</td><td>eventloop(socket) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl:2</td><td>/Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl</td><td>IJulia.eventloop</td><td>IJulia</td></tr><tr><th>5</th><td>99.9</td><td>macro expansion at FProfile.jl:40 [inlined]</td><td>MethodInstance for missing_info()</td><td>missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:364</td><td>/Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl</td><td>FProfile.missing_info</td><td>FProfile</td></tr></tbody></table>" + "<table class=\"data-frame\"><thead><tr><th></th><th>count_percent</th><th>stackframe</th><th>specialization</th><th>method</th><th>file</th><th>function</th><th>module</th></tr></thead><tbody><tr><th>1</th><td>99.8</td><td>execute_request(::ZMQ.Socket, ::IJulia.Msg) at execute_request.jl:154</td><td>MethodInstance for execute_request(::ZMQ.Socket, ::IJulia.Msg)</td><td>execute_request(socket, msg) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl:115</td><td>/Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl</td><td>IJulia.execute_request</td><td>IJulia</td></tr><tr><th>2</th><td>99.8</td><td>anonymous at <missing>:?</td><td>MethodInstance for missing_info()</td><td>missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:369</td><td>/Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl</td><td>FProfile.missing_info</td><td>FProfile</td></tr><tr><th>3</th><td>99.8</td><td>(::IJulia.##14#17)() at task.jl:335</td><td>MethodInstance for (::IJulia.##14#17)()</td><td>(::IJulia.##14#17)() in IJulia at task.jl:335</td><td>task.jl</td><td>IJulia.#14</td><td>IJulia</td></tr><tr><th>4</th><td>99.8</td><td>eventloop(::ZMQ.Socket) at eventloop.jl:8</td><td>MethodInstance for eventloop(::ZMQ.Socket)</td><td>eventloop(socket) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl:2</td><td>/Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl</td><td>IJulia.eventloop</td><td>IJulia</td></tr><tr><th>5</th><td>99.8</td><td>macro expansion at FProfile.jl:40 [inlined]</td><td>MethodInstance for missing_info()</td><td>missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:369</td><td>/Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl</td><td>FProfile.missing_info</td><td>FProfile</td></tr></tbody></table>" ], "text/plain": [ "5×7 DataFrames.DataFrame\n", "│ Row │ count_percent │\n", "├─────┼───────────────┤\n", - "│ 1 │ 99.9 │\n", - "│ 2 │ 99.9 │\n", - "│ 3 │ 99.9 │\n", - "│ 4 │ 99.9 │\n", - "│ 5 │ 99.9 │\n", + "│ 1 │ 99.8 │\n", + "│ 2 │ 99.8 │\n", + "│ 3 │ 99.8 │\n", + "│ 4 │ 99.8 │\n", + "│ 5 │ 99.8 │\n", "\n", "│ Row │ stackframe │\n", "├─────┼───────────────────────────────────────────────────────────────────────┤\n", @@ -123,10 +115,10 @@ "│ Row │ method │\n", "├─────┼───────────────────────────────────────────────────────────────────────────────────────────────────────┤\n", "│ 1 │ execute_request(socket, msg) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl:115 │\n", - "│ 2 │ missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:364 │\n", + "│ 2 │ missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:369 │\n", "│ 3 │ (::IJulia.##14#17)() in IJulia at task.jl:335 │\n", "│ 4 │ eventloop(socket) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl:2 │\n", - "│ 5 │ missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:364 │\n", + "│ 5 │ missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:369 │\n", "\n", "│ Row │ file │\n", "├─────┼─────────────────────────────────────────────────────────┤\n", @@ -169,11 +161,9 @@ " df[df[:function].===derivative, :]\n", "```\n", "\n", - "It is common to focus optimization efforts on one module at a time (... the one you're developing). `flat(pd, MyModule)` filters out other modules and adds a useful column: `end_count_percent` 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 `end_count_percent`. `sum_of_sin` has `end_count_percent = ~87%` because while it calls `sum` and `sin`, those are defined in another module (`Base`), and counted as external.\n", + "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: `end_count_percent` measures how much `MyModule`-specific work is done on that line.\n", "\n", - "Why 87% and not 100%? That's a [bug in the profiler](https://github.com/JuliaLang/julia/issues/9689). \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 `end_count_percent`. `sum_of_sin` has `end_count_percent = 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." ] @@ -229,37 +219,37 @@ }, { "cell_type": "code", - "execution_count": 27, + "execution_count": 6, "metadata": {}, "outputs": [ { "data": { "text/html": [ - "<table class=\"data-frame\"><thead><tr><th></th><th>count_percent</th><th>method</th><th>file</th><th>function</th><th>module</th></tr></thead><tbody><tr><th>1</th><td>99.9</td><td>include_string(mod::Module, code::String, fname::String) in Compat at /Users/cedric/.julia/v0.6/Compat/src/Compat.jl:464</td><td>/Users/cedric/.julia/v0.6/Compat/src/Compat.jl</td><td>include_string</td><td>Compat</td></tr><tr><th>2</th><td>99.9</td><td>include_string(txt::String, fname::String) in Base at loading.jl:515</td><td>loading.jl</td><td>include_string</td><td>Base</td></tr><tr><th>3</th><td>99.9</td><td>execute_request(socket, msg) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl:115</td><td>/Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl</td><td>IJulia.execute_request</td><td>IJulia</td></tr><tr><th>4</th><td>99.9</td><td>eventloop(socket) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl:2</td><td>/Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl</td><td>IJulia.eventloop</td><td>IJulia</td></tr><tr><th>5</th><td>99.9</td><td>(::IJulia.##14#17)() in IJulia at task.jl:335</td><td>task.jl</td><td>IJulia.#14</td><td>IJulia</td></tr><tr><th>6</th><td>99.9</td><td>missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:364</td><td>/Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl</td><td>FProfile.missing_info</td><td>FProfile</td></tr><tr><th>7</th><td>99.8</td><td>second_derivative(f::Function, x::Number) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/derivative.jl:71</td><td>/Users/cedric/.julia/v0.6/Calculus/src/derivative.jl</td><td>Calculus.second_derivative</td><td>Calculus</td></tr><tr><th>8</th><td>55.71</td><td>derivative(f::Function, ftype::Symbol, dtype::Symbol) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/derivative.jl:2</td><td>/Users/cedric/.julia/v0.6/Calculus/src/derivative.jl</td><td>Calculus.derivative</td><td>Calculus</td></tr><tr><th>9</th><td>17.28</td><td>finite_difference_hessian(f::Function, g::Function, x::Number, dtype::Symbol) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl:224</td><td>/Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl</td><td>Calculus.finite_difference_hessian</td><td>Calculus</td></tr><tr><th>10</th><td>14.9</td><td>finite_difference(f::Function, x::T, dtype::Symbol) where T<:Number in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl:48</td><td>/Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl</td><td>Calculus.finite_difference</td><td>Calculus</td></tr></tbody></table>" + "<table class=\"data-frame\"><thead><tr><th></th><th>count_percent</th><th>method</th><th>file</th><th>function</th><th>module</th></tr></thead><tbody><tr><th>1</th><td>99.8</td><td>eventloop(socket) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl:2</td><td>/Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl</td><td>IJulia.eventloop</td><td>IJulia</td></tr><tr><th>2</th><td>99.8</td><td>include_string(txt::String, fname::String) in Base at loading.jl:515</td><td>loading.jl</td><td>include_string</td><td>Base</td></tr><tr><th>3</th><td>99.8</td><td>(::IJulia.##14#17)() in IJulia at task.jl:335</td><td>task.jl</td><td>IJulia.#14</td><td>IJulia</td></tr><tr><th>4</th><td>99.8</td><td>include_string(mod::Module, code::String, fname::String) in Compat at /Users/cedric/.julia/v0.6/Compat/src/Compat.jl:464</td><td>/Users/cedric/.julia/v0.6/Compat/src/Compat.jl</td><td>include_string</td><td>Compat</td></tr><tr><th>5</th><td>99.8</td><td>missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:369</td><td>/Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl</td><td>FProfile.missing_info</td><td>FProfile</td></tr><tr><th>6</th><td>99.8</td><td>execute_request(socket, msg) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl:115</td><td>/Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl</td><td>IJulia.execute_request</td><td>IJulia</td></tr><tr><th>7</th><td>99.19</td><td>second_derivative(f::Function, x::Number) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/derivative.jl:71</td><td>/Users/cedric/.julia/v0.6/Calculus/src/derivative.jl</td><td>Calculus.second_derivative</td><td>Calculus</td></tr><tr><th>8</th><td>47.71</td><td>derivative(f::Function, ftype::Symbol, dtype::Symbol) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/derivative.jl:2</td><td>/Users/cedric/.julia/v0.6/Calculus/src/derivative.jl</td><td>Calculus.derivative</td><td>Calculus</td></tr><tr><th>9</th><td>18.51</td><td>finite_difference_hessian(f::Function, g::Function, x::Number, dtype::Symbol) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl:224</td><td>/Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl</td><td>Calculus.finite_difference_hessian</td><td>Calculus</td></tr><tr><th>10</th><td>15.06</td><td>finite_difference(f::Function, x::T, dtype::Symbol) where T<:Number in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl:48</td><td>/Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl</td><td>Calculus.finite_difference</td><td>Calculus</td></tr></tbody></table>" ], "text/plain": [ "10×5 DataFrames.DataFrame\n", "│ Row │ count_percent │\n", "├─────┼───────────────┤\n", - "│ 1 │ 99.9 │\n", - "│ 2 │ 99.9 │\n", - "│ 3 │ 99.9 │\n", - "│ 4 │ 99.9 │\n", - "│ 5 │ 99.9 │\n", - "│ 6 │ 99.9 │\n", - "│ 7 │ 99.8 │\n", - "│ 8 │ 55.71 │\n", - "│ 9 │ 17.28 │\n", - "│ 10 │ 14.9 │\n", + "│ 1 │ 99.8 │\n", + "│ 2 │ 99.8 │\n", + "│ 3 │ 99.8 │\n", + "│ 4 │ 99.8 │\n", + "│ 5 │ 99.8 │\n", + "│ 6 │ 99.8 │\n", + "│ 7 │ 99.19 │\n", + "│ 8 │ 47.71 │\n", + "│ 9 │ 18.51 │\n", + "│ 10 │ 15.06 │\n", "\n", "│ Row │ method │\n", "├─────┼──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤\n", - "│ 1 │ include_string(mod::Module, code::String, fname::String) in Compat at /Users/cedric/.julia/v0.6/Compat/src/Compat.jl:464 │\n", + "│ 1 │ eventloop(socket) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl:2 │\n", "│ 2 │ include_string(txt::String, fname::String) in Base at loading.jl:515 │\n", - "│ 3 │ execute_request(socket, msg) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl:115 │\n", - "│ 4 │ eventloop(socket) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl:2 │\n", - "│ 5 │ (::IJulia.##14#17)() in IJulia at task.jl:335 │\n", - "│ 6 │ missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:364 │\n", + "│ 3 │ (::IJulia.##14#17)() in IJulia at task.jl:335 │\n", + "│ 4 │ include_string(mod::Module, code::String, fname::String) in Compat at /Users/cedric/.julia/v0.6/Compat/src/Compat.jl:464 │\n", + "│ 5 │ missing_info() in FProfile at /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl:369 │\n", + "│ 6 │ execute_request(socket, msg) in IJulia at /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl:115 │\n", "│ 7 │ second_derivative(f::Function, x::Number) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/derivative.jl:71 │\n", "│ 8 │ derivative(f::Function, ftype::Symbol, dtype::Symbol) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/derivative.jl:2 │\n", "│ 9 │ finite_difference_hessian(f::Function, g::Function, x::Number, dtype::Symbol) in Calculus at /Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl:224 │\n", @@ -267,12 +257,12 @@ "\n", "│ Row │ file │\n", "├─────┼─────────────────────────────────────────────────────────────┤\n", - "│ 1 │ /Users/cedric/.julia/v0.6/Compat/src/Compat.jl │\n", + "│ 1 │ /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl │\n", "│ 2 │ loading.jl │\n", - "│ 3 │ /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl │\n", - "│ 4 │ /Users/cedric/.julia/v0.6/IJulia/src/eventloop.jl │\n", - "│ 5 │ task.jl │\n", - "│ 6 │ /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl │\n", + "│ 3 │ task.jl │\n", + "│ 4 │ /Users/cedric/.julia/v0.6/Compat/src/Compat.jl │\n", + "│ 5 │ /Users/cedric/.julia/v0.6/FProfile/src/FProfile.jl │\n", + "│ 6 │ /Users/cedric/.julia/v0.6/IJulia/src/execute_request.jl │\n", "│ 7 │ /Users/cedric/.julia/v0.6/Calculus/src/derivative.jl │\n", "│ 8 │ /Users/cedric/.julia/v0.6/Calculus/src/derivative.jl │\n", "│ 9 │ /Users/cedric/.julia/v0.6/Calculus/src/finite_difference.jl │\n", @@ -280,19 +270,19 @@ "\n", "│ Row │ function │ module │\n", "├─────┼────────────────────────────────────┼──────────┤\n", - "│ 1 │ include_string │ Compat │\n", + "│ 1 │ IJulia.eventloop │ IJulia │\n", "│ 2 │ include_string │ Base │\n", - "│ 3 │ IJulia.execute_request │ IJulia │\n", - "│ 4 │ IJulia.eventloop │ IJulia │\n", - "│ 5 │ IJulia.#14 │ IJulia │\n", - "│ 6 │ FProfile.missing_info │ FProfile │\n", + "│ 3 │ IJulia.#14 │ IJulia │\n", + "│ 4 │ include_string │ Compat │\n", + "│ 5 │ FProfile.missing_info │ FProfile │\n", + "│ 6 │ IJulia.execute_request │ IJulia │\n", "│ 7 │ Calculus.second_derivative │ Calculus │\n", "│ 8 │ Calculus.derivative │ Calculus │\n", "│ 9 │ Calculus.finite_difference_hessian │ Calculus │\n", "│ 10 │ Calculus.finite_difference │ Calculus │" ] }, - "execution_count": 27, + "execution_count": 6, "metadata": {}, "output_type": "execute_result" } @@ -310,21 +300,22 @@ }, { "cell_type": "code", - "execution_count": 29, + "execution_count": 7, "metadata": {}, "outputs": [ { "data": { "text/plain": [ - " 174 ...ulus/src/derivative.jl:71; second_derivative(::Function, ::F...\n", - " 5 .../finite_difference.jl:0; finite_difference_hessian(::Func...\n", - " 169 .../finite_difference.jl:224; finite_difference_hessian(::Func...\n", - " 4 .../finite_difference.jl:0; finite_difference(::Calculus.##1...\n", - " 26 .../finite_difference.jl:27; finite_difference(::Calculus.##1...\n", - " 120 .../finite_difference.jl:55; finite_difference(::Calculus.##1...\n" + " 182 ...ulus/src/derivative.jl:71; second_derivative(::Function, ::F...\n", + " 4 .../finite_difference.jl:0; finite_difference_hessian(::Func...\n", + " 178 .../finite_difference.jl:224; finite_difference_hessian(::Func...\n", + " 5 .../finite_difference.jl:0; finite_difference(::Calculus.##1...\n", + " 23 .../finite_difference.jl:27; finite_difference(::Calculus.##1...\n", + " 1 .../finite_difference.jl:54; finite_difference(::Calculus.##1...\n", + " 118 .../finite_difference.jl:55; finite_difference(::Calculus.##1...\n" ] }, - "execution_count": 29, + "execution_count": 7, "metadata": {}, "output_type": "execute_result" } @@ -354,47 +345,49 @@ "source": [ "# Tree view\n", "\n", - "FProfile's tree view looks the same as `Base.Profile.print(format=:tree)`. The numbers represent raw counts." + "FProfile's tree view looks the same as `Base.Profile.print(format=:tree)`. The numbers represent raw counts. Some branches might seem [out of place](https://github.com/JuliaLang/julia/issues/9689)." ] }, { "cell_type": "code", - "execution_count": 19, + "execution_count": 8, "metadata": {}, "outputs": [ { "data": { "text/plain": [ - " 1006 ./task.jl:335; (::IJulia.##14#17)()\n", - " 1006 ...ulia/src/eventloop.jl:8; eventloop(::ZMQ.Socket)\n", - " 1006 ...c/execute_request.jl:154; execute_request(::ZMQ.Socket, :...\n", - " 1006 ...Compat/src/Compat.jl:464; include_string(::Module, ::Str...\n", - " 1006 ./loading.jl:515; include_string(::String, ::String)\n", - " 1006 ./<missing>:?; anonymous\n", - " 1006 ...ile/src/FProfile.jl:40; macro expansion\n", - " 1006 ./profile.jl:23; macro expansion\n", - " 1005 ...le/src/FProfile.jl:55; macro expansion\n", - " 5 .../src/derivative.jl:0; second_derivative(::Functio...\n", - " 1000 .../src/derivative.jl:71; second_derivative(::Functio...\n", - " 8 ...src/derivative.jl:0; derivative(::Function, ::Sy...\n", - " 552 ...src/derivative.jl:3; derivative(::Function, ::Sy...\n", - " 5 ...ite_difference.jl:0; finite_difference_hessian(:...\n", - " 169 ...ite_difference.jl:224; finite_difference_hessian(:...\n", - " 4 ...ite_difference.jl:0; finite_difference(::Calculu...\n", - " 26 ...ite_difference.jl:27; finite_difference(::Calculu...\n", - " 120 ...ite_difference.jl:55; finite_difference(::Calculu...\n", - " 2 ./math.jl:300; finite_difference(::Base.#...\n", - " 2 ...ite_difference.jl:0; finite_difference(::Base.#...\n", - " 31 ...ite_difference.jl:27; finite_difference(::Base.#...\n", + " 981 ./task.jl:335; (::IJulia.##14#17)()\n", + " 981 ...Julia/src/eventloop.jl:8; eventloop(::ZMQ.Socket)\n", + " 981 ...rc/execute_request.jl:154; execute_request(::ZMQ.Socket, ::...\n", + " 981 ...Compat/src/Compat.jl:464; include_string(::Module, ::Stri...\n", + " 981 ./loading.jl:515; include_string(::String, ::String)\n", + " 981 ./<missing>:?; anonymous\n", + " 981 ...ile/src/FProfile.jl:40; macro expansion\n", + " 981 ./profile.jl:23; macro expansion\n", + " 981 ...ile/src/FProfile.jl:55; macro expansion\n", + " 6 .../src/derivative.jl:0; second_derivative(::Function...\n", + " 969 .../src/derivative.jl:71; second_derivative(::Function...\n", + " 12 ...src/derivative.jl:0; derivative(::Function, ::Sy...\n", + " 1 ...src/derivative.jl:2; derivative(::Function, ::Sy...\n", + " 455 ...src/derivative.jl:3; derivative(::Function, ::Sy...\n", + " 4 ...ite_difference.jl:0; finite_difference_hessian(:...\n", + " 178 ...ite_difference.jl:224; finite_difference_hessian(:...\n", + " 5 ...ite_difference.jl:0; finite_difference(::Calculu...\n", + " 23 ...ite_difference.jl:27; finite_difference(::Calculu...\n", + " 1 ...ite_difference.jl:54; finite_difference(::Calculu...\n", + " 118 ...ite_difference.jl:55; finite_difference(::Calculu...\n", + " 3 ./math.jl:300; finite_difference(::Base.#...\n", + " 3 ...ite_difference.jl:0; finite_difference(::Base.#...\n", + " 27 ...ite_difference.jl:27; finite_difference(::Base.#...\n", " 1 ...ite_difference.jl:48; finite_difference(::Base.#...\n", - " 1 ...ite_difference.jl:54; finite_difference(::Base.#...\n", - " 63 ...ite_difference.jl:55; finite_difference(::Base.#...\n", - " 48 ./math.jl:419; sin\n", - " 2 ./math.jl:300; nan_dom_err\n", - " 1 ...lus/src/derivative.jl:0; derivative(::Function, ::Symbol,...\n" + " 2 ...ite_difference.jl:54; finite_difference(::Base.#...\n", + " 70 ...ite_difference.jl:55; finite_difference(::Base.#...\n", + " 58 ./math.jl:419; sin\n", + " 1 ...lus/src/derivative.jl:0; derivative(::Function, ::Symbol, ...\n", + " 1 .../finite_difference.jl:0; finite_difference(::Calculus.##1#...\n" ] }, - "execution_count": 19, + "execution_count": 8, "metadata": {}, "output_type": "execute_result" } @@ -412,35 +405,36 @@ }, { "cell_type": "code", - "execution_count": 24, + "execution_count": 13, "metadata": {}, "outputs": [ { "data": { "text/plain": [ - " 1005 ...ofile/src/FProfile.jl:55; macro expansion\n", - " 5 ...lus/src/derivative.jl:0; second_derivative(::Function, ::...\n", - " 1000 ...lus/src/derivative.jl:71; second_derivative(::Function, ::...\n", - " 8 ...lus/src/derivative.jl:0; derivative(::Function, ::Symbol,...\n", - " 552 ...lus/src/derivative.jl:3; derivative(::Function, ::Symbol,...\n", - " 5 .../finite_difference.jl:0; finite_difference_hessian(::Func...\n", - " 169 .../finite_difference.jl:224; finite_difference_hessian(::Func...\n" + " 975 ...rofile/src/FProfile.jl:55; macro expansion\n", + " 6 ...lus/src/derivative.jl:0; second_derivative(::Function, ::F...\n", + " 969 ...lus/src/derivative.jl:71; second_derivative(::Function, ::F...\n", + " 12 ...lus/src/derivative.jl:0; derivative(::Function, ::Symbol,...\n", + " 1 ...lus/src/derivative.jl:2; derivative(::Function, ::Symbol,...\n", + " 455 ...lus/src/derivative.jl:3; derivative(::Function, ::Symbol,...\n", + " 4 .../finite_difference.jl:0; finite_difference_hessian(::Func...\n", + " 178 .../finite_difference.jl:224; finite_difference_hessian(::Func...\n" ] }, - "execution_count": 24, + "execution_count": 13, "metadata": {}, "output_type": "execute_result" } ], "source": [ - "tree(pd, second_derivative, -1:1) # -1:1 = show one level of callers and one level of called functions" + "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 and filterable datastructure:" + "Trees are an indexable and filterable datastructure. Use `get_specialization, get_method, get_file, get_function, get_module, is_C_call` and `is_inlined` in your `filter` predicate." ] }, { @@ -451,22 +445,7 @@ { "data": { "text/plain": [ - " 5 ...lus/src/derivative.jl:0; second_derivative(::Function, ::F...\n", - " 1000 ...lus/src/derivative.jl:71; second_derivative(::Function, ::F...\n", - " 8 ...lus/src/derivative.jl:0; derivative(::Function, ::Symbol,...\n", - " 552 ...lus/src/derivative.jl:3; derivative(::Function, ::Symbol,...\n", - " 5 .../finite_difference.jl:0; finite_difference_hessian(::Func...\n", - " 169 .../finite_difference.jl:224; finite_difference_hessian(::Func...\n", - " 4 .../finite_difference.jl:0; finite_difference(::Calculus.##1...\n", - " 26 .../finite_difference.jl:27; finite_difference(::Calculus.##1...\n", - " 120 .../finite_difference.jl:55; finite_difference(::Calculus.##1...\n", - " 2 ./math.jl:300; finite_difference(::Base.#sin, :...\n", - " 2 .../finite_difference.jl:0; finite_difference(::Base.#sin, :...\n", - " 31 .../finite_difference.jl:27; finite_difference(::Base.#sin, :...\n", - " 1 .../finite_difference.jl:48; finite_difference(::Base.#sin, :...\n", - " 1 .../finite_difference.jl:54; finite_difference(::Base.#sin, :...\n", - " 63 .../finite_difference.jl:55; finite_difference(::Base.#sin, :...\n", - " 1 ...lus/src/derivative.jl:0; derivative(::Function, ::Symbol, ...\n" + "6 ...culus/src/derivative.jl:0; second_derivative(::Function, ::Float64)\n" ] }, "execution_count": 20, @@ -475,45 +454,7 @@ } ], "source": [ - "tr_calc = filter(sf->get_module(sf)===Calculus, tr)" - ] - }, - { - "cell_type": "code", - "execution_count": 21, - "metadata": {}, - "outputs": [ - { - "data": { - "text/plain": [ - "169 ...c/finite_difference.jl:224; finite_difference_hessian(::Funct...\n", - " 4 ...c/finite_difference.jl:0; finite_difference(::Calculus.##1#...\n", - " 26 ...c/finite_difference.jl:27; finite_difference(::Calculus.##1#...\n", - " 120 ...c/finite_difference.jl:55; finite_difference(::Calculus.##1#...\n", - " 2 ./math.jl:300; finite_difference(::Base.#sin, ::...\n", - " 2 .../finite_difference.jl:0; finite_difference(::Base.#sin, ::...\n", - " 31 .../finite_difference.jl:27; finite_difference(::Base.#sin, ::...\n", - " 1 .../finite_difference.jl:48; finite_difference(::Base.#sin, ::...\n", - " 1 .../finite_difference.jl:54; finite_difference(::Base.#sin, ::...\n", - " 63 .../finite_difference.jl:55; finite_difference(::Base.#sin, ::...\n" - ] - }, - "execution_count": 21, - "metadata": {}, - "output_type": "execute_result" - } - ], - "source": [ - "tr_calc[2, 4]" - ] - }, - { - "cell_type": "markdown", - "metadata": {}, - "source": [ - "The functions `get_specialization, get_method, get_file, get_function, get_module, is_C_call, is_inlined` all accept a `StackFrame` argument, and are useful to select the calls you care about (note that C calls are excluded by default; see `?tree`).\n", - "\n", - "Use `prune(tree, n_levels)` to limit the level of details." + "tr_deriv[1,1]" ] }, { @@ -529,7 +470,7 @@ }, { "cell_type": "code", - "execution_count": 17, + "execution_count": 12, "metadata": {}, "outputs": [ { @@ -542,21 +483,20 @@ { "data": { "text/plain": [ - "11-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 <missing>:? \n", - " macro expansion at FProfile.jl:40 [inlined] \n", - " macro expansion at profile.jl:23 [inlined] \n", - " macro expansion at FProfile.jl:55 [inlined] \n", - " second_derivative(::Function, ::Float64) at derivative.jl:71 \n", - " finite_difference_hessian(::Function, ::Function, ::Float64, ::Symbol) at finite_difference.jl:224" + "10-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 <missing>:? \n", + " macro expansion at FProfile.jl:40 [inlined] \n", + " macro expansion at profile.jl:23 [inlined] \n", + " macro expansion at FProfile.jl:55 [inlined] \n", + " second_derivative(::Function, ::Float64) at derivative.jl:71 " ] }, - "execution_count": 17, + "execution_count": 12, "metadata": {}, "output_type": "execute_result" } diff --git a/src/FProfile.jl b/src/FProfile.jl index e8a40d7..eb601db 100644 --- a/src/FProfile.jl +++ b/src/FProfile.jl @@ -81,21 +81,21 @@ get_module(m::Module) = m is_C_call(sf::StackFrame) = sf.from_c is_inlined(sf::StackFrame) = sf.inlined -symbol2accessor = OrderedDict(:stackframe=>get_stackframe, - # The line is already part of :stackframe, and grouping - # on :stackframe makes more sense anyway. - #:line=>get_line, - :specialization=>get_specialization, - :method=>get_method, - :file=>get_file, - :function=>get_function, - :module=>get_module) -type2symbol_dict = Dict(StackFrame=>:stackframe, - MethodInstance=>:specialization, - Method=>:method, - String=>:file, - Function=>:function, - Module=>:module)::Any +const symbol2accessor = OrderedDict(:stackframe=>get_stackframe, + # The line is already part of :stackframe, and + # grouping on :stackframe makes more sense anyway. + #:line=>get_line, + :specialization=>get_specialization, + :method=>get_method, + :file=>get_file, + :function=>get_function, + :module=>get_module) +const type2symbol_dict = Dict(StackFrame=>:stackframe, + MethodInstance=>:specialization, + Method=>:method, + String=>:file, + Function=>:function, + Module=>:module)::Any function type2symbol(T) for (typ, sym) in type2symbol_dict @@ -167,12 +167,14 @@ mutable struct Node count::Int children::Vector{Node} end -get_stackframe(node::Node) = node.sf Node(node::Node, children::Vector{Node}) = Node(node.sf, node.count, children) Base.getindex(node::Node, i::Int) = node.children[i] Base.getindex(node::Node, i::Int, args...) = node[i][args...] Base.length(node::Node) = length(node.children) - +for acc in (:get_stackframe, :get_specialization, :get_method, :get_file, :get_function, + :get_module) + @eval $acc(node::Node) = $acc(node.sf) +end # This filter code was taken from TraceCalls.jl filter_descendents(f, node) = # helper @@ -180,11 +182,9 @@ filter_descendents(f, node) = # helper isempty(node.children) ? Node[] : Node[n for child in node.children for n in filter_(f, child)] filter_(f, node) = - (f(get_stackframe(node)) ? [Node(node, filter_descendents(f, node))] : + (f(node) ? [Node(node, filter_descendents(f, node))] : filter_descendents(f, node)) -Base.filter(f::Function, node::Node) = - # Apply f(::StackFrame) - Node(node, filter_descendents(f, node)) +Base.filter(f::Function, node::Node) = Node(node, filter_descendents(f, node)) Base.map(f::Function, node::Node) = # Apply f(::Node), leaves first f(Node(node, Node[map(f, child) for child in node.children])) @@ -289,9 +289,18 @@ function Base.show(io::IO, node::Node) end end -tree(pd::ProfileData; C = false, mincount::Int = 0, noisefloor = 0) = - tree(backtraces(pd; C=C); mincount=mincount, noisefloor=noisefloor) -function tree(bt::BackTraces; mincount::Int = 0, noisefloor = 0) +""" `tree(pd::ProfileData; C = false, mincount::Int = 0, maxdepth=-1)` displays a tree +of function calls, along with the number of backtraces going through each call. + + - `C` -- If `true`, backtraces from C and Fortran code are shown (normally they are excluded). + + - `maxdepth` -- Limits the depth higher than `maxdepth` in the `:tree` format. + + - `mincount` -- Limits the printout to only those lines with at least `mincount` occurrences. +""" +tree(pd::ProfileData; C = false, mincount::Int = 0, maxdepth=-1) = + tree(backtraces(pd; C=C); mincount=mincount, maxdepth=maxdepth) +function tree(bt::BackTraces; mincount::Int = 0, maxdepth=-1) # We start with an empty Node tree, then iterate over every trace, adding counts and # new branches. root = FProfile.Node(FProfile.UNKNOWN, -1, []) @@ -312,8 +321,12 @@ function tree(bt::BackTraces; mincount::Int = 0, noisefloor = 0) end end # Sort the children in each node alphabetically. See Profile.liperm. - return map(n->Node(n, n.children[Profile.liperm(map(get_stackframe, n.children))]), + root = map(n->Node(n, n.children[Profile.liperm(map(get_stackframe, n.children))]), root) + if maxdepth != -1 + root = prune(root, maxdepth) + end + return filter(node->node.count >= mincount, root) end function tree(pd::ProfileData, object::T, neighborhood::UnitRange=-1:1; kwargs...) where T