Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Every sqlx::query!() call adds 80+ milliseconds to build time #1096

Closed
pvdbrand opened this issue Mar 13, 2021 · 7 comments
Closed

Every sqlx::query!() call adds 80+ milliseconds to build time #1096

pvdbrand opened this issue Mar 13, 2021 · 7 comments

Comments

@pvdbrand
Copy link

pvdbrand commented Mar 13, 2021

I've been developing an application over the last couple of months, using sqlx. I'm very happy with it, but the debug build times of my application seemed to increase steadily over time. I'm using sqlx 0.4.2, Rust 1.50, and a Postgres 12 database.

I'm pretty sure it's due to compiling the sqlx::query!() calls. I wrote a small script which checks out each source code revision, and measures the 'cargo build' time. (It resets the database, compiles the code, appends something trivial to my main.rs, and then compiles the code again. The measured time is the time taken by the last compilation). The same script also counts the number of occurrences of 'sqlx::query' in my code. The measurements are made on a AMD Ryzen 5900X CPU. This is the result:

image

When I started using sqlx, the 'cargo build' time was 5 seconds. Now it's around 12 seconds. During that time I wrote 92 queries. Every time I add a bunch of queries to the code, the time taken by 'cargo build' goes up by a similar amount. In my case, around 88 milliseconds per sqlx::query!().

Using offline mode does not seem to make any difference.

I also looked at the total LOC and the number of 'async fn' occurrences of each revision. These also have some correlation with the compile times of course, but it's not nearly as strong as the correlation with the number of sqlx::query!() calls.

I'm worried that compile times will keep on going up in the future, because I expect to be writing a lot more queries. Is there anything I can do to decrease the time taken to compile each query, besides trying to split my code up into lots of little crates?

@pvdbrand
Copy link
Author

I added some print statements to the expand_query() proc_macro to measure the time taken by macro expansion. All 87 queries which use expand_query() in my latest revision only take 0.8 seconds (wall clock) in total. The wall clock time between the first macro expansion and the last one is 1.1 seconds.

@jplatte
Copy link
Contributor

jplatte commented Mar 14, 2021

#941 should help with compile times, but I'm not sure when I'm going to get back to it.

@pvdbrand
Copy link
Author

#941 might shave some time off the 1.1 seconds taken by the query! macro expansion, but that's about it right?

The majority of the time is spent by the Rust compiler compiling the generated code I guess?

@jplatte
Copy link
Contributor

jplatte commented Mar 14, 2021

Oh, I see. There is the -Z time-passes (if I recall the name correctly) option for figuring out where the compiler spends its time, maybe you should use that to gather more information.

Otherwise incremental re-linking could help I guess, though I don't know much about that.

@pvdbrand
Copy link
Author

I tried running "cargo +nightly rustc -- -Z self-profile" followed by "summarize summarize *.mm_profdata", which produces the following profile results:

Item Self time % of total time Time Item count Incremental load time
run_linker 3.93s 57.309 3.93s 1 0.00ns
expand_crate 1.33s 19.477 1.40s 1 0.00ns
monomorphization_collector_graph_walk 264.12ms 3.855 733.05ms 1 0.00ns
incr_comp_load_dep_graph 107.68ms 1.571 107.68ms 1 0.00ns
normalize_projection_ty 68.60ms 1.001 112.31ms 1997 0.00ns
resolve_instance 67.98ms 0.992 160.84ms 63046 0.00ns
metadata_register_crate 63.98ms 0.934 226.14ms 274 0.00ns
evaluate_obligation 61.71ms 0.901 74.55ms 11325 0.00ns
incr_comp_encode_serialized_dep_graph 58.35ms 0.852 58.35ms 1 0.00ns
encode_query_results_for 46.06ms 0.672 46.06ms 24 0.00ns

57% of the time is spent in the linker. Another 19.5% (1.33 seconds) is spent expanding macros, which is close to the time I measured earlier.

I tried using cranelift, but it panics during the build.

Interestingly, the nightly compiler is much faster than rustc 1.50.0. A build takes just 7 seconds instead of 12 seconds!

@pvdbrand
Copy link
Author

pvdbrand commented Mar 14, 2021

Following the advice of jplatte, I also tried using lld. I create the file ~/.cargo/config, with the following contents:

[build]
rustflags = ["-C", "link-arg=-fuse-ld=lld"]

This improves the compile time to 8.5 seconds on Rust 1.50.0 (instead of 12 seconds), and just 3.5 seconds on nightly (instead of 7 seconds). Nice!

@abonander
Copy link
Collaborator

We've made some improvements to compile times when using query!() but there's only going to be so much improvement possible, given the amount of work the macro needs to do.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants