Struggling to understand how to use PrecompileTools

General Usage Performance
1

Hello!

I wrote a bunch of libs in Julia that all work together. One lib in particular exists just to read and stream a certain data from HDF5 files. One of the functions in this lib has the job of, given one of these HDF5 files, read the contents of its summary and display it. Note, it doesn’t compute the summary from the data, that has already been done and stored inside the HDF5 alongside the data. This function reads only the summary and displays it on the screen. It’s just a few lines long.

Now, the thing I just described, after I restart Julia, and after all the imports have run, takes 15 seconds to run the first time. This is a crazy amount of time. My guess is that this time is spent compiling something, so I thought I would look into PrecompileTools so that this is done just once and doesn’t have to happen every time I restart Julia. Schematically I have:

import ...
(...)

@time printstats(filename)

The last line prints

  2.680033 seconds (847.55 k allocations: 44.609 MiB, 99.26% compilation time);

First off, this isn’t accurate. I timed it on my wristwatch and that line takes 15 seconds the first time around. No idea why @time says 2.7 secs.

Second time around it prints

  0.016743 seconds (162.97 k allocations: 6.526 MiB)

Alright, this is what I would expect.

So I tried using PrecompileTools. I add it to the package’s env, I add using PrecompileTools and then I write:

@setup_workload begin
    @compile_workload begin
        printstats(filename)
    end
end

I restart Julia, do my imports, and the run the timed line, which now prints

  0.105645 seconds (168.01 k allocations: 6.763 MiB, 82.82% compilation time)

Again not accurate, my wristwatch shows 9 and half seconds.

Let me emphasize what a microscopic amount of work reading and printing this data is. None of these times can be explained by the work that actually matters to me.

What’s going on here? Why are the @times wrong? Why does it seem that PrecompileTools has very little effect on the times? What can I do to avoid these constant recompilations?

Thank you

2

PrecompileTools likely did its job there, taking 2.68 seconds down to 0.106. PrecompileTools can’t precompile everything, the typical reason being runtime dispatches of call signatures that weren’t cached by @compile_workload.

Could you clarify when you started and stopped the wristwatch exactly? Are you doing it for a script ran from a command prompt, are you starting the moment you hit Enter to execute that specific line in the REPL and stopping when the timing printout comes, etc?

That said, there are a few things that can be said. @time expands to a lot of code besides the input expression, and it only starts its timer before a compilation-specific timer and the input expression, then stops after. The prior setup and the timing printout won’t be counted, though a discrepancy of >10 seconds isn’t normal, you can check with @time @time .... The compiler may also do some work on the input expression before the timer starts and fail to get counted, which can be remedied by @time @eval ..., but again, >10 seconds isn’t normal especially for a single call, though it’s worth a try whenever the compilation timing seems strangely low.

I also don’t think it could be explained by your system pausing the Julia process for a weirdly long time to work on other things, @time takes a difference in the time_ns and that uses the system clock AFAIK. If there is a deeper issue with your system clock, you can compare a wristwatch with other timers outside Julia to see, give 1-2 seconds leeway for printing and human reaction latency.