Log slow deserialization

Summary:
## This stack

Track and down methods that are holding up the reactor and optimize them.

## This diff

Large blobs can take a long time to deserialize; the operation is synchronous, which will block the reactor. Log a warning when that happens.

Reviewed By: markbt

Differential Revision: D66766253

fbshipit-source-id: bf61b97aa8b41eb55263f668aee4be71e83d6dd9

eden/mononoke/mononoke_types/Cargo.toml

@@ -48,6 +48,7 @@ sapling-xdiff = { version = "0.1.0", path = "../../scm/lib/xdiff" }
 serde = { version = "1.0.185", features = ["derive", "rc"] }
 serde_derive = "1.0.185"
 sha1 = "0.10.5"
+slog = { version = "2.7", features = ["max_level_trace", "nested-values"] }
 smallvec = { version = "1.6.1", features = ["serde", "specialization", "union"] }
 sorted_vector_map = { version = "0.2.0", git = "https://github.com/facebookexperimental/rust-shed.git", branch = "main" }
 sql = { version = "0.1.0", git = "https://github.com/facebookexperimental/rust-shed.git", branch = "main" }

eden/mononoke/mononoke_types/src/typed_hash.rs

@@ -23,6 +23,7 @@ use edenapi_types::BonsaiChangesetId as EdenapiBonsaiChangesetId;
 use edenapi_types::CommitId as EdenapiCommitId;
 use edenapi_types::ContentId as EdenapiContentId;
 use edenapi_types::FsnodeId as EdenapiFsnodeId;
+pub use slog;
 use sql::mysql;
 
 use crate::basename_suffix_skeleton_manifest_v3::BssmV3Directory;
@@ -57,6 +58,8 @@ use crate::unode::FileUnode;
 use crate::unode::ManifestUnode;
 use crate::ThriftConvert;
 
+pub const SLOW_DESERIAZLIZATION_THRESHOLD_MS: u128 = 100;
+
 // There is no NULL_HASH for typed hashes. Any places that need a null hash should use an
 // Option type, or perhaps a list as desired.
 
@@ -440,9 +443,17 @@ macro_rules! impl_typed_hash_loadable {
                 let blobstore_key = id.blobstore_key();
                 let get = blobstore.get(ctx, &blobstore_key);
 
-                let bytes = get.await?.ok_or(LoadableError::Missing(blobstore_key))?;
+                let bytes = get.await?.ok_or(LoadableError::Missing(blobstore_key.clone()))?;
+
+                let now = std::time::Instant::now();
                 let blob: Blob<$typed> = Blob::new(id, bytes.into_raw_bytes());
-                <Self::Value as BlobstoreValue>::from_blob(blob).map_err(LoadableError::Error)
+                let len = blob.len();
+                let ret = <Self::Value as BlobstoreValue>::from_blob(blob).map_err(LoadableError::Error);
+                let diff = now.elapsed().as_millis();
+                if diff > $crate::typed_hash::SLOW_DESERIAZLIZATION_THRESHOLD_MS {
+                    $crate::typed_hash::slog::warn!(ctx.logger(), "Slow load of {} ({} bytes) took {:?}", blobstore_key, len, now.elapsed());
+                }
+                ret
             }
         }