Unnecessary compilation happening on every call


#1

I seem to have a case where the function gets compiled on almost every call. This is annoyingly slow.

julia> notice(logger, "Before call"); qlp_run()
[2018-11-15 16:13:13 | notice | root]: Before call
[2018-11-15 16:14:18 | notice | root]: First line
...
...
[2018-11-15 16:14:20 | notice | root]: Starting shutdown

Then I run again immediately in the same Julia session:

julia> notice(logger, "Before call"); qlp_run()
[2018-11-15 16:14:25 | notice | root]: Before call
[2018-11-15 16:15:29 | notice | root]: First line
...
...

With top of the function definition starting:

function qlp_run(fileStartidx = 0, fileProcPeriod = 1; mode="offline", configFilename = "config.json", inputPath="/run/shm/ifs/")
notice(logger, "First line")
...

My code currently lives in the main module.

Any suggestions of what is causing it and how to improve things? I am suspecting it is the use of keyword arguments, but I have on occasion had it that subsequent calls execute immediately, but that seems to be the exception.


#2

Please provide a self-contained, minimal working example.

For instance, what is notice, where is it coming from, what julia version are you running, etc.


#3

Sorry I should have atleast included some more details.

Here is the includes:

using Statistics
using FFTW
using DSP
using JSON
using Memento
using Unmarshal
using Sockets
using LinearAlgebra
using Nullables

import Base.push!

notice is from the logging library Memento it was just a quick and easy way to print the timestamp, since I already use it later in the code. I can probably modify it to print the time using a more standardised method without any difference, since the problem was there before I included those 2 notice calls (before the function call and as first line of the function body).

(v1.0) pkg> status
    Status `~/.julia/environments/v1.0/Project.toml`
  [6e4b80f9] BenchmarkTools v0.4.1
  [35d6a980] ColorSchemes v2.0.0
  [5ae59095] Colors v0.9.5
  [8f4d0f93] Conda v1.1.1
  [5a033b19] CurveFit v0.1.1+ [`~/.julia/dev/CurveFit`]
  [717857b8] DSP v0.5.1
  [7a1cc6ca] FFTW v0.2.4
  [5789e2e9] FileIO v1.0.2
  [0ef565a4] Geodesy v0.5.0
  [7073ff75] IJulia v1.13.0
  [916415d5] Images v0.16.1
  [682c06a0] JSON v0.19.0
  [b964fa9f] LaTeXStrings v1.0.3
  [ee78f7c6] Makie v0.9.0
  [f28f55f0] Memento v0.10.0
  [4d1e1d77] Nullables v0.0.8
  [47be7bcc] ORCA v0.1.1
  [f0f68f2c] PlotlyJS v0.11.2
  [91a5bcdd] Plots v0.21.0
  [438e738f] PyCall v1.18.5
  [d330b81b] PyPlot v2.6.3
  [cbff2730] Unmarshal v0.2.1
  [37e2e46d] LinearAlgebra 
  [10745b16] Statistics 

julia> versioninfo()
Julia Version 1.0.1
Commit 0d713926f8 (2018-09-29 19:05 UTC)
Platform Info:
  OS: Linux (x86_64-pc-linux-gnu)
  CPU: Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-6.0.0 (ORCJIT, haswell)

I would love to provide a self-contained minimal example, but am not sure how I would even approach it.

Currently the function is 950 lines of a 7k code-base split over numerous files (excluding “standard” packages) Yes, I know that is bad in terms of program structure, but splitting it further into smaller functions is difficult since the only way I could get fast processing was to make everything pre-allocated, which means function calls become cluttered with temporary variables. I am still trying to refactor to make this better. Part of the reason behind the question is thus to understand if I restructure what still ends up being compiled (function and all called functions or are the called functions only compiled once? How is inlining decisions made?). How important is it to split into separate modules?

I believe I am observing the problem due to the function being so big. If I create a 5 line example, how will I know whether it is being recompiled every time or only once?

I was hoping to reproduce and Ctrl-C to attempt to get a stack track to see if that can give clues about where it is busy (but even if I manage to get a stack trace, I doubt it will reveal why it is recompiling instead of just using the previous code), but now it seems to execute immediately with no compile delay. I will need to wait until it recurs before I can try to get that info.


#4

A function is being compiled only on it’s first call, no matter its length in lines of code. There definitely shouldn’t be a minute of waiting time between calling the function and getting to the first line. I’d link this, but as you use a lot of big packages it seems like this would take too much time to reduce.

If you’re able to share code that deterministically shows this behaviour, please do.

As for your other questions - smaller functions in general allow faster execution, since there’s more specialized versions of code available to be called. It may be that the logging notice only showed the problem and in truth the main function itself is slow - in that case, it’d be worthwhile to check @code_warntype for type instability or profile the code. As always, the general performance tips apply.


#5

Unfortunately if you start using keyword arguments @code_warntype becomes more difficult to use. The standard call just shows calling the inner with defaults populated. You cannot actually call the true inner function as far as I have been able to see.
I have in the past changed the function definition to remove the keyword arguments as just define them in the function body to atleast get some insight. Some instabilities remain, but I also haven’t been able to decode all of what that is telling me in the new format (the old format of code_warntype was for me easier to decode to get a sense of where things are going wrong).

julia> @code_warntype qlp_run()
Body::Any
120 1 ─ %1 = invoke Main.:(#qlp_run#45)("offline"::String, "config.json"::String, "/run/shm/ifs/"::String, _1::Function, 0::Int64, 1::Int64)::Any   │╻ qlp_run
    └──      return %1                                                                                                                              │ 

julia> @code_warntype qlp_run("offline", "config.json", "/run/shm/ifs/", 1, 0, 1)

julia> @code_warntype qlp_run(mode="offline", configFilename = "config.json", inputPath="/run/shm/ifs/", 1, 0, 1)

julia> @code_warntype qlp_run(1,0,1, mode="offline", configFilename = "config.json", inputPath="/run/shm/ifs/")

I am trying to follow the performance tips as I understood it for v0.6, I still need to check the details to properly understand nuances that might have changed with v1.0. But even if my code is not 100% performant and contains some type instabilities, the minute delay doesn’t make sense.
It feels as if every now and again I get Julia into a state that it believes something is dirty (for example package updated on disk, but already using older version in memory and then it keeps trying to recompile to to get into a consistent state, but I see this on julia runs where I didn’t do an explicit Pkg.update(), thus it shouldn’t be that).

Thanks for the suggestions thus far, I will look when it recurs and try to see if that time I get more clues. Any other suggestions on what else to look out for would also be appreciated.