Compile time scales non-linearly with number of fields in structs

[evnu]

We are experiencing very long compile times for our crates when using rustlerwith --release mode. It appears that the compile time does scale superlinearly with the number of fields when using derives such as NifStruct. I implemented an example here. For the benchmark, I created some simple crates which contain only one struct using NifStruct and a number of simple fields.

Example run:

~/tools/rusty/native/benchmark_compile(master ✗) ./benchmark.sh
number_of_fields  time
0 0.03
1 0.24
2 0.27
4 0.54
8 1.76
16 9.11
32 60.81
48 156.27
64 407.51
~/tools/rusty/native/benchmark_compile(master ✗) ./plot.gpi

For comparision, here are the results when using the debug mode:

As expected, the compile time is much faster. It also appears to be more linear than with release mode. I suspect that we somehow make the life of LLVM harder w.r.t. the generated code.

[hansihe]

Could you try running with -Z time-passes to see where the time is spent?

[evnu]

Could you try running with -Z time-passes to see where the time is spent?

This will be a lot of data. Should I split it by crate, or do you have another format in mind?

[hansihe]

I don't think it should be that much, and even then I imagine the majority of time would be spent in a couple of places

[evnu]

I prebuilt 64_struct and then ran -Z time-passes:

~/tools/rusty/native/benchmark_compile/64_struct(master ✗) touch src/lib.rs
~/tools/rusty/native/benchmark_compile/64_struct(master ✗) rustup run nightly cargo rustc --release --lib -- -Z time-passes |& tee time-passes.log

time-passes.log

[evnu]

Some additional information with cargo install cargo-llvm-lines. The decode impl is very long in 64_struct:

~/tools/rusty/native/benchmark_compile/64_struct(master ✗) cargo llvm-lines --lib | head -20
   Compiling struct_64 v0.1.0 (/home/mo/tools/rusty/native/benchmark_compile/64_struct)
    Finished dev [unoptimized + debuginfo] target(s) in 1.21s
  26319    1  <benchmark64::Struct as rustler::types::Decoder>::decode
   2036    1  <benchmark64::Struct as rustler::types::Encoder>::encode
    798    1  <benchmark64::RUSTLER_ATOMS_Struct::RUSTLER_ATOMS as core::ops::deref::Deref>::deref::__static_ref_initialize::{{closure}}
    165   10  core::ptr::real_drop_in_place
    137    1  core::ptr::swap_nonoverlapping_bytes
    116    2  core::ptr::swap_nonoverlapping_one
    106    2  core::intrinsics::overlaps
     96    2  core::intrinsics::copy_nonoverlapping
     73    2  core::ptr::read
     68    2  core::ptr::swap_nonoverlapping
     66    1  core::result::Result<T,E>::unwrap
     60    2  core::intrinsics::is_aligned_and_not_null
     58    1  std::sync::once::Once::call_once
     57    2  core::ops::function::FnOnce::call_once
     54    2  core::mem::replace
     48    1  core::num::<impl usize>::overflowing_mul
     46    1  alloc::alloc::exchange_malloc
     43    1  rustler::env::OwnedEnv::run
     42    1  core::option::Option<T>::unwrap
     41    1  core::num::<impl usize>::checked_mul

Maybe this is a similar problem as described here (LLVM is not good at large functions).

[evnu]

Interesting. If I only derive Encoder for the structs, the compilation is fast. See here. Example:

~/tools/rusty/native/benchmark_compile/64_struct(master ✗) cargo llvm-lines --lib | head -20
   Compiling struct_64 v0.1.0 (/home/mo/tools/rusty/native/benchmark_compile/64_struct)
warning: unused import: `rustler::Encoder`
 --> native/benchmark_compile/64_struct/src/lib.rs:1:5
  |
1 | use rustler::Encoder;
  |     ^^^^^^^^^^^^^^^^
  |
  = note: `#[warn(unused_imports)]` on by default
    Finished dev [unoptimized + debuginfo] target(s) in 0.33s
   2036    1  <benchmark64::Struct as rustler::types::Encoder>::encode
    798    1  <benchmark64::RUSTLER_ATOMS_Struct::RUSTLER_ATOMS as core::ops::deref::Deref>::deref::__static_ref_initialize::{{closure}}
    137    1  core::ptr::swap_nonoverlapping_bytes
    119    6  core::ptr::real_drop_in_place
    116    2  core::ptr::swap_nonoverlapping_one
    106    2  core::intrinsics::overlaps
     96    2  core::intrinsics::copy_nonoverlapping
     73    2  core::ptr::read
     68    2  core::ptr::swap_nonoverlapping
     66    1  core::result::Result<T,E>::unwrap
     60    2  core::intrinsics::is_aligned_and_not_null
     58    1  std::sync::once::Once::call_once
     57    2  core::ops::function::FnOnce::call_once
     54    2  core::mem::replace
     48    1  core::num::<impl usize>::overflowing_mul
     43    1  rustler::env::OwnedEnv::run
     42    1  core::option::Option<T>::unwrap
     41    1  core::num::<impl usize>::checked_mul
     38    1  <benchmark64::RUSTLER_ATOMS_Struct::RUSTLER_ATOMS as core::ops::deref::Deref>::deref
     38    1  core::cell::Cell<T>::replace

[evnu]

I implemented a simple change in evnu@d8c803d to speed up the decoder compilation. Instead of using match directly, I extracted the common decode parts into a local helper function.

commit d8c803d874c795b4f0e0c850991611288fed035c
Author: Magnus Ottenklinger <evnu@posteo.de>
Date:   Tue Jan 28 14:24:21 2020 +0100

    Try to speed up decoder compilation

diff --git a/rustler_codegen/src/ex_struct.rs b/rustler_codegen/src/ex_struct.rs
index fe166fd..4616c70 100644
--- a/rustler_codegen/src/ex_struct.rs
+++ b/rustler_codegen/src/ex_struct.rs
@@ -55,6 +55,7 @@ pub fn transcoder_decorator(ast: &syn::DeriveInput) -> TokenStream {
 fn gen_decoder(ctx: &Context, fields: &[&Field], atoms_module_name: &Ident) -> TokenStream {
     let struct_type = &ctx.ident_with_lifetime;
     let struct_name = ctx.ident;
+    let struct_name_str = struct_name.to_string();
 
     let field_defs: Vec<TokenStream> = fields
         .iter()
@@ -62,16 +63,8 @@ fn gen_decoder(ctx: &Context, fields: &[&Field], atoms_module_name: &Ident) -> T
             let ident = field.ident.as_ref().unwrap();
             let ident_str = ident.to_string();
             let atom_fun = Ident::new(&format!("atom_{}", ident_str), Span::call_site());
-            let error_message = format!(
-                "Could not decode field :{} on %{}{{}}",
-                ident.to_string(),
-                struct_name.to_string()
-            );
             quote! {
-                #ident: match ::rustler::Decoder::decode(term.map_get(#atom_fun().encode(env))?) {
-                    Err(_) => return Err(::rustler::Error::RaiseTerm(Box::new(#error_message))),
-                    Ok(value) => value
-                }
+                #ident: try_decode_field(env, term, #atom_fun())?
             }
         })
         .collect();
@@ -83,6 +76,24 @@ fn gen_decoder(ctx: &Context, fields: &[&Field], atoms_module_name: &Ident) -> T
 
                 let env = term.get_env();
 
+                fn try_decode_field<'a, T>(
+                    env: rustler::Env<'a>,
+                    term: rustler::Term<'a>,
+                    field: rustler::Atom,
+                    ) -> Result<T, rustler::Error>
+                    where
+                        T: rustler::Decoder<'a>,
+                    {
+                        use rustler::Encoder;
+                        match ::rustler::Decoder::decode(term.map_get(field.encode(env))?) {
+                            Err(_) => Err(::rustler::Error::RaiseTerm(Box::new(format!(
+                                            "Could not decode field :{:?} on %{}{{}}",
+                                            field, #struct_name_str
+                            )))),
+                            Ok(value) => Ok(value),
+                        }
+                    };
+
                 let module: ::rustler::types::atom::Atom = term.map_get(atom_struct().to_term(env))?.decode()?;
                 if module != atom_module() {
                     return Err(::rustler::Error::Atom("invalid_struct"));

This reduced the compilation time a lot:

Compared to my original results, the benchmark results in 47s for the 64 field case compared to over 400s in the original case.

[evnu]

The number of LLVM IR lines shrank by about 50% with the patch in #299 (comment):

~/tools/rusty/native/benchmark_compile/64_struct(master ✗) cargo llvm-lines --lib | head -20
   Compiling struct_64 v0.1.0 (/home/mo/tools/rusty/native/benchmark_compile/64_struct)
warning: unused import: `rustler::Encoder`
 --> native/benchmark_compile/64_struct/src/lib.rs:1:5
  |
1 | use rustler::Encoder;
  |     ^^^^^^^^^^^^^^^^
  |
  = note: `#[warn(unused_imports)]` on by default
    Finished dev [unoptimized + debuginfo] target(s) in 0.64s
  11039    1  <benchmark64::Struct as rustler::types::Decoder>::decode
   2036    1  <benchmark64::Struct as rustler::types::Encoder>::encode
    798    1  <benchmark64::RUSTLER_ATOMS_Struct::RUSTLER_ATOMS as core::ops::deref::Deref>::deref::__static_ref_initialize::{{closure}}
    224    1  <benchmark64::Struct as rustler::types::Decoder>::decode::try_decode_field
    206   12  core::ptr::real_drop_in_place
    137    1  core::ptr::swap_nonoverlapping_bytes
    116    2  core::ptr::swap_nonoverlapping_one
    106    2  core::intrinsics::overlaps
     96    2  core::intrinsics::copy_nonoverlapping
     73    2  core::ptr::read
     68    2  core::ptr::swap_nonoverlapping
     66    1  core::result::Result<T,E>::unwrap
     62    2  core::fmt::ArgumentV1::new
     60    2  core::intrinsics::is_aligned_and_not_null
     58    1  std::sync::once::Once::call_once
     57    2  core::ops::function::FnOnce::call_once
     54    2  core::mem::replace
     48    1  core::num::<impl usize>::overflowing_mul
     46    1  alloc::alloc::exchange_malloc
     43    1  core::fmt::Arguments::new_v1

[evnu]

Curious.. When using unwrap() instead of proper error propagation with ? on top of the diff in #299 (comment), the compilation is almost instantaneous.

diff --git a/rustler_codegen/src/ex_struct.rs b/rustler_codegen/src/ex_struct.rs
index 4616c70..c20f8c2 100644
--- a/rustler_codegen/src/ex_struct.rs
+++ b/rustler_codegen/src/ex_struct.rs
@@ -64,7 +64,7 @@ fn gen_decoder(ctx: &Context, fields: &[&Field], atoms_module_name: &Ident) -> T
             let ident_str = ident.to_string();
             let atom_fun = Ident::new(&format!("atom_{}", ident_str), Span::call_site());
             quote! {
-                #ident: try_decode_field(env, term, #atom_fun())?
+                #ident: try_decode_field(env, term, #atom_fun()).unwrap()
             }
         })
         .collect();

Of course we cannot do that, as decoding might very well fail. But still interesting.

[evnu]

In evnu@d6a3969, I split the decoding of fields and the field assignment:

commit d6a3969299d55d5a799fcb03385b66d4515cae6b
Author: Magnus Ottenklinger <evnu@posteo.de>
Date:   Tue Jan 28 15:14:53 2020 +0100

    Preinitialize fields as variables

diff --git a/rustler_codegen/src/ex_struct.rs b/rustler_codegen/src/ex_struct.rs
index 4616c70..b5a9fa6 100644
--- a/rustler_codegen/src/ex_struct.rs
+++ b/rustler_codegen/src/ex_struct.rs
@@ -57,14 +57,18 @@ fn gen_decoder(ctx: &Context, fields: &[&Field], atoms_module_name: &Ident) -> T
     let struct_name = ctx.ident;
     let struct_name_str = struct_name.to_string();
 
-    let field_defs: Vec<TokenStream> = fields
+    let idents: Vec<_> = fields
         .iter()
-        .map(|field| {
-            let ident = field.ident.as_ref().unwrap();
+        .map(|field| field.ident.as_ref().unwrap())
+        .collect();
+
+    let field_defs: Vec<TokenStream> = idents
+        .iter()
+        .map(|ident| {
             let ident_str = ident.to_string();
             let atom_fun = Ident::new(&format!("atom_{}", ident_str), Span::call_site());
             quote! {
-                #ident: try_decode_field(env, term, #atom_fun())?
+                let #ident = try_decode_field(env, term, #atom_fun())?;
             }
         })
         .collect();
@@ -99,7 +103,9 @@ fn gen_decoder(ctx: &Context, fields: &[&Field], atoms_module_name: &Ident) -> T
                     return Err(::rustler::Error::Atom("invalid_struct"));
                 }
 
-                Ok(#struct_name { #(#field_defs),* })
+                #(#field_defs);*
+
+                Ok(#struct_name { #(#idents),* })
             }
         }
     };

The results are great:

I submitted #300 to simplify discussing the changes.