Profiling

Let’s work with a simple test case.:

First, you should run the code you are going to profile at least once (unless you are going to profile the Julia JIT compiler):

Now everything is ready to profile this function.:

There are several graphical browsers for viewing the profiling results. One "family" of visualizers is based on https://github.com/timholy/FlameGraphs.jl [FlameGraphs.jl], with each member of the family providing its own user interface:

A completely independent approach to profiling visualization is https://github.com/vchuravy/PProf.jl [PProf.jl], which uses the external tool `pprof'.

However, here we will use text mapping, which is included in the standard library.:

Each line here represents a specific location (line number) in the code. Indentation is used to indicate a nested sequence of function calls, with lines with more indentation located deeper in the sequence of calls. In each row, the first "field" is the number of backtraces (samples) performed in this row or any functions performed by this row_. The second field is the file name and line number, and the third field is the function name. Please note that the specific line numbers may change as the Julia code changes. If you want to track this point, it’s better to run this example yourself.

In this example, we can see that the top-level function being called is located in the 'event.jl` file. This is the function that triggers the REPL when Julia is started. If you look at line 97 of the REPL.jl file, you will see that the eval_user_input() function is called here. This function processes your input in the REPL, and since we are working interactively, these functions were called when we entered @profile myfunc(). The following line reflects the actions performed in the macro @profile.

The first line shows that 80 backtraces were executed in line 73 of the event.jl file, but it’s not that this line was "expensive" in itself: the third line shows that all 80 backtraces were actually launched inside its eval_user_input call, and so on. To find out which operations really take time, you need to look deeper into the call chain.

Here is the first important line in this output:

The REPL refers to the fact that we defined the function (myfunc') in the REPL rather than putting it in a file. If we were using a file, its name would be displayed here. `[1] indicates that the function (myfunc') was the first expression evaluated in this REPL session. Line 2 of the function (`myfunc()) contains a call to `rand', and 52 (out of 80) backtraces occurred in it. Below you can see the function call `dsfmt_fill_array_close_open!`inside the file `dSFMT.jl'.

A little further you can see:

Line 3 of the function ('myfunc') contains the maximum call, and 28 (out of 80) backtraces occurred in it. Below you can see the specific locations in the base/reduce' file.jl, in which time-consuming operations are performed in the maximum function for a given type of input data.

In general, we can make a preliminary conclusion that generating random numbers is about twice as expensive as searching for the maximum element. It would be possible to increase confidence in this result by collecting more samples.:

In general, if there are N samples collected in one row, we can expect uncertainty about the order of sqrt(N) (if we do not take into account other sources of noise, such as computer workload with other tasks). The main exception to this rule is garbage collection, which is performed infrequently, but is usually quite expensive. (Since the Julia garbage collector is written in C, such events can be detected using the C=true output mode described below, or using https://github.com/timholy/ProfileView.jl [ProfileView.jl].)

Next, a standard tree dump is shown. An alternative is a flat dump, which accumulates calculations regardless of their nesting.:

If there is recursion in the code, a potentially difficult point is that a line in a child function can accumulate calculations that exceed the total number of backtraces. Consider the following function definitions.

If you profiled dumbsum3 and performed a backtrace during the execution of dumbsum(1), it would look like this:

Therefore, this child function receives three calculations, although the parent function receives only one. The tree view makes this situation much more understandable, and for this reason (among others) is probably the most preferred way to view the results.

Macro results @profile accumulates in the buffer. If you are executing multiple code snippets using a macro @profile, then Profile.print() outputs the combined results. It can be very useful. But sometimes you want to start with a clean slate, and this can be done using the function Profile.clear().

Profile.print has other parameters that we haven’t considered yet. Here is the full announcement:

Let’s first discuss two positional arguments, and then the named arguments.

Any combination of the following named arguments is possible:

The names of files or functions are sometimes truncated (with ...), and the margins are truncated with +n at the beginning, where n is the number of additional spaces that would have been inserted if there had been room for them. If you need a complete profile of deeply embedded code, it is often recommended to save its file using a wide displaysize in IOContext:

@profile simply accumulates backtraces, and the analysis occurs when you call Profile.print(). With a long-term calculation, it is quite possible that the pre-allocated buffer for storing backtraces will be filled. If this happens, the backtracking will stop, but the calculations will continue. As a result, some important profiling data may be missing (in this case, a warning will be displayed).

You can get and configure the relevant parameters as follows:

'n` is the total number of instruction pointers available for storage. The default value is 10^6. If a standard backtrace consists of 20 instruction pointers, you can collect 50,000 backtraces, which assumes a statistical error of less than 1%. This may be sufficient for most applications.

Therefore, you will most likely need to change the delay, expressed in seconds, which sets the amount of time available in Julia between snapshots to perform the required calculations. For a very long task, frequent backtracking may not be required. The default parameter is `delay = 0.001'. Of course, the delay can be either reduced or increased. However, the cost of profiling increases when the delay becomes similar to the time required to create a backtrace (~30 microseconds on the author’s laptop).

One of the most common methods of improving performance is to reduce the amount of allocated memory. There are several measurement tools available in Julia:

Julia currently supports Intel VTune, OProfile, and perf as external profiling tools.

Depending on the selected tool, compile using the variables USE_INTEL_JITEVENTS, USE_OPROFILE_JITEVENTS and USE_PERF_JITEVENTS, which are set to 1 in `Make.user'. Multiple flags are supported.

Before starting Julia, set the environment variable ENABLE_JITPROFILING value is 1.

Now you can use these tools in various ways. For example, using OProfile you can try a simple entry:

Or it can be done using perf:

There are many other interesting things that you can measure in your program. The full list can be found at https://www.brendangregg.com/perf.html [the Linux perf examples page].

Remember that perf saves a perf.data file for each execution, which can become quite voluminous even for small programs. Additionally, the perf LLVM module saves temporary debugging objects to the ~/.debug/jit folder. Do not forget to clean it regularly.