Feat: [MR-495] Populate Request Metadata

Cargo.toml

@@ -300,6 +300,7 @@ members = [
   "rs/rust_canisters/dfn_json",
   "rs/rust_canisters/dfn_macro",
   "rs/rust_canisters/dfn_protobuf",
+  "rs/rust_canisters/downstream_calls_test",
   "rs/rust_canisters/ecdsa",
   "rs/rust_canisters/http_types",
   "rs/rust_canisters/memory_test",

rs/canister_sandbox/backend_lib/src/sandbox_server.rs

@@ -161,7 +161,7 @@ mod tests {
     use ic_test_utilities::types::ids::{canister_test_id, subnet_test_id, user_test_id};
     use ic_types::{
         ingress::WasmResult,
-        messages::CallContextId,
+        messages::{CallContextId, RequestMetadata},
         methods::{FuncRef, WasmMethod},
         time::Time,
         CanisterTimer, ComputeAllocation, Cycles, MemoryAllocation, NumBytes, NumInstructions,
@@ -218,6 +218,7 @@ mod tests {
             CanisterTimer::Inactive,
             0,
             BTreeSet::from([controller]),
+            RequestMetadata::new(0, Time::from_nanos_since_unix_epoch(0)),
         )
     }
 

rs/canonical_state/src/encoding/tests/compatibility.rs

@@ -322,10 +322,10 @@ fn canonical_encoding_request_v14_plus() {
             .payment(Cycles::new(4))
             .method_name("test".to_string())
             .method_payload(vec![6])
-            .metadata(Some(RequestMetadata {
-                call_tree_depth: 13,
-                call_tree_start_time: Time::from_nanos_since_unix_epoch(101),
-            }))
+            .metadata(Some(RequestMetadata::new(
+                13,
+                Time::from_nanos_since_unix_epoch(101),
+            )))
             .build()
             .into();
 

rs/canonical_state/src/encoding/tests/test_fixtures.rs

@@ -33,10 +33,10 @@ pub fn request(certification_version: CertificationVersion) -> RequestOrResponse
         .method_name("test".to_string())
         .method_payload(vec![6])
         .metadata(
-            (certification_version >= CertificationVersion::V14).then_some(RequestMetadata {
-                call_tree_depth: 1,
-                call_tree_start_time: Time::from_nanos_since_unix_epoch(100_000),
-            }),
+            (certification_version >= CertificationVersion::V14).then_some(RequestMetadata::new(
+                1,
+                Time::from_nanos_since_unix_epoch(100_000),
+            )),
         )
         .build()
         .into()

rs/canonical_state/src/encoding/types.rs

@@ -55,9 +55,9 @@ pub struct RequestMetadata {
     #[serde(skip_serializing_if = "Option::is_none")]
     pub call_tree_depth: Option<u64>,
     #[serde(skip_serializing_if = "Option::is_none")]
-    pub call_tree_start_time: Option<Time>,
+    pub call_tree_start_time_u64: Option<u64>,
     #[serde(skip_serializing_if = "Option::is_none")]
-    pub call_subtree_deadline: Option<Time>,
+    pub call_subtree_deadline_u64: Option<u64>,
 }
 
 /// Canonical representation of `ic_types::messages::Request`.
@@ -260,9 +260,11 @@ impl TryFrom<RequestOrResponse> for ic_types::messages::RequestOrResponse {
 impl From<&ic_types::messages::RequestMetadata> for RequestMetadata {
     fn from(metadata: &ic_types::messages::RequestMetadata) -> Self {
         RequestMetadata {
-            call_tree_depth: Some(metadata.call_tree_depth),
-            call_tree_start_time: Some(metadata.call_tree_start_time),
-            call_subtree_deadline: None,
+            call_tree_depth: Some(*metadata.call_tree_depth()),
+            call_tree_start_time_u64: Some(
+                metadata.call_tree_start_time().as_nanos_since_unix_epoch(),
+            ),
+            call_subtree_deadline_u64: None,
         }
     }
 }
@@ -293,12 +295,10 @@ impl From<(&ic_types::messages::Request, CertificationVersion)> for Request {
 
 impl From<RequestMetadata> for ic_types::messages::RequestMetadata {
     fn from(metadata: RequestMetadata) -> Self {
-        ic_types::messages::RequestMetadata {
-            call_tree_depth: metadata.call_tree_depth.unwrap_or(0),
-            call_tree_start_time: metadata
-                .call_tree_start_time
-                .unwrap_or(Time::from_nanos_since_unix_epoch(0)),
-        }
+        ic_types::messages::RequestMetadata::new(
+            metadata.call_tree_depth.unwrap_or(0),
+            Time::from_nanos_since_unix_epoch(metadata.call_tree_start_time_u64.unwrap_or(0)),
+        )
     }
 }
 

rs/embedders/fuzz/fuzz_targets/execute_with_wasm_executor.rs

@@ -27,6 +27,7 @@ use ic_test_utilities::{
     types::ids::user_test_id,
 };
 use ic_types::{
+    messages::RequestMetadata,
     methods::{FuncRef, WasmMethod},
     ComputeAllocation, MemoryAllocation, NumBytes, NumInstructions,
 };
@@ -114,6 +115,7 @@ fn setup_wasm_execution_input(func_ref: FuncRef) -> WasmExecutionInput {
         &network_topology,
         dirty_page_overhead,
         ComputeAllocation::default(),
+        RequestMetadata::new(0, mock_time()),
     );
 
     let canister_current_memory_usage = NumBytes::new(0);

rs/embedders/src/wasmtime_embedder/wasmtime_embedder_tests.rs

@@ -18,7 +18,9 @@ use ic_system_api::{
 use ic_test_utilities::{
     cycles_account_manager::CyclesAccountManagerBuilder, mock_time, types::ids::canister_test_id,
 };
-use ic_types::{ComputeAllocation, MemoryAllocation, NumBytes, NumInstructions};
+use ic_types::{
+    messages::RequestMetadata, ComputeAllocation, MemoryAllocation, NumBytes, NumInstructions,
+};
 use ic_wasm_types::BinaryEncodedWasm;
 
 use lazy_static::lazy_static;
@@ -50,6 +52,7 @@ fn test_wasmtime_system_api() {
         &NetworkTopology::default(),
         SchedulerConfig::application_subnet().dirty_page_overhead,
         ComputeAllocation::default(),
+        RequestMetadata::new(0, mock_time()),
     );
     let canister_memory_limit = NumBytes::from(4 << 30);
     let canister_current_memory_usage = NumBytes::from(0);

rs/embedders/tests/wasmtime_random_memory_writes.rs

@@ -20,6 +20,7 @@ use ic_test_utilities::{
 use ic_test_utilities_logger::with_test_replica_logger;
 use ic_types::MemoryAllocation;
 use ic_types::{
+    messages::RequestMetadata,
     methods::{FuncRef, WasmMethod},
     ComputeAllocation, Cycles, NumBytes, NumInstructions, PrincipalId,
 };
@@ -69,6 +70,7 @@ fn test_api_for_update(
         }
         .dirty_page_overhead,
         ComputeAllocation::default(),
+        RequestMetadata::new(0, mock_time()),
     );
     let canister_memory_limit = NumBytes::from(4 << 30);
     let canister_current_memory_usage = NumBytes::from(0);

rs/execution_environment/benches/lib/src/common.rs

@@ -32,7 +32,7 @@ use ic_test_utilities::{
 };
 use ic_test_utilities_execution_environment::generate_network_topology;
 use ic_types::{
-    messages::{CallbackId, CanisterMessage, Payload, RejectContext},
+    messages::{CallbackId, CanisterMessage, Payload, RejectContext, RequestMetadata},
     methods::{Callback, WasmClosure},
     Cycles, MemoryAllocation, NumBytes, NumInstructions, Time,
 };
@@ -113,7 +113,12 @@ where
         .system_state
         .call_context_manager_mut()
         .unwrap()
-        .new_call_context(call_origin.clone(), Cycles::new(10), mock_time());
+        .new_call_context(
+            call_origin.clone(),
+            Cycles::new(10),
+            mock_time(),
+            RequestMetadata::new(0, mock_time()),
+        );
     let callback = Callback::new(
         call_context_id,
         canister_test_id(LOCAL_CANISTER_ID),

rs/execution_environment/src/execution/common.rs

@@ -6,6 +6,8 @@ use lazy_static::lazy_static;
 use prometheus::IntCounter;
 use std::sync::atomic::{AtomicU64, Ordering};
 
+use crate::execution_environment::ExecutionResponse;
+use crate::{as_round_instructions, metrics::CallTreeMetrics, ExecuteMessageResult, RoundLimits};
 use ic_base_types::{CanisterId, NumBytes, SubnetId};
 use ic_embedders::wasm_executor::{CanisterStateChanges, SliceExecutionOutput};
 use ic_error_types::{ErrorCode, RejectCode, UserError};
@@ -18,7 +20,7 @@ use ic_replicated_state::{
     CallContext, CallContextAction, CallOrigin, CanisterState, ExecutionState, NetworkTopology,
     SystemState,
 };
-use ic_system_api::sandbox_safe_system_state::SystemStateChanges;
+use ic_system_api::sandbox_safe_system_state::{RequestMetadataStats, SystemStateChanges};
 use ic_types::ingress::{IngressState, IngressStatus, WasmResult};
 use ic_types::messages::{
     CallContextId, CallbackId, CanisterCall, CanisterCallOrTask, MessageId, Payload, RejectContext,
@@ -27,9 +29,6 @@ use ic_types::messages::{
 use ic_types::methods::{Callback, WasmMethod};
 use ic_types::{Cycles, NumInstructions, Time, UserId};
 
-use crate::execution_environment::ExecutionResponse;
-use crate::{as_round_instructions, ExecuteMessageResult, RoundLimits};
-
 lazy_static! {
     /// Track how many system task errors have been encountered
     /// so that we can restrict logging to a sample of them.
@@ -414,7 +413,7 @@ fn try_apply_canister_state_changes(
     network_topology: &NetworkTopology,
     subnet_id: SubnetId,
     log: &ReplicaLogger,
-) -> HypervisorResult<()> {
+) -> HypervisorResult<RequestMetadataStats> {
     subnet_available_memory
         .try_decrement(
             output.allocated_bytes,
@@ -446,6 +445,8 @@ pub fn apply_canister_state_changes(
     subnet_id: SubnetId,
     log: &ReplicaLogger,
     state_changes_error: &IntCounter,
+    call_tree_metrics: &dyn CallTreeMetrics,
+    call_context_creation_time: Time,
 ) {
     if let Some(CanisterStateChanges {
         globals,
@@ -468,7 +469,7 @@ pub fn apply_canister_state_changes(
             subnet_id,
             log,
         ) {
-            Ok(()) => {
+            Ok(request_stats) => {
                 execution_state.wasm_memory = wasm_memory;
                 execution_state.stable_memory = stable_memory;
                 execution_state.exported_globals = globals;
@@ -477,6 +478,8 @@ pub fn apply_canister_state_changes(
                 // i.e., `(start)`, `canister_init`, `canister_pre_upgrade`, and `canister_post_upgrade`)
                 // call this `apply_canister_state_change` to finish execution.
                 system_state.canister_version += 1;
+
+                call_tree_metrics.observe(request_stats, call_context_creation_time, time);
             }
             Err(err) => {
                 debug_assert_eq!(err, HypervisorError::OutOfMemory);

rs/execution_environment/src/execution/inspect_message.rs

@@ -1,7 +1,7 @@
 use crate::Hypervisor;
 use crate::{
     execution_environment::{as_round_instructions, RoundLimits},
-    metrics::IngressFilterMetrics,
+    metrics::{CallTreeMetricsNoOp, IngressFilterMetrics},
 };
 use ic_error_types::{ErrorCode, UserError};
 use ic_interfaces::execution_environment::SubnetAvailableMemory;
@@ -28,7 +28,7 @@ pub fn execute_inspect_message(
     network_topology: &NetworkTopology,
     logger: &ReplicaLogger,
     state_changes_error: &IntCounter,
-    metrics: &IngressFilterMetrics,
+    ingress_filter_metrics: &IngressFilterMetrics,
 ) -> (NumInstructions, Result<(), UserError>) {
     let canister_id = canister.canister_id();
     let memory_usage = canister.memory_usage();
@@ -69,7 +69,9 @@ pub fn execute_inspect_message(
         // Ignore compute allocation
         compute_allocation_used: 0,
     };
-    let inspect_message_timer = metrics.inspect_message_duration_seconds.start_timer();
+    let inspect_message_timer = ingress_filter_metrics
+        .inspect_message_duration_seconds
+        .start_timer();
     let (output, _output_execution_state, _system_state_accessor) = hypervisor.execute(
         system_api,
         time,
@@ -82,10 +84,12 @@ pub fn execute_inspect_message(
         network_topology,
         &mut round_limits,
         state_changes_error,
+        &CallTreeMetricsNoOp,
+        time,
     );
     drop(inspect_message_timer);
-    metrics.inspect_message_count.inc();
-    metrics
+    ingress_filter_metrics.inspect_message_count.inc();
+    ingress_filter_metrics
         .inspect_message_instructions
         .observe((message_instruction_limit.get() - output.num_instructions_left.get()) as f64);
     match output.wasm_result {

rs/execution_environment/src/execution/install.rs

@@ -24,7 +24,7 @@ use ic_replicated_state::{
 };
 use ic_system_api::ApiType;
 use ic_types::funds::Cycles;
-use ic_types::messages::CanisterCall;
+use ic_types::messages::{CanisterCall, RequestMetadata};
 use ic_types::methods::{FuncRef, SystemMethod, WasmMethod};
 
 /// Installs a new code in canister. The algorithm consists of five stages:
@@ -156,6 +156,7 @@ pub(crate) fn execute_install(
             helper.canister_message_memory_usage(),
             helper.execution_parameters().clone(),
             FuncRef::Method(method),
+            RequestMetadata::for_new_call_tree(original.time),
             round_limits,
             round.network_topology,
         );
@@ -269,6 +270,7 @@ fn install_stage_2b_continue_install_after_start(
         helper.canister_message_memory_usage(),
         helper.execution_parameters().clone(),
         FuncRef::Method(method),
+        RequestMetadata::for_new_call_tree(original.time),
         round_limits,
         round.network_topology,
     );

rs/execution_environment/src/execution/nonreplicated_query.rs

@@ -7,13 +7,13 @@
 
 use crate::execution::common::{validate_canister, validate_method};
 use crate::execution_environment::RoundLimits;
-use crate::{Hypervisor, NonReplicatedQueryKind};
+use crate::{metrics::CallTreeMetricsNoOp, Hypervisor, NonReplicatedQueryKind};
 use ic_error_types::UserError;
 use ic_interfaces::execution_environment::SystemApiCallCounters;
 use ic_replicated_state::{CallOrigin, CanisterState, NetworkTopology};
 use ic_system_api::{ApiType, ExecutionParameters};
 use ic_types::ingress::WasmResult;
-use ic_types::messages::CallContextId;
+use ic_types::messages::{CallContextId, RequestMetadata};
 use ic_types::methods::{FuncRef, WasmMethod};
 use ic_types::{Cycles, NumInstructions, Time};
 use prometheus::IntCounter;
@@ -81,7 +81,12 @@ pub fn execute_non_replicated_query(
                 .system_state
                 .call_context_manager_mut()
                 .unwrap()
-                .new_call_context(call_origin, Cycles::zero(), time);
+                .new_call_context(
+                    call_origin,
+                    Cycles::zero(),
+                    time,
+                    RequestMetadata::for_new_call_tree(time),
+                );
             (
                 ic_system_api::NonReplicatedQueryKind::Stateful {
                     call_context_id,
@@ -101,6 +106,7 @@ pub fn execute_non_replicated_query(
         data_certificate,
         non_replicated_query_kind,
     );
+
     // As we are executing the query in non-replicated mode, we can
     // modify the canister as the caller is not going to be able to
     // commit modifications to the canister anyway.
@@ -116,6 +122,8 @@ pub fn execute_non_replicated_query(
         network_topology,
         round_limits,
         state_changes_error,
+        &CallTreeMetricsNoOp,
+        time,
     );
     canister.system_state = output_system_state;
     if preserve_changes {