[RUN-888] Show dirty page info per message type

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,
         }
     }
 }

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<InstallCodeResult, CanisterManagerError>,
         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 {

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)

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<MemoryAllocation>,
     pub sender: PrincipalId,
     pub canister_id: CanisterId,
+    pub log_dirty_pages: FlagStatus,
 }
 
 pub(crate) fn validate_controller(

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 =

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,

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)
     }