mongo-rust-driver icon indicating copy to clipboard operation
mongo-rust-driver copied to clipboard

Slow Build Times

Open TroyKomodo opened this issue 2 months ago • 2 comments

Versions/Environment

  1. Rustc / Os rustc 1.77.2 (25ef9e3d8 2024-04-09) Host: x86_64-unknown-linux-gnu Target: x86_64-unknown-linux-gnu

  2. What versions of the driver and its dependencies are you using?

registry+https://github.com/rust-lang/crates.io-index#[email protected] registry+https://github.com/rust-lang/crates.io-index#[email protected]

  1. What version of MongoDB are you using? (Check with the MongoDB shell using db.version())

N/A

  1. What is your MongoDB topology (standalone, replica set, sharded cluster, serverless)?

N/A

Describe the bug

Large codegen slowing down builds causing long linking times.

image

Running cargo build --timings shows mongodb takes roughly 20s of a 70s build and is not executed in parallel.

image

Running cargo llvm-lines

Shows that bson serde implementation is generating a wildly large amount of LLVM IR.

 Lines                  Copies               Function name
  -----                  ------               -------------
  3466340                76515                (TOTAL)
   125174 (3.6%,  3.6%)     84 (0.1%,  0.1%)  bson::de::raw::Deserializer::deserialize_next
    54462 (1.6%,  5.2%)    124 (0.2%,  0.3%)  bson::de::serde::Deserializer::deserialize_next
    48905 (1.4%,  6.6%)    320 (0.4%,  0.7%)  bson::de::raw::DocumentAccess::read
    46484 (1.3%,  7.9%)    914 (1.2%,  1.9%)  std::panicking::try
    44157 (1.3%,  9.2%)    123 (0.2%,  2.0%)  alloc::raw_vec::RawVec<T,A>::grow_amortized
    41480 (1.2%, 10.4%)     34 (0.0%,  2.1%)  <&mut bson::ser::raw::value_serializer::ValueSerializer as serde::ser::SerializeStruct>::serialize_field
    38171 (1.1%, 11.5%)    447 (0.6%,  2.7%)  <alloc::boxed::Box<T,A> as core::ops::drop::Drop>::drop
    35217 (1.0%, 12.5%)    235 (0.3%,  3.0%)  bson::de::raw::Deserializer::access_document
    33818 (1.0%, 13.5%)    914 (1.2%,  4.2%)  std::panicking::try::do_catch
    26409 (0.8%, 14.3%)    182 (0.2%,  4.4%)  tokio::runtime::task::core::Cell<T,S>::new
    25431 (0.7%, 15.0%)    650 (0.8%,  5.3%)  tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
    23734 (0.7%, 15.7%)    110 (0.1%,  5.4%)  bson::de::raw::Deserializer::deserialize_document
    23569 (0.7%, 16.4%)    867 (1.1%,  6.5%)  <core::result::Result<T,E> as core::ops::try_trait::Try>::branch
    22956 (0.7%, 17.0%)    182 (0.2%,  6.8%)  tokio::runtime::task::harness::poll_future
    22484 (0.6%, 17.7%)    914 (1.2%,  8.0%)  std::panicking::try::do_call
    21999 (0.6%, 18.3%)   1295 (1.7%,  9.7%)  core::ops::function::FnOnce::call_once
    21816 (0.6%, 18.9%)     96 (0.1%,  9.8%)  <shared::database::types::role::permissions::_::<impl serde::de::Deserialize for shared::database::types::role::permissions::AllowDeny<T>>::deserialize::__Visitor<T> as serde::de::Visitor>::visit_map
    21776 (0.6%, 19.6%)    636 (0.8%, 10.6%)  serde::de::Visitor::visit_map
    20968 (0.6%, 20.2%)    220 (0.3%, 10.9%)  <shared::database::id::Id<S> as serde::de::Deserialize>::deserialize
    19675 (0.6%, 20.7%)     12 (0.0%, 10.9%)  <shared::database::types::product::_::<impl serde::de::Deserialize for shared::database::types::product::Product>::deserialize::__Visitor as serde::de::Visitor>::visit_map
    18661 (0.5%, 21.3%)    152 (0.2%, 11.1%)  bson::de::raw::CodeWithScopeDeserializer::read
    18395 (0.5%, 21.8%)    490 (0.6%, 11.8%)  core::result::Result<T,E>::map_err
    18056 (0.5%, 22.3%)      7 (0.0%, 11.8%)  mongodb::client::executor::<impl mongodb::client::Client>::execute_operation_on_connection::{{closure}}
    17649 (0.5%, 22.8%)    146 (0.2%, 12.0%)  std::thread::local::LocalKey<T>::try_with
    17035 (0.5%, 23.3%)     12 (0.0%, 12.0%)  <shared::database::types::role::_::<impl serde::de::Deserialize for shared::database::types::role::Role>::deserialize::__Visitor as serde::de::Visitor>::visit_map
    16591 (0.5%, 23.8%)     12 (0.0%, 12.0%)  <shared::database::types::user::_::<impl serde::de::Deserialize for shared::database::types::user::User>::deserialize::__Visitor as serde::de::Visitor>::visit_map
    16586 (0.5%, 24.3%)    424 (0.6%, 12.5%)  core::result::Result<T,E>::map
    16518 (0.5%, 24.8%)      7 (0.0%, 12.6%)  mongodb::client::executor::<impl mongodb::client::Client>::execute_operation_with_retry::{{closure}}
    14913 (0.4%, 25.2%)    385 (0.5%, 13.1%)  core::option::Option<T>::map
    14815 (0.4%, 25.6%)     12 (0.0%, 13.1%)  <shared::database::types::role::permissions::_::<impl serde::de::Deserialize for shared::database::types::role::permissions::Permissions>::deserialize::__Visitor as serde::de::Visitor>::visit_map
    14566 (0.4%, 26.0%)    114 (0.1%, 13.2%)  <bson::de::raw::DocumentAccess as serde::de::SeqAccess>::next_element_seed

Perhaps an investigation into why this is the case is in order.

I am unsure if this is normal behavior or not I just noticed on my 128core build machine that im spending roughly 20s building mongodb alone and 40s linking a binary in a debug build. (the total build time is 70s). I know that not all of that build time / linking time is cause by this repo and is likely caused by other dependencies in the tree. I am opening this issue here because of the strange build timings output where mongodb is not being compiled in parallel and because of llvm-lines showing bson producing exorbitant amounts of LLVM-IR which I think is the leading contributor to the slow build times I am facing.

TroyKomodo avatar May 01 '24 16:05 TroyKomodo