From 1e14f3c8779c2b7f8aba38c88cfb1d7026180284 Mon Sep 17 00:00:00 2001 From: Alexandru Uta Date: Tue, 13 Feb 2024 12:07:49 +0000 Subject: [PATCH] [RUN-888] Show dirty page info per message type --- rs/config/src/execution_environment.rs | 4 ++++ .../src/canister_manager.rs | 4 ++++ .../src/canister_manager/tests.rs | 1 + .../src/execution/install_code.rs | 14 ++++++++++++- .../src/execution/response.rs | 17 +++++++++++++++- .../src/execution/update.rs | 17 +++++++++++++++- .../src/execution_environment.rs | 20 ++++++++++++++++++- 7 files changed, 73 insertions(+), 4 deletions(-) diff --git a/rs/config/src/execution_environment.rs b/rs/config/src/execution_environment.rs index 00296668090..73c3bc6057f 100644 --- a/rs/config/src/execution_environment.rs +++ b/rs/config/src/execution_environment.rs @@ -264,6 +264,9 @@ pub struct Config { // TODO(IC-272): remove this flag once the feature is enabled by default. /// Indicates whether fetching canister logs API is enabled or not. pub fetch_canister_logs: FlagStatus, + + /// Indicates whether dirty page logging is enabled or not. + pub dirty_page_logging: FlagStatus, } impl Default for Config { @@ -335,6 +338,7 @@ impl Default for Config { stop_canister_timeout_duration: STOP_CANISTER_TIMEOUT_DURATION, canister_snapshots: FlagStatus::Disabled, fetch_canister_logs: FlagStatus::Disabled, + dirty_page_logging: FlagStatus::Disabled, } } } diff --git a/rs/execution_environment/src/canister_manager.rs b/rs/execution_environment/src/canister_manager.rs index 94c73548d9d..835c0cf66bc 100644 --- a/rs/execution_environment/src/canister_manager.rs +++ b/rs/execution_environment/src/canister_manager.rs @@ -829,6 +829,7 @@ impl CanisterManager { round_limits: &mut RoundLimits, round_counters: RoundCounters, subnet_size: usize, + log_dirty_pages: FlagStatus, ) -> ( Result, NumInstructions, @@ -867,6 +868,7 @@ impl CanisterManager { CompilationCostHandling::CountFullAmount, round_counters, subnet_size, + log_dirty_pages, ); match dts_result { DtsInstallCodeResult::Finished { @@ -925,6 +927,7 @@ impl CanisterManager { compilation_cost_handling: CompilationCostHandling, round_counters: RoundCounters, subnet_size: usize, + log_dirty_pages: FlagStatus, ) -> DtsInstallCodeResult { if let Err(err) = validate_controller(&canister, &context.sender()) { return DtsInstallCodeResult::Finished { @@ -980,6 +983,7 @@ impl CanisterManager { requested_memory_allocation: context.memory_allocation, sender: context.sender(), canister_id: canister.canister_id(), + log_dirty_pages, }; let round = RoundContext { diff --git a/rs/execution_environment/src/canister_manager/tests.rs b/rs/execution_environment/src/canister_manager/tests.rs index 76d8b129799..e55e79d7f9e 100644 --- a/rs/execution_environment/src/canister_manager/tests.rs +++ b/rs/execution_environment/src/canister_manager/tests.rs @@ -368,6 +368,7 @@ fn install_code( round_limits, round_counters, SMALL_APP_SUBNET_MAX_SIZE, + Config::default().dirty_page_logging, ); let instructions_left = instruction_limit - instructions_used.min(instruction_limit); (instructions_left, result, canister) diff --git a/rs/execution_environment/src/execution/install_code.rs b/rs/execution_environment/src/execution/install_code.rs index cb89ec721b2..59d5d703eff 100644 --- a/rs/execution_environment/src/execution/install_code.rs +++ b/rs/execution_environment/src/execution/install_code.rs @@ -30,7 +30,7 @@ use crate::{ CanisterManagerError, CanisterMgrConfig, DtsInstallCodeResult, InstallCodeResult, }, canister_settings::{validate_canister_settings, CanisterSettings}, - execution_environment::RoundContext, + execution_environment::{log_dirty_pages, RoundContext}, CompilationCostHandling, RoundLimits, }; @@ -415,6 +415,17 @@ impl InstallCodeHelper { let old_wasm_hash = get_wasm_hash(&clean_canister); let new_wasm_hash = get_wasm_hash(&self.canister); + + if original.log_dirty_pages == FlagStatus::Enabled { + log_dirty_pages( + round.log, + &original.canister_id, + original.message.method_name(), + self.total_heap_delta.get() as usize / PAGE_SIZE, + instructions_used, + ); + } + DtsInstallCodeResult::Finished { canister: self.canister, message: original.message, @@ -798,6 +809,7 @@ pub(crate) struct OriginalContext { pub requested_memory_allocation: Option, pub sender: PrincipalId, pub canister_id: CanisterId, + pub log_dirty_pages: FlagStatus, } pub(crate) fn validate_controller( diff --git a/rs/execution_environment/src/execution/response.rs b/rs/execution_environment/src/execution/response.rs index d1a22203f63..c658b32d527 100644 --- a/rs/execution_environment/src/execution/response.rs +++ b/rs/execution_environment/src/execution/response.rs @@ -31,9 +31,11 @@ use crate::execution::common::{ self, action_to_response, apply_canister_state_changes, update_round_limits, }; use crate::execution_environment::{ - ExecuteMessageResult, ExecutionResponse, PausedExecution, RoundContext, RoundLimits, + log_dirty_pages, ExecuteMessageResult, ExecutionResponse, PausedExecution, RoundContext, + RoundLimits, }; use crate::metrics::CallTreeMetrics; +use ic_config::flag_status::FlagStatus; #[cfg(test)] mod tests; @@ -554,6 +556,16 @@ impl ResponseHelper { ); } + if original.log_dirty_pages == FlagStatus::Enabled { + log_dirty_pages( + round.log, + &original.canister_id, + format!("reponse_to_{}", original.message.originator).as_str(), + heap_delta.get() as usize / PAGE_SIZE, + instructions_used, + ); + } + ExecuteMessageResult::Finished { canister: self.canister, response, @@ -639,6 +651,7 @@ struct OriginalContext { canister_id: CanisterId, subnet_memory_reservation: NumBytes, instructions_executed: NumInstructions, + log_dirty_pages: FlagStatus, } /// Struct used to hold necessary information for the @@ -844,6 +857,7 @@ pub fn execute_response( subnet_size: usize, subnet_memory_reservation: NumBytes, call_tree_metrics: &dyn CallTreeMetrics, + log_dirty_pages: FlagStatus, ) -> ExecuteMessageResult { let (callback, callback_id, call_context, call_context_id) = match common::get_call_context_and_callback( @@ -890,6 +904,7 @@ pub fn execute_response( canister_id: clean_canister.canister_id(), subnet_memory_reservation, instructions_executed: call_context.instructions_executed(), + log_dirty_pages, }; let mut helper = diff --git a/rs/execution_environment/src/execution/update.rs b/rs/execution_environment/src/execution/update.rs index a35101cd7e6..8936a1817e6 100644 --- a/rs/execution_environment/src/execution/update.rs +++ b/rs/execution_environment/src/execution/update.rs @@ -6,10 +6,11 @@ use crate::execution::common::{ ingress_status_with_processing_state, update_round_limits, validate_message, }; use crate::execution_environment::{ - ExecuteMessageResult, PausedExecution, RoundContext, RoundLimits, + log_dirty_pages, ExecuteMessageResult, PausedExecution, RoundContext, RoundLimits, }; use crate::metrics::CallTreeMetrics; use ic_base_types::CanisterId; +use ic_config::flag_status::FlagStatus; use ic_embedders::wasm_executor::{CanisterStateChanges, PausedWasmExecution, WasmExecutionResult}; use ic_error_types::{ErrorCode, UserError}; use ic_interfaces::execution_environment::{ @@ -43,6 +44,7 @@ pub fn execute_update( round_limits: &mut RoundLimits, subnet_size: usize, call_tree_metrics: &dyn CallTreeMetrics, + log_dirty_pages: FlagStatus, ) -> ExecuteMessageResult { let (clean_canister, prepaid_execution_cycles, resuming_aborted) = match prepaid_execution_cycles { @@ -111,6 +113,7 @@ pub fn execute_update( request_metadata, freezing_threshold, canister_id: clean_canister.canister_id(), + log_dirty_pages, }; let helper = match UpdateHelper::new(&clean_canister, &original) { @@ -267,6 +270,7 @@ struct OriginalContext { request_metadata: RequestMetadata, freezing_threshold: Cycles, canister_id: CanisterId, + log_dirty_pages: FlagStatus, } /// Contains fields of `UpdateHelper` that are necessary for resuming an update @@ -465,6 +469,17 @@ impl UpdateHelper { original.subnet_size, round.log, ); + + if original.log_dirty_pages == FlagStatus::Enabled { + log_dirty_pages( + round.log, + &original.canister_id, + &original.method.name(), + output.instance_stats.dirty_pages, + instructions_used, + ); + } + ExecuteMessageResult::Finished { canister: self.canister, response, diff --git a/rs/execution_environment/src/execution_environment.rs b/rs/execution_environment/src/execution_environment.rs index 4774a20cf55..729b6e2d4f6 100644 --- a/rs/execution_environment/src/execution_environment.rs +++ b/rs/execution_environment/src/execution_environment.rs @@ -178,6 +178,21 @@ pub fn as_num_instructions(a: RoundInstructions) -> NumInstructions { NumInstructions::from(u64::try_from(a.get()).unwrap_or(0)) } +/// Helper method for logging dirty pages. +pub fn log_dirty_pages( + log: &ReplicaLogger, + canister_id: &CanisterId, + method_name: &str, + dirty_pages: usize, + instructions: NumInstructions, +) { + let output_message = format!( + "Executed {canister_id}::{method_name}: dirty_4kb_pages = {dirty_pages}, instructions = {instructions}" + ); + info!(log, "{}", output_message.as_str()); + eprintln!("{output_message}"); +} + /// Contains limits (or budget) for various resources that affect duration of /// a round such as /// - executed instructions, @@ -1400,6 +1415,7 @@ impl ExecutionEnvironment { round_limits, subnet_size, &self.call_tree_metrics, + self.config.dirty_page_logging, ) } WasmMethod::System(_) => { @@ -1425,7 +1441,6 @@ impl ExecutionEnvironment { ExecutionMode::Replicated, self.subnet_memory_saturation(&round_limits.subnet_available_memory), ); - execute_update( canister, CanisterCallOrTask::Task(task.clone()), @@ -1437,6 +1452,7 @@ impl ExecutionEnvironment { round_limits, subnet_size, &self.call_tree_metrics, + self.config.dirty_page_logging, ) } @@ -1809,6 +1825,7 @@ impl ExecutionEnvironment { subnet_size, scaled_subnet_memory_reservation, &self.call_tree_metrics, + self.config.dirty_page_logging, ) } @@ -2480,6 +2497,7 @@ impl ExecutionEnvironment { compilation_cost_handling, round_counters, subnet_size, + self.config.dirty_page_logging, ); self.process_install_code_result(state, dts_result, dts_status, since) }