{ "cells": [ { "cell_type": "markdown", "metadata": {}, "source": [ "# Contents\n", "\n", "[Overview](#Overview)\n", "\n", "[Tracing code](#Tracing-code)\n", " * [Syntax](#Syntax)\n", " * [Tracing tips](#Tracing-tips)\n", " * [Implementation](#Implementation-of-@trace)\n", "\n", "[Manipulating traces](#Manipulating-traces)\n", " * [Custom text/HTML](#Custom-text/HTML)\n", " * [Map, filter, collect](#Map,-filter,-collect)\n", "\n", "[Saving traces to disk](#Saving-traces-to-disk)\n", "\n", "[Working with mutable state](#Working-with-mutable-state)\n", "\n", "[Debugging with traces](#Debugging-with-traces)\n", " * [Debugging test failures](#Debugging-test-failures)\n", " * [Displaying extra information](#Displaying-extra-information)\n", "\n", "[Profiling](#Profiling)\n", " * [Type stability](#Type-stability)\n", " * [Grouping and benchmarking](#Grouping-and-benchmarking)\n", " * [Profiling the compiler](#Profiling-the-compiler)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Overview\n", "\n", "[TraceCalls.jl](https://github.com/cstjean/TraceCalls.jl) is a functional tracing package for debugging and exploring Julia code. It records and displays a tree of function calls. For example, here is how [Calculus.jl](https://github.com/johnmyleswhite/Calculus.jl) computes the second-derivative of `sin(x) + sqrt(x)`:" ] }, { "cell_type": "code", "execution_count": 1, "metadata": { "scrolled": false }, "outputs": [ { "data": { "text/html": [ "
#1() => -1.0914708926553454
" ], "text/plain": [ "- #1() => \u001b[1m\u001b[32m-1.0914708926553454\u001b[39m\u001b[22m\n", " - Calculus.second_derivative(f, 1.0) => \u001b[1m\u001b[32m-1.0914708926553454\u001b[39m\u001b[22m\n", " - Calculus.derivative(f, :central) => \u001b[1m\u001b[32mCalculus.#20\u001b[39m\u001b[22m\n", " - Calculus.derivative(f, :scalar, :central) => \u001b[1m\u001b[32mCalculus.#20\u001b[39m\u001b[22m\n", " - Calculus.finite_difference_hessian(f, Calculus.#20, 1.0, :central) => \u001b[1m\u001b[32m-1.0914708926553454\u001b[39m\u001b[22m\n", " - Calculus.finite_difference(Calculus.#20, 1.0, :central) => \u001b[1m\u001b[32m-1.0914708926553454\u001b[39m\u001b[22m\n", " - Calculus.finite_difference(f, 1.0000060554544523, :central) => \u001b[1m\u001b[32m1.0402956965076036\u001b[39m\u001b[22m\n", " - f(1.0000121109455733) => \u001b[1m\u001b[32m1.8414835837724568\u001b[39m\u001b[22m\n", " - f(0.9999999999633314) => \u001b[1m\u001b[32m1.8414709847697501\u001b[39m\u001b[22m\n", " - Calculus.finite_difference(f, 0.9999939445455476, :central) => \u001b[1m\u001b[32m1.0403089152121567\u001b[39m\u001b[22m\n", " - f(1.0) => \u001b[1m\u001b[32m1.8414709848078965\u001b[39m\u001b[22m\n", " - f(0.9999878890910952) => \u001b[1m\u001b[32m1.8414583857213915\u001b[39m\u001b[22m\n" ] }, "execution_count": 1, "metadata": {}, "output_type": "execute_result" } ], "source": [ "using Calculus, TraceCalls\n", "\n", "@traceable f(x) = sin(x) + sqrt(x)\n", "trace_derivative = @trace Calculus second_derivative(f, 1.0)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "The output of `@trace` is a `Trace` object --- an explorable tree-like datastructure:" ] }, { "cell_type": "code", "execution_count": 2, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
Calculus.derivative(f, :central) => Calculus.#20
" ], "text/plain": [ "- Calculus.derivative(f, :central) => \u001b[1m\u001b[32mCalculus.#20\u001b[39m\u001b[22m\n", " - Calculus.derivative(f, :scalar, :central) => \u001b[1m\u001b[32mCalculus.#20\u001b[39m\u001b[22m\n" ] }, "execution_count": 2, "metadata": {}, "output_type": "execute_result" } ], "source": [ "trace_derivative[1][1] # get the first call of the first call." ] }, { "cell_type": "code", "execution_count": 3, "metadata": {}, "outputs": [ { "data": { "text/plain": [ ":central" ] }, "execution_count": 3, "metadata": {}, "output_type": "execute_result" } ], "source": [ "trace_derivative[1][1].args[2] # get its second argument" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "It can work as a [more-informative stack-trace](#Debugging-with-traces) (which contains _values_ rather than just types - see `@stacktrace`):" ] }, { "cell_type": "code", "execution_count": 4, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#3() => DomainError()
" ], "text/plain": [ "- #3() => \u001b[31mDomainError()\u001b[39m\n", " - Calculus.second_derivative(f, 0.0) => \u001b[31mDomainError()\u001b[39m\n", " - Calculus.derivative(f, :central) => \u001b[1m\u001b[32mCalculus.#58\u001b[39m\u001b[22m\n", " - Calculus.derivative(f, :scalar, :central) => \u001b[1m\u001b[32mCalculus.#58\u001b[39m\u001b[22m\n", " - Calculus.finite_difference_hessian(f, Calculus.#58, 0.0, :central) => \u001b[31mDomainError()\u001b[39m\n", " - Calculus.finite_difference(Calculus.#58, 0.0, :central) => \u001b[31mDomainError()\u001b[39m\n", " - Calculus.finite_difference(f, 6.0554544523933395e-6, :central) => \u001b[1m\u001b[32m288.35028436717505\u001b[39m\u001b[22m\n", " - f(1.2110908904786679e-5) => \u001b[1m\u001b[32m0.0034921840266401915\u001b[39m\u001b[22m\n", " - f(0.0) => \u001b[1m\u001b[32m0.0\u001b[39m\u001b[22m\n", " - Calculus.finite_difference(f, -6.0554544523933395e-6, :central) => \u001b[31mDomainError()\u001b[39m\n", " - f(0.0) => \u001b[1m\u001b[32m0.0\u001b[39m\u001b[22m\n", " - f(-1.2110908904786679e-5) => \u001b[31mDomainError()\u001b[39m\n" ] }, "execution_count": 4, "metadata": {}, "output_type": "execute_result" } ], "source": [ "@trace Calculus second_derivative(f, 0.0)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "And finally, since full call data is recorded, we can rerun every part of the trace for [profiling](#Profiling), [debugging](#Debugging-with-traces), and testing." ] }, { "cell_type": "code", "execution_count": 18, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#1() => 256
" ], "text/plain": [ "- #1() => \u001b[1m\u001b[32m\u001b[38;2;255;0;0m256\u001b[39m\u001b[39m\u001b[22m\n", " - Calculus.second_derivative(f, 1.0) => \u001b[1m\u001b[32m\u001b[38;2;255;0;0m256\u001b[39m\u001b[39m\u001b[22m\n", " - Calculus.derivative(f, :central) => \u001b[1m\u001b[32m\u001b[38;2;255;0;0m208\u001b[39m\u001b[39m\u001b[22m\n", " - Calculus.derivative(f, :scalar, :central) => \u001b[1m\u001b[32m\u001b[38;2;255;0;0m208\u001b[39m\u001b[39m\u001b[22m\n", " - Calculus.finite_difference_hessian(f, Calculus.#20, 1.0, :central) => \u001b[1m\u001b[32m\u001b[38;2;255;0;0m16\u001b[39m\u001b[39m\u001b[22m\n", " - Calculus.finite_difference(Calculus.#20, 1.0, :central) => \u001b[1m\u001b[32m\u001b[38;2;255;0;0m16\u001b[39m\u001b[39m\u001b[22m\n", " - Calculus.finite_difference(f, 1.0000060554544523, :central) => \u001b[1m\u001b[32m\u001b[38;2;0;255;0m0\u001b[39m\u001b[39m\u001b[22m\n", " - f(1.0000121109455733) => \u001b[1m\u001b[32m\u001b[38;2;0;255;0m0\u001b[39m\u001b[39m\u001b[22m\n", " - f(0.9999999999633314) => \u001b[1m\u001b[32m\u001b[38;2;0;255;0m0\u001b[39m\u001b[39m\u001b[22m\n", " - Calculus.finite_difference(f, 0.9999939445455476, :central) => \u001b[1m\u001b[32m\u001b[38;2;0;255;0m0\u001b[39m\u001b[39m\u001b[22m\n", " - f(1.0) => \u001b[1m\u001b[32m\u001b[38;2;0;255;0m0\u001b[39m\u001b[39m\u001b[22m\n", " - f(0.9999878890910952) => \u001b[1m\u001b[32m\u001b[38;2;0;255;0m0\u001b[39m\u001b[39m\u001b[22m\n" ] }, "execution_count": 18, "metadata": {}, "output_type": "execute_result" } ], "source": [ "greenred(map(:@allocated, trace_derivative)) # compute how many bytes were allocated in each function call" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Tracing code\n", "\n", "#### Syntax\n", "\n", "```julia\n", "@traceable function foo()\n", "...\n", "end\n", "\n", "@trace (some_function, SomeModule, \"some_interactively_included_file.jl\") bar(1)\n", "```\n", "\n", "This call to `@trace` will execute `bar(1)` while tracing all methods of `some_function`, all methods defined in `SomeModule / \"some_interactively_included_file.jl\"`, and all methods defined with `@traceable` (in this case, `foo()`). \n", "\n", "Tracing Julia code involves a fair amount of code analysis; TraceCalls.jl will error, warn, or silently skip (when tracing a module) the following:\n", "\n", " - Inner constructors\n", " - Functions that are defined by `eval`\n", " - Callable objects (eg. `(func::Functor)(x) = ...`)\n", " \n", "The `@traceable` macro (to be used primarily for interactively-defined functions) remembers the function definition without modifying it. It has no impact on the performance of your code.\n", "\n", "#### Tracing tips\n", "\n", "It might be tempting to run `@trace MyModule some_long_computation()`, but a) there is a small cost to every traced call, and b) a trace with a million calls is too large and unwieldy to be of much use anyway. If you are only interested in the details of one particular `my_fun` call that happens during `some_long_computation()`, then it's usually better to do this:\n", "\n", "```julia\n", "trace_my_fun = @trace my_fun some_long_computation() # fast, because we're only tracing one function\n", "trace = @trace MyModule trace_my_fun[3]() # select the third `my_fun()` call, and trace it fully\n", "```\n", "\n", "This strategy also works with [`@stacktrace`](#Debugging-with-traces). \n", "\n", "#### Implementation of @trace\n", "\n", "`@trace some_fn foo(10)` performs these operations:\n", "\n", "1. Find the source code of `some_fn`\n", "2. Replace the definition(s) of `some_fn` with a tracing version (using `eval`)\n", "3. Run `foo(10)`\n", "4. Restore the original definition(s) of `some_fn` (using `eval`)\n", "\n", "The downside of this scheme is that `@trace` can trigger significant JIT compiling time. Tracing large modules can be slow the first time around, but caching is used to avoid repeated computations." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Manipulating traces\n", "\n", "Consider computing a [random walk](https://en.wikipedia.org/wiki/Random_walk) on a small graph, using [LightGraphs.jl](http://juliagraphs.github.io/LightGraphs.jl/latest/)" ] }, { "cell_type": "code", "execution_count": 1, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#1() => [2, 1, 2, 3, 2]
" ], "text/plain": [ "- #1() => \u001b[1m\u001b[32m[2, 1, 2, 3, 2]\u001b[39m\u001b[22m\n", " - LightGraphs.randomwalk({3, 2} undirected simple Int64 graph, 2, 5) => \u001b[1m\u001b[32m[2, 1, 2, 3, 2]\u001b[39m\u001b[22m\n", " - eltype({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mInt64\u001b[39m\u001b[22m\n", " - LightGraphs.vertices({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m1:3\u001b[39m\u001b[22m\n", " - LightGraphs.nv({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m3\u001b[39m\u001b[22m\n", " - eltype({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mInt64\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mArray{Int64,1}[[2], [1, 3], [2]]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 3) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 3) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n" ] }, "execution_count": 1, "metadata": {}, "output_type": "execute_result" } ], "source": [ "using LightGraphs, TraceCalls\n", "\n", "graph = Graph(3) # build an undirected graph with three connected vertices\n", "add_edge!(graph, 1, 2); add_edge!(graph, 2, 3) \n", "\n", "trace_walk = @trace LightGraphs randomwalk(graph, 2, 5)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "The trace can be indexed:" ] }, { "cell_type": "code", "execution_count": 2, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => [1, 3]
" ], "text/plain": [ "- LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n" ] }, "execution_count": 2, "metadata": {}, "output_type": "execute_result" } ], "source": [ "trace_walk[1][3] # can also be written trace_walk[1,3]" ] }, { "cell_type": "code", "execution_count": 3, "metadata": {}, "outputs": [ { "data": { "text/plain": [ "2" ] }, "execution_count": 3, "metadata": {}, "output_type": "execute_result" } ], "source": [ "trace_walk[1][3][:v] # get the second argument by name. To get it by position, use trace_walk[1][3].args[2]" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Called:" ] }, { "cell_type": "code", "execution_count": 4, "metadata": {}, "outputs": [ { "data": { "text/plain": [ "2-element Array{Int64,1}:\n", " 1\n", " 3" ] }, "execution_count": 4, "metadata": {}, "output_type": "execute_result" } ], "source": [ "trace_walk[1,3]() # call `LightGraphs.out_neighbors(...)`" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Or pruned (useful for exploring large traces):" ] }, { "cell_type": "code", "execution_count": 5, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#1() => [2, 1, 2, 3, 2]
" ], "text/plain": [ "- #1() => \u001b[1m\u001b[32m[2, 1, 2, 3, 2]\u001b[39m\u001b[22m\n", " - LightGraphs.randomwalk({3, 2} undirected simple Int64 graph, 2, 5) => \u001b[1m\u001b[32m[2, 1, 2, 3, 2]\u001b[39m\u001b[22m\n", " - eltype({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mInt64\u001b[39m\u001b[22m\n", " - LightGraphs.vertices({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m1:3\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n" ] }, "execution_count": 5, "metadata": {}, "output_type": "execute_result" } ], "source": [ "pruned_trace = prune(trace_walk, \n", " 2, # maximum depth\n", " 4) # maximum length of each trace (eg. if foo() calls bar() 100 times, keep the first 4 times)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "A subcall of a pruned/filtered trace can be reexpanded by retracing it:" ] }, { "cell_type": "code", "execution_count": 8, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#7() => 1:3
" ], "text/plain": [ "- #7() => \u001b[1m\u001b[32m1:3\u001b[39m\u001b[22m\n", " - LightGraphs.vertices({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m1:3\u001b[39m\u001b[22m\n", " - LightGraphs.nv({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m3\u001b[39m\u001b[22m\n", " - eltype({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mInt64\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mArray{Int64,1}[[2], [1, 3], [2]]\u001b[39m\u001b[22m\n" ] }, "execution_count": 8, "metadata": {}, "output_type": "execute_result" } ], "source": [ "@trace LightGraphs pruned_trace[1, 2]() # don't forget the (); it triggers the computation for that call" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "#### Custom text/HTML\n", "\n", "TraceCalls.jl calls `TraceCalls.show_val(io::IO, mime, x)` to display each argument and return value. It defaults to `show(io, x)`, but can be customized, either to highlight certain values, or to shorten objects that are not important for the task at hand. Implement `TraceCalls.show_val(::IO, ::MIME\"text/html\", value)` for Atom/IJulia, and `TraceCalls.show_val(::IO, ::MIME\"text/plain\", value)` for the REPL and other non-HTML environments. See [the Julia manual on custom pretty-printing](https://docs.julialang.org/en/stable/manual/types/#Custom-pretty-printing-1) for more information, and [print_with_color](https://docs.julialang.org/en/stable/stdlib/io-network/#Base.print_with_color) / [Crayons.jl](https://github.com/KristofferC/Crayons.jl) for colorful REPL display." ] }, { "cell_type": "code", "execution_count": 10, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#17() => [2,1,2,1,2]
" ], "text/plain": [ "- #17() => \u001b[1m\u001b[32m[2, 1, 2, 1, 2]\u001b[39m\u001b[22m\n", " - LightGraphs.randomwalk({3, 2} undirected simple Int64 graph, 2, 5) => \u001b[1m\u001b[32m[2, 1, 2, 1, 2]\u001b[39m\u001b[22m\n", " - eltype({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mInt64\u001b[39m\u001b[22m\n", " - LightGraphs.vertices({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m1:3\u001b[39m\u001b[22m\n", " - LightGraphs.nv({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m3\u001b[39m\u001b[22m\n", " - eltype({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mInt64\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mArray{Int64,1}[[2], [1, 3], [2]]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.SimpleGraphs.fadj({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n" ] }, "execution_count": 10, "metadata": {}, "output_type": "execute_result" } ], "source": [ "TraceCalls.show_val(io::IO, ::MIME\"text/html\", v::Vector{Int}) = \n", " write(io, string(\"[\", join([x==2 ? \"2\" : x for x in v], \",\"), \"]\"))\n", "TraceCalls.show_val(io::IO, ::MIME\"text/html\", ::Graph) = # could also be done with `@show_val_only_type Graph`\n", " write(io, \"AnyOldGraph\") \n", "trace_walk" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "See also `?@show_val_only_type`, `?TraceCalls.show_call`, `?TraceCalls.show_return_val` and `?highlight`." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "#### Map, filter, collect\n", "\n", "Each function call in a trace is represented by an instance of the `Trace` structure:\n", "\n", "```julia\n", "struct Trace\n", " func::Function # the function called\n", " args::Tuple # the positional arguments\n", " kwargs::Tuple # the keyword arguments\n", " called::Vector{Trace} # the functions called within the execution of this function call \n", " value # This is the return value of the func(args...; kwargs...) call, but it's also where\n", " # the result of `map(f, ::Trace)` will be stored.\n", "end\n", "```" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "The following filtering functions are provided:\n", "\n", "- `filter(f, trace)` keeps all function calls for which `f(::Trace)` is true. It's useful to cut out uninteresting intermediate functions. \n", "- `filter_cutting(f, trace)` is like `filter`, but will remove all descendents of the traces for which `f(trace)` is false. \n", "- `filter_lineage(f, trace)` keeps all function calls for which `f(::Trace)` is true of at least one of its descendents or ancestors. Use it to focus on some interesting part of the trace. " ] }, { "cell_type": "code", "execution_count": 11, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#17() => [2,1,2,1,2]
" ], "text/plain": [ "- #17() => \u001b[1m\u001b[32m[2, 1, 2, 1, 2]\u001b[39m\u001b[22m\n", " - LightGraphs.randomwalk({3, 2} undirected simple Int64 graph, 2, 5) => \u001b[1m\u001b[32m[2, 1, 2, 1, 2]\u001b[39m\u001b[22m\n", " - eltype({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mInt64\u001b[39m\u001b[22m\n", " - LightGraphs.vertices({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m1:3\u001b[39m\u001b[22m\n", " - LightGraphs.nv({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32m3\u001b[39m\u001b[22m\n", " - eltype({3, 2} undirected simple Int64 graph) => \u001b[1m\u001b[32mInt64\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 1) => \u001b[1m\u001b[32m[2]\u001b[39m\u001b[22m\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => \u001b[1m\u001b[32m[1, 3]\u001b[39m\u001b[22m\n" ] }, "execution_count": 11, "metadata": {}, "output_type": "execute_result" } ], "source": [ "# Get rid of the `fadj` calls\n", "filter(trace->trace.func != LightGraphs.SimpleGraphs.fadj, trace_walk)" ] }, { "cell_type": "code", "execution_count": 55, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#17() => [2,1,2,1,2]
" ], "text/plain": [ "- \n", " - \n", " - \n", " - \n", " - \n", " - \n", " - \n", " - \n" ] }, "execution_count": 55, "metadata": {}, "output_type": "execute_result" } ], "source": [ "# Focus on the callers and callees of `LightGraphs.out_neighbors(AnyOldGraph, 2)`\n", "filter_lineage(trace -> trace.func==out_neighbors && trace[:v]==2, \n", " trace_walk; highlight=true)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "`map(f, trace)` applies `f` (whether a function or quoted macro such as `:@which`) to each `Trace`, and stores the result in `Trace`'s `value` field. " ] }, { "cell_type": "code", "execution_count": 14, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#21() => nothing
" ], "text/plain": [ "- #21() => nothing\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => 2\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 3) => 3\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => 2\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 1) => 1\n", " - LightGraphs.out_neighbors({3, 2} undirected simple Int64 graph, 2) => 2\n" ] }, "execution_count": 14, "metadata": {}, "output_type": "execute_result" } ], "source": [ "# Take the second argument of every call to LightGraphs.out_neighbors\n", "map(trace->trace.func == LightGraphs.out_neighbors ? trace.args[2] : nothing,\n", " filter(trace->trace.func == LightGraphs.out_neighbors, trace_walk))" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "`objects_in(trace)` returns all passed arguments and the return value as a vector. For example, `filter(tr->any(x==3.1 for x in objects_in(tr)), trace)` keeps all calls that contain the value `3.1`. `collect(trace)` returns a `Vector` of all `Trace` objects in `trace`. " ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Saving traces to disk\n", "\n", "Traces can be saved and reloaded with [JLD2.jl](https://github.com/simonster/JLD2.jl):\n", "\n", "```julia\n", "using TraceCalls, JLD2, FileIO\n", "save(\"test.jld2\", \"tracing_foo\", some_trace)\n", "reloaded_trace = load(\"test.jld2\", \"tracing_foo\")\n", "```\n", "\n", "Notes: \n", "\n", "- JLD2.jl will save closures without error, but when they are reloaded (as `ReconstructedTypes` instances), they will usually not be callable.\n", "- Before loading a trace, make sure to `import/using` all the modules defining the types and functions that the saved trace refers to." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Working with mutable state\n", "\n", "By default, `@trace` stores the function call's arguments without copying them. This can yield surprising results when tracing functions that modify their arguments. Consider generating a vector of `n` 5s using `push!`:" ] }, { "cell_type": "code", "execution_count": 15, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#31() => [5,5,5]
" ], "text/plain": [ "- #31() => [5, 5, 5]\n", " - many_5s(3) => [5, 5, 5]\n", " - push5!([5, 5, 5]) => [5, 5, 5]\n", " - push5!([5, 5, 5]) => [5, 5, 5]\n", " - push5!([5, 5, 5]) => [5, 5, 5]\n" ] }, "execution_count": 15, "metadata": {}, "output_type": "execute_result" } ], "source": [ "@traceable push5!(vec::Vector) = push!(vec, 5)\n", "@traceable function many_5s(n)\n", " vec = Int[]\n", " for i in 1:n\n", " push5!(vec)\n", " end\n", " return vec\n", "end\n", "\n", "@trace many_5s(3)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "When `push5!` was first called, `vec` was empty, but this trace makes it look like it already had three 5s in it. This is because all vectors in that trace are [the same object](http://www.johnmyleswhite.com/notebook/2014/09/06/values-vs-bindings-the-map-is-not-the-territory/). You can fix this (if you care) by telling TraceCalls to make a copy of every vector argument and return value:" ] }, { "cell_type": "code", "execution_count": 16, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#33() => [5,5,5]
" ], "text/plain": [ "- #33() => [5, 5, 5]\n", " - many_5s(3) => [5, 5, 5]\n", " - push5!(Int64[]) => [5]\n", " - push5!([5]) => [5, 5]\n", " - push5!([5, 5]) => [5, 5, 5]\n" ] }, "execution_count": 16, "metadata": {}, "output_type": "execute_result" } ], "source": [ "TraceCalls.store(x::Vector) = copy(x) # the default is `store(x) = x`\n", "@trace many_5s(3)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Alternatively, it's sometimes simpler to filter out all mutating functions:" ] }, { "cell_type": "code", "execution_count": 17, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#35() => [5,5,5]
" ], "text/plain": [ "- #35() => [5, 5, 5]\n", " - many_5s(3) => [5, 5, 5]\n" ] }, "execution_count": 17, "metadata": {}, "output_type": "execute_result" } ], "source": [ "tr = @trace many_5s(3)\n", "filter(!is_mutating, tr) # filter out every function that ends with a ! (see https://docs.julialang.org/en/stable/manual/style-guide/#Append-!-to-names-of-functions-that-modify-their-arguments-1)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "The most drastic solution is to have TraceCalls store the text/HTML representation of each value:\n", "\n", "```julia\n", "TraceCalls.store(x) = REPR(x)\n", "```\n", "\n", "This essentially turns TraceCalls.jl into a traditional, non-inspectable tracing package, but it guarantees that each value is shown as it was when the call was made." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Debugging with traces\n", "\n", "The starting point for debugging exceptions is `@stacktrace`. It works like `@trace`, but uses `filter` to keep only the part of the trace involved in the exception." ] }, { "cell_type": "code", "execution_count": 18, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#37() => DomainError()
" ], "text/plain": [ "- #37() => DomainError()\n", " - Optim.optimize(logplus10, [0.0], Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true), Optim.Options{Void}(1.0e-32, 1.0e-32, 1.0e-8, false, 1000, false, false, false, false, 1, nothing, NaN)) => DomainError()\n", " - Optim.optimize(Optim.OnceDifferentiable(logplus10, Optim.g!, Optim.fg!), [0.0], Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true), Optim.Options{Void}(1.0e-32, 1.0e-32, 1.0e-8, false, 1000, false, false, false, false, 1, nothing, NaN)) => DomainError()\n", " - Optim.update_state!(Optim.OnceDifferentiable(logplus10, Optim.g!, Optim.fg!), Optim.BFGSState{Float64,1,Array{Float64,1}}(\"BFGS\", 1, [0.0], 2.302585092994046, 1, 1, 0, [NaN], [0.1], [0.1], NaN, [2.37575e-314], [1.69069e-320], [NaN], [1.0], [-0.1], [-12.4999], [0.133333], 1.0, false, LineSearches.LineSearchResults{Float64}([0.0, 1.0, 5.0, 25.0], [2.30259, 2.29253, 2.25129, 2.0149], [-0.01, -0.010101, -0.0105263, -0.0133333], 0)), Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true)) => DomainError()\n", " - Optim.perform_linesearch!(Optim.BFGSState{Float64,1,Array{Float64,1}}(\"BFGS\", 1, [0.0], 2.302585092994046, 1, 1, 0, [NaN], [0.1], [0.1], NaN, [2.37575e-314], [1.69069e-320], [NaN], [1.0], [-0.1], [-12.4999], [0.133333], 1.0, false, LineSearches.LineSearchResults{Float64}([0.0, 1.0, 5.0, 25.0], [2.30259, 2.29253, 2.25129, 2.0149], [-0.01, -0.010101, -0.0105263, -0.0133333], 0)), Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true), Optim.OnceDifferentiable(logplus10, Optim.g!, Optim.fg!)) => DomainError()\n", " - Calculus.finite_difference!(logplus10, [-12.5], [0.133333], :central) => DomainError()\n", " - logplus10([-12.4999]) => DomainError()\n" ] }, "execution_count": 18, "metadata": {}, "output_type": "execute_result" } ], "source": [ "using Optim, TraceCalls\n", "@traceable logplus10(x) = log(x[1]+10)\n", "TraceCalls.store(v::Vector) = copy(v)\n", "\n", "# Minimize the function x -> log(x[1]+10) starting at x = 0\n", "strace = @stacktrace (Optim, Calculus) optimize(logplus10, [0.0], BFGS())" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Then we can zoom in on the most interesting part of the stack-trace: " ] }, { "cell_type": "code", "execution_count": 19, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
Optim.perform_linesearch!(Optim.BFGSState{Float64,1,Array{Float64,1}}(\"BFGS\", 1, [0.0], 2.302585092994046, 1, 1, 0, [NaN], [0.1], [0.1], NaN, [2.37575e-314], [1.69069e-320], [NaN], [1.0], [-0.1], [-12.4999], [0.133333], 1.0, false, LineSearches.LineSearchResults{Float64}([0.0, 1.0, 5.0, 25.0], [2.30259, 2.29253, 2.25129, 2.0149], [-0.01, -0.010101, -0.0105263, -0.0133333], 0)), Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true), Optim.OnceDifferentiable(logplus10, Optim.g!, Optim.fg!)) => DomainError()
" ], "text/plain": [ "- Optim.perform_linesearch!(Optim.BFGSState{Float64,1,Array{Float64,1}}(\"BFGS\", 1, [0.0], 2.302585092994046, 1, 1, 0, [NaN], [0.1], [0.1], NaN, [2.37575e-314], [1.69069e-320], [NaN], [1.0], [-0.1], [-12.4999], [0.133333], 1.0, false, LineSearches.LineSearchResults{Float64}([0.0, 1.0, 5.0, 25.0], [2.30259, 2.29253, 2.25129, 2.0149], [-0.01, -0.010101, -0.0105263, -0.0133333], 0)), Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true), Optim.OnceDifferentiable(logplus10, Optim.g!, Optim.fg!)) => DomainError()\n", " - Calculus.finite_difference!(logplus10, [-12.5], [0.133333], :central) => DomainError()\n", " - logplus10([-12.4999]) => DomainError()\n" ] }, "execution_count": 19, "metadata": {}, "output_type": "execute_result" } ], "source": [ "strace[1,1,1,1] # could also use `strace[bottom-2]`, or `strace[top+4]` --- bottom/top are special values like `end`" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Calling a `Trace` object performs its computation. By tracing `strace[1,1,1,1]()`, we get the full trace for this part of the computation:" ] }, { "cell_type": "code", "execution_count": 20, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#39() => DomainError()
" ], "text/plain": [ "- #39() => DomainError()\n", " - Optim.perform_linesearch!(Optim.BFGSState{Float64,1,Array{Float64,1}}(\"BFGS\", 1, [0.0], 2.302585092994046, 1, 1, 0, [NaN], [0.1], [0.1], NaN, [2.37575e-314], [1.69069e-320], [NaN], [1.0], [-0.1], [-12.4999], [0.133333], 1.0, false, LineSearches.LineSearchResults{Float64}([0.0, 1.0, 5.0, 25.0], [2.30259, 2.29253, 2.25129, 2.0149], [-0.01, -0.010101, -0.0105263, -0.0133333], 0)), Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true), Optim.OnceDifferentiable(logplus10, Optim.g!, Optim.fg!)) => DomainError()\n", " - Optim.checked_dphi0!(Optim.BFGSState{Float64,1,Array{Float64,1}}(\"BFGS\", 1, [0.0], 2.302585092994046, 1, 1, 0, [NaN], [0.1], [0.1], NaN, [2.37575e-314], [1.69069e-320], [NaN], [1.0], [-0.1], [-12.4999], [0.133333], 1.0, false, LineSearches.LineSearchResults{Float64}([0.0, 1.0, 5.0, 25.0], [2.30259, 2.29253, 2.25129, 2.0149], [-0.01, -0.010101, -0.0105263, -0.0133333], 0)), Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true)) => -0.009999999996070853\n", " - Optim.alphaguess!(Optim.BFGSState{Float64,1,Array{Float64,1}}(\"BFGS\", 1, [0.0], 2.302585092994046, 1, 1, 0, [NaN], [0.1], [0.1], NaN, [2.37575e-314], [1.69069e-320], [NaN], [1.0], [-0.1], [-12.4999], [0.133333], 1.0, false, LineSearches.LineSearchResults{Float64}([0.0, 1.0, 5.0, 25.0], [2.30259, 2.29253, 2.25129, 2.0149], [-0.01, -0.010101, -0.0105263, -0.0133333], 0)), Optim.BFGS{LineSearches.#hagerzhang!,Optim.##115#119}(LineSearches.hagerzhang!, Optim.#115, true), -0.009999999996070853, Optim.OnceDifferentiable(logplus10, Optim.g!, Optim.fg!)) => 1.0\n", " - Calculus.finite_difference!(logplus10, [-0.1], [0.133333], :central) => nothing\n", " - logplus10([-0.0999939]) => 2.2925353688044074\n", " - logplus10([-0.100006]) => 2.2925341454802757\n", " - logplus10([-0.1]) => 2.2925347571425285\n", " - Calculus.finite_difference!(logplus10, [-0.5], [0.10101], :central) => nothing\n", " - logplus10([-0.499994]) => 2.25129243603289\n", " - logplus10([-0.500006]) => 2.2512911612003736\n", " - logplus10([-0.5]) => 2.251291798616835\n", " - Calculus.finite_difference!(logplus10, [-2.5], [0.105263], :central) => nothing\n", " - logplus10([-2.49998]) => 2.01490503909053\n", " - logplus10([-2.50002]) => 2.0149010021208964\n", " - logplus10([-2.5]) => 2.0149030206077505\n", " - Calculus.finite_difference!(logplus10, [-12.5], [0.133333], :central) => DomainError()\n", " - logplus10([-12.4999]) => DomainError()\n" ] }, "execution_count": 20, "metadata": {}, "output_type": "execute_result" } ], "source": [ "linesearch_trace = @trace (Optim, Calculus) strace[1,1,1,1]()" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Focusing on just `finite_difference!` shows what happened: the line search keeps going for lower and lower values of `x`, until it tries `log(-12.5+10) == log(-2.5)`, which is a `DomainError`." ] }, { "cell_type": "code", "execution_count": 21, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#39() => DomainError()
" ], "text/plain": [ "- #39() => DomainError()\n", " - Calculus.finite_difference!(logplus10, [-0.1], [0.133333], :central) => nothing\n", " - Calculus.finite_difference!(logplus10, [-0.5], [0.10101], :central) => nothing\n", " - Calculus.finite_difference!(logplus10, [-2.5], [0.105263], :central) => nothing\n", " - Calculus.finite_difference!(logplus10, [-12.5], [0.133333], :central) => DomainError()\n" ] }, "execution_count": 21, "metadata": {}, "output_type": "execute_result" } ], "source": [ "filter(tr->tr.func==Calculus.finite_difference!, linesearch_trace)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "We could fix the error (for instance, by changing `logplus10`'s definition) and call `linesearch_trace()` to check that this part of the computation now returns a sensible result.\n", "\n", "`filter` is useful even when there is no exception to debug. By selecting only certain parts of the trace, it's the TraceCalls equivalent of setting a breakpoint. \n", "\n", "TraceCalls.jl implements `which(::Trace)` and `edit(::Trace)`. They point to the source location for that function call." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "#### Debugging test failures\n", "\n", "When a test used to pass, but now fails after a code change, `compare_past_trace` can be used to highlight the differences." ] }, { "cell_type": "code", "execution_count": 22, "metadata": {}, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "search: \u001b[1mc\u001b[22m\u001b[1mo\u001b[22m\u001b[1mm\u001b[22m\u001b[1mp\u001b[22m\u001b[1ma\u001b[22m\u001b[1mr\u001b[22m\u001b[1me\u001b[22m\u001b[1m_\u001b[22m\u001b[1mp\u001b[22m\u001b[1ma\u001b[22m\u001b[1ms\u001b[22m\u001b[1mt\u001b[22m\u001b[1m_\u001b[22m\u001b[1mt\u001b[22m\u001b[1mr\u001b[22m\u001b[1ma\u001b[22m\u001b[1mc\u001b[22m\u001b[1me\u001b[22m\n", "\n" ] }, { "data": { "text/markdown": [ "`compare_past_trace(old_trace::Trace; filter_out_equal=true))` reruns every function call in `old_trace`, and shows in red where the new result differs from the old. If `filter_out_equal==true`, only show the non-equal results. \n" ], "text/plain": [ "`compare_past_trace(old_trace::Trace; filter_out_equal=true))` reruns every function call in `old_trace`, and shows in red where the new result differs from the old. If `filter_out_equal==true`, only show the non-equal results. \n" ] }, "execution_count": 22, "metadata": {}, "output_type": "execute_result" } ], "source": [ "?compare_past_trace" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "To use it:\n", "\n", "1. Trace the failing test/computation under the correct code (it won't fail, of course)\n", "2. `git checkout` the bad code (or make the changes manually - I recommend [git stash](https://git-scm.com/docs/git-stash) for switching back and forth). `TraceCalls` imports `Revise.jl`, so the code changes will take effect automatically.\n", "3. Call `compare_past_trace` on the trace from step 1\n", "\n", "You may also call `compare_past_trace` on an old trace [loaded from disk](#Saving-traces-to-disk)." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "#### Displaying extra information\n", "\n", "To display intermediate results in your traces, use `trace_log` instead of `println/@show`:" ] }, { "cell_type": "code", "execution_count": 26, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#18() => 5.0
" ], "text/plain": [ "- #18() => 5.0\n", " - hypothenuse_length(3, 4) => 5.0\n", " - TraceCalls.trace_log(; a2=9, b2=16) => nothing\n" ] }, "execution_count": 26, "metadata": {}, "output_type": "execute_result" } ], "source": [ "using TraceCalls\n", "\n", "@traceable function hypothenuse_length(a, b)\n", " a2 = a * a\n", " b2 = b * b\n", " trace_log(a2=a2, b2=FontColor(:blue, b2)) # FontColor is also useful in Base.show_val or Base.map\n", " return sqrt(a2+b2)\n", "end\n", "\n", "@trace hypothenuse_length(3, 4)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "# Profiling\n", "\n", "`measure(:@measuring_macro, trace)` applies the given _quoted_ macro (put a `:` in front of the `@`) to every function call in `trace`. Useful macros/functions are `@allocated` and `@elapsed`, as well as [BenchmarkTools](https://github.com/JuliaCI/BenchmarkTools.jl)' `@belapsed`, `median∘benchmark` and `minimum∘benchmark` (see [here](https://github.com/JuliaCI/BenchmarkTools.jl/blob/master/doc/manual.md#which-estimator-should-i-use)). Because measuring involves rerunning every function call in the trace, it can be slow. A good rule-of-thumb is to use the more accurate `@belapsed` when the code to profile takes less than half a second and the trace is relatively short, and `@elapsed` when it takes less than a minute. When the trace is very large, try the `explore_worst=true` option, which will only profile the worst callee of each call (so the runtime is $O(wd)$ instead of $O(w^d)$). You can also [`prune` or `filter` the trace first](#Manipulating-traces).\n", "\n", "The output of `measure` is a normal, [explorable and callable](#Manipulating-traces) Trace object. Remember that due to timing fluctuations, even if `f(x)` calls `g(x)`, it does not imply that `@elapsed(f(x)) >= @elapsed(g(x))`." ] }, { "cell_type": "code", "execution_count": 3, "metadata": { "scrolled": false }, "outputs": [ { "data": { "text/html": [ "
#8() => 1.0
" ], "text/plain": [ "- #8() => \u001b[1m\u001b[32m\u001b[38;2;255;0;0m1.0\u001b[39m\u001b[39m\u001b[22m\n", " - getindex(PyObject , :pi) => \u001b[1m\u001b[32m\u001b[38;2;247;8;0m0.9699\u001b[39m\u001b[39m\u001b[22m\n", " - getindex(PyObject , \"pi\") => \u001b[1m\u001b[32m\u001b[38;2;29;226;0m0.114\u001b[39m\u001b[39m\u001b[22m\n", " - convert(PyCall.PyAny, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[38;2;188;67;0m0.7366\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pytype_query(PyObject 3.141592653589793, PyCall.PyObject) => \u001b[1m\u001b[32m\u001b[38;2;123;132;0m0.4832\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyint_query(PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[38;2;35;220;0m0.1354\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x000000011ef9cc98) => \u001b[1m\u001b[32m\u001b[38;2;17;238;0m0.0663\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x000000011ef9eaa8) => \u001b[1m\u001b[32m\u001b[38;2;17;238;0m0.06704\u001b[39m\u001b[39m\u001b[22m\n", " - convert(Float64, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[38;2;3;252;0m0.009888\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.asscalar(PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[38;2;1;254;0m0.005534\u001b[39m\u001b[39m\u001b[22m\n" ] }, "execution_count": 3, "metadata": {}, "output_type": "execute_result" } ], "source": [ "## Profile the PyCall code for accessing Python's `math.pi` \n", "using PyCall, TraceCalls\n", "\n", "math = pyimport(:math)\n", "trace_pycall = @trace PyCall math[:pi];\n", "\n", "using BenchmarkTools: @belapsed\n", "m_trace = measure(:@belapsed, trace_pycall; normalize=true, threshold=0.005) # only show/explore calls that take >0.5% of total runtime" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "`normalize(m_trace[1,2,1])` can be used to make the numbers in a subtrace more comparable." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "#### Type stability\n", "\n", "`code_warntype(trace_pycall[1,2])` returns the type-annotated code for that function call. Similarly for `code_llvm, code_lowered, code_native` and `code_typed`. `is_inferred(::Trace)` uses the same code as `Base.Test.@inferred`, but returns `true/false`, which is useful with `map`:" ] }, { "cell_type": "code", "execution_count": 2, "metadata": {}, "outputs": [ { "data": { "text/html": [ "
#1() => false
" ], "text/plain": [ "- #1() => \u001b[1m\u001b[32m\u001b[31mfalse\u001b[39m\u001b[39m\u001b[22m\n", " - getindex(PyObject , :pi) => \u001b[1m\u001b[32m\u001b[31mfalse\u001b[39m\u001b[39m\u001b[22m\n", " - getindex(PyObject , \"pi\") => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject ) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - convert(PyCall.PyAny, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[31mfalse\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pytype_query(PyObject 3.141592653589793, PyCall.PyObject) => \u001b[1m\u001b[32m\u001b[31mfalse\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyint_query(PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[31mfalse\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x0000000124956c98) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x0000000124958aa8) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyisinstance(PyObject 3.141592653589793, PyObject NULL) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyisinstance(PyObject 3.141592653589793, PyObject NULL) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyfloat_query(PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[31mfalse\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x0000000124954998) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - convert(Float64, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.asscalar(PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyisinstance(PyObject 3.141592653589793, PyObject NULL) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n", " - PyCall.pyerr_check(\"ccall(@pysym(:PyFloat_AsDouble), Cdouble, (PyPtr,), asscalar(po))\", 3.141592653589793) => \u001b[1m\u001b[32m\u001b[32mtrue\u001b[39m\u001b[39m\u001b[22m\n" ] }, "execution_count": 2, "metadata": {}, "output_type": "execute_result" } ], "source": [ "redgreen(map(is_inferred, trace_pycall)) # ignore the top-most call - it will always be `false`" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "#### Grouping and benchmarking\n", "\n", "TraceCalls.jl also provides a flat, more efficient profiling tool: `trace_benchmark`. It groups the calls by their signature (for example, `sin(1.3)` and `sin(2.3)` will be in the same group, but `sin(1)` will be in a different one) and only profiles one of the calls in each group." ] }, { "cell_type": "code", "execution_count": 3, "metadata": { "scrolled": false }, "outputs": [ { "data": { "text/html": [ "Benchmark\n", " 
2 calls like convert(PyCall.PyAny, PyObject 3.141592653589793) => TrialEstimate(900.426 ns, 16 bytes)
\n", " 
1 call like #1() => TrialEstimate(1.355 μs, 224 bytes)
\n", " 
1 call like getindex(PyObject , :pi) => TrialEstimate(1.350 μs, 224 bytes)
\n", " 
1 call like PyCall.pytype_query(PyObject 3.141592653589793, PyCall.PyObject) => TrialEstimate(605.153 ns, 0 bytes)
\n", " 
3 calls like PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x0000000124956c98) => TrialEstimate(86.650 ns, 0 bytes)
\n", " 
1 call like getindex(PyObject , \"pi\") => TrialEstimate(194.738 ns, 16 bytes)
\n", " 
1 call like PyCall.pyint_query(PyObject 3.141592653589793) => TrialEstimate(177.301 ns, 0 bytes)
\n", " 
3 calls like PyCall.pyisinstance(PyObject 3.141592653589793, PyObject NULL) => TrialEstimate(3.368 ns, 0 bytes)
\n", " 
5 calls like Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject ) => TrialEstimate(1.843 ns, 0 bytes)
\n", " 
1 call like PyCall.asscalar(PyObject 3.141592653589793) => TrialEstimate(6.723 ns, 0 bytes)
\n", " 
1 call like PyCall.pyerr_check(\"ccall(@pysym(:PyFloat_AsDouble), Cdouble, (PyPtr,), asscalar(po))\", 3.141592653589793) => TrialEstimate(5.806 ns, 0 bytes)
\n", " 
1 call like PyCall.pyfloat_query(PyObject 3.141592653589793) => TrialEstimate(5.797 ns, 0 bytes)
\n" ], "text/plain": [ "Benchmark\n", " 2 calls like convert(PyCall.PyAny, PyObject 3.141592653589793) => \u001b[1m\u001b[32mTrialEstimate(900.426 ns, 16 bytes)\u001b[39m\u001b[22m\n", " 1 call like #1() => \u001b[1m\u001b[32mTrialEstimate(1.355 μs, 224 bytes)\u001b[39m\u001b[22m\n", " 1 call like getindex(PyObject , :pi) => \u001b[1m\u001b[32mTrialEstimate(1.350 μs, 224 bytes)\u001b[39m\u001b[22m\n", " 1 call like PyCall.pytype_query(PyObject 3.141592653589793, PyCall.PyObject) => \u001b[1m\u001b[32mTrialEstimate(605.153 ns, 0 bytes)\u001b[39m\u001b[22m\n", " 3 calls like PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x0000000124956c98) => \u001b[1m\u001b[32mTrialEstimate(86.650 ns, 0 bytes)\u001b[39m\u001b[22m\n", " 1 call like getindex(PyObject , \"pi\") => \u001b[1m\u001b[32mTrialEstimate(194.738 ns, 16 bytes)\u001b[39m\u001b[22m\n", " 1 call like PyCall.pyint_query(PyObject 3.141592653589793) => \u001b[1m\u001b[32mTrialEstimate(177.301 ns, 0 bytes)\u001b[39m\u001b[22m\n", " 3 calls like PyCall.pyisinstance(PyObject 3.141592653589793, PyObject NULL) => \u001b[1m\u001b[32mTrialEstimate(3.368 ns, 0 bytes)\u001b[39m\u001b[22m\n", " 5 calls like Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject ) => \u001b[1m\u001b[32mTrialEstimate(1.843 ns, 0 bytes)\u001b[39m\u001b[22m\n", " 1 call like PyCall.asscalar(PyObject 3.141592653589793) => \u001b[1m\u001b[32mTrialEstimate(6.723 ns, 0 bytes)\u001b[39m\u001b[22m\n", " 1 call like PyCall.pyerr_check(\"ccall(@pysym(:PyFloat_AsDouble), Cdouble, (PyPtr,), asscalar(po))\", 3.141592653589793) => \u001b[1m\u001b[32mTrialEstimate(5.806 ns, 0 bytes)\u001b[39m\u001b[22m\n", " 1 call like PyCall.pyfloat_query(PyObject 3.141592653589793) => \u001b[1m\u001b[32mTrialEstimate(5.797 ns, 0 bytes)\u001b[39m\u001b[22m\n" ] }, "execution_count": 3, "metadata": {}, "output_type": "execute_result" } ], "source": [ "using BenchmarkTools # necessary for trace_benchmark\n", "bench = trace_benchmark(trace_pycall)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "After doing some code changes, you can rerun the same benchmark with `run` (technical note: it will use the same [tuning parameters](https://github.com/JuliaCI/BenchmarkTools.jl/blob/master/doc/manual.md#caching-parameters)). Then [call `ratio` or `judge`](https://github.com/JuliaCI/BenchmarkTools.jl/blob/master/doc/manual.md#trialratio-and-trialjudgement) to get a report on regressions and improvements." ] }, { "cell_type": "code", "execution_count": 4, "metadata": {}, "outputs": [ { "data": { "text/html": [ "Benchmark\n", " 
1 call like PyCall.pyerr_check(\"ccall(@pysym(:PyFloat_AsDouble), Cdouble, (PyPtr,), asscalar(po))\", 3.141592653589793) => TrialJudgement(+4.89% => invariant)
\n", " 
2 calls like convert(PyCall.PyAny, PyObject 3.141592653589793) => TrialJudgement(+0.97% => invariant)
\n", " 
1 call like PyCall.pytype_query(PyObject 3.141592653589793, PyCall.PyObject) => TrialJudgement(+0.90% => invariant)
\n", " 
1 call like PyCall.pyint_query(PyObject 3.141592653589793) => TrialJudgement(+0.34% => invariant)
\n", " 
5 calls like Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject ) => TrialJudgement(+0.00% => invariant)
\n", " 
1 call like PyCall.pyfloat_query(PyObject 3.141592653589793) => TrialJudgement(+0.00% => invariant)
\n", " 
3 calls like PyCall.pyisinstance(PyObject 3.141592653589793, PyObject NULL) => TrialJudgement(-0.03% => invariant)
\n", " 
1 call like PyCall.asscalar(PyObject 3.141592653589793) => TrialJudgement(-0.18% => invariant)
\n", " 
1 call like getindex(PyObject , \"pi\") => TrialJudgement(-0.49% => invariant)
\n", " 
1 call like #1() => TrialJudgement(-1.75% => invariant)
\n", " 
3 calls like PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x0000000124956c98) => TrialJudgement(-0.97% => invariant)
\n", " 
1 call like getindex(PyObject , :pi) => TrialJudgement(-5.19% => improvement)
\n" ], "text/plain": [ "Benchmark\n", " 1 call like PyCall.pyerr_check(\"ccall(@pysym(:PyFloat_AsDouble), Cdouble, (PyPtr,), asscalar(po))\", 3.141592653589793) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 2 calls like convert(PyCall.PyAny, PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 1 call like PyCall.pytype_query(PyObject 3.141592653589793, PyCall.PyObject) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 1 call like PyCall.pyint_query(PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 5 calls like Base.unsafe_convert(Ptr{PyCall.PyObject_struct}, PyObject ) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 1 call like PyCall.pyfloat_query(PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 3 calls like PyCall.pyisinstance(PyObject 3.141592653589793, PyObject NULL) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 1 call like PyCall.asscalar(PyObject 3.141592653589793) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 1 call like getindex(PyObject , \"pi\") => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 1 call like #1() => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 3 calls like PyCall.pyisinstance(PyObject 3.141592653589793, Ptr{PyCall.PyObject_struct} @0x0000000124956c98) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n", " 1 call like getindex(PyObject , :pi) => \u001b[1m\u001b[32m\u001b[91m\u001b[39m\u001b[39m\u001b[22m\n" ] }, "execution_count": 4, "metadata": {}, "output_type": "execute_result" } ], "source": [ "bench_new = run(bench);\n", "judge(bench_new, bench; sort=true)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "It's possible to save the benchmark to disk, but [please read these notes carefully](#Saving-traces-to-disk). The reloaded benchmark is likely to have one or more \"broken\" closure, and those will show up in the `run/judge` outputs as red exceptions (which can usually be ignored)." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "#### Profiling the compiler\n", "\n", "Parametric types sometimes trigger very long compilation times. You can use `@compilation_times to_trace expr` to estimate each method's total compilation time (in seconds). _This is very, very approximate and experimental_. This macro has the [same syntax and limitations](#Syntax) as `™@trace`. It will estimate the compilation time of every method specialization that appears in `@trace to_trace expr`. It is based on `precompile` and is [subject to precompile's limitations](https://github.com/JuliaLang/julia/issues/23548) (notably, keyword-argument functions are essentially ignored)." ] }, { "cell_type": "code", "execution_count": 4, "metadata": {}, "outputs": [ { "data": { "text/plain": [ "DataStructures.OrderedDict{Any,Float64} with 13 entries:\n", " convert(::Type{T}, po::PyCall.PyObject) where T<:Real in PyCall… => 0.0822036\n", " getindex(o::PyCall.PyObject, s::Symbol) in PyCall at /Users/ced… => 0.00703522\n", " pyerr_check(msg::AbstractString, val) in PyCall at /Users/cedri… => 9.4938e-5\n", " pyisinstance(o::PyCall.PyObject, t::Union{Ptr{PyCall.PyObject_s… => 9.1195e-5\n", " asscalar(o::PyCall.PyObject) in PyCall at /Users/cedric/.julia/… => 8.8809e-5\n", " convert(::Type{PyCall.PyAny}, o::PyCall.PyObject) in PyCall at … => 8.6389e-5\n", " unsafe_convert(::Type{Ptr{PyCall.PyObject_struct}}, po::PyCall.… => 6.4736e-5\n", " pytype_query(o::PyCall.PyObject, default::Union{Tuple{Vararg{Ty… => 4.3544e-5\n", " (::##29#30)() in Main at /Users/cedric/.julia/v0.6/TraceCalls/s… => 1.2242e-5\n", " getindex(o::PyCall.PyObject, s::AbstractString) in PyCall at /U… => 8.009e-6\n", " pyint_query(o::PyCall.PyObject) in PyCall at /Users/cedric/.jul… => 4.477e-6\n", " pyfloat_query(o::PyCall.PyObject) in PyCall at /Users/cedric/.j… => 3.236e-6\n", " pyisinstance(o::PyCall.PyObject, t::PyCall.PyObject) in PyCall … => 3.118e-6" ] }, "execution_count": 4, "metadata": {}, "output_type": "execute_result" } ], "source": [ "@compilation_times PyCall math[:pi]" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "To improve compilation time, consider [::ANY](https://docs.julialang.org/en/stable/stdlib/constants/#Core.ANY), [SnoopCompile.jl](https://github.com/timholy/SnoopCompile.jl), and using parametric types less.\n", "\n", "Technical note: consider the two function definitions `traced_1() = traced_2() + untraced()` and `traced_3() = untraced()`. The compilation time of `traced_2` won't be part of the compilation time of `traced_1` (by design), but `untraced()` may be counted in either `traced_1` or `traced_3`, depending on which one is profiled first. You can either accept this as measurement noise, or make sure that `untraced` is traced." ] } ], "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 }