Merge branch 'ulan/run-680' into 'master'

RUN-680: Add a config flag for tracing message execution

This adds a flag named `trace_execution` to the execution
environment config. The flag is disabled by default.

When enabled, it logs the following after each message execution:

```
Executed <canister_id>::<function_name>: instructions=<N>, duration=<T>ms.
```

Subsequent MRs will hook this flag with ic-start and dfx. 

See merge request dfinity-lab/public/ic!13246

rs/canister_sandbox/replica_controller/src/sandboxed_execution_controller.rs

@@ -6,9 +6,10 @@ use ic_canister_sandbox_common::protocol::structs::{SandboxExecInput, SandboxExe
 use ic_canister_sandbox_common::sandbox_service::SandboxService;
 use ic_canister_sandbox_common::{protocol, rpc};
 use ic_config::embedders::Config as EmbeddersConfig;
+use ic_config::flag_status::FlagStatus;
 use ic_embedders::wasm_executor::{
     get_wasm_reserved_pages, wasm_execution_error, CanisterStateChanges, PausedWasmExecution,
-    WasmExecutionResult, WasmExecutor,
+    SliceExecutionOutput, WasmExecutionResult, WasmExecutor,
 };
 use ic_embedders::{
     wasm_utils::WasmImportsDetails, CompilationCache, CompilationResult, WasmExecutionInput,
@@ -24,6 +25,7 @@ use ic_replicated_state::canister_state::execution_state::{
 };
 use ic_replicated_state::{EmbedderCache, ExecutionState, ExportedFunctions, Memory, PageMap};
 use ic_types::ingress::WasmResult;
+use ic_types::methods::{FuncRef, WasmMethod};
 use ic_types::{CanisterId, NumInstructions};
 use ic_wasm_types::CanisterModule;
 #[cfg(target_os = "linux")]
@@ -455,6 +457,69 @@ enum SandboxProcessStatus {
     Evicted,
 }
 
+// This is a helper struct that is used for tracing execution of method when the
+// `ic_config::execution_environment::Config::trace_execution` flag is enabled.
+// The struct keeps track of the number of executed slices, instructions and
+// the total duration of all executed slices.
+struct ExecutionTracingState {
+    canister_id: CanisterId,
+    function: FuncRef,
+    slices: usize,
+    instructions: NumInstructions,
+    duration: Duration,
+}
+
+impl ExecutionTracingState {
+    fn observe_slice(&mut self, slice: &SliceExecutionOutput, duration: Duration) {
+        self.slices += 1;
+        self.instructions += slice.executed_instructions;
+        self.duration += duration;
+    }
+
+    fn trace(&mut self, log: &ReplicaLogger, result: &SandboxExecOutput, duration: Duration) {
+        self.observe_slice(&result.slice, duration);
+        let canister_id = self.canister_id;
+        let function_name = self.format_function_name();
+        let instructions = self.instructions;
+        let duration_ms = duration.as_millis();
+        info!(log, "Executed {canister_id}::{function_name}: instructions = {instructions}, duration = {duration_ms}ms.");
+        eprintln!("Executed {canister_id}::{function_name}: instructions = {instructions}, duration = {duration_ms}ms.");
+    }
+
+    fn format_function_name(&self) -> String {
+        match &self.function {
+            FuncRef::Method(method) => match method {
+                WasmMethod::Update(name)
+                | WasmMethod::Query(name)
+                | WasmMethod::CompositeQuery(name) => name.to_string(),
+                WasmMethod::System(system) => system.to_string(),
+            },
+            FuncRef::UpdateClosure(closure) | FuncRef::QueryClosure(closure) => {
+                format!("[response@{}::{}]", closure.func_idx, closure.env)
+            }
+        }
+    }
+}
+
+enum ExecutionTracing {
+    Enabled(ExecutionTracingState),
+    Disabled,
+}
+
+impl ExecutionTracing {
+    fn observe_slice(&mut self, slice: &SliceExecutionOutput, duration: Duration) {
+        if let ExecutionTracing::Enabled(state) = self {
+            state.observe_slice(slice, duration);
+        }
+    }
+
+    fn trace(&mut self, log: &ReplicaLogger, result: &SandboxExecOutput, duration: Duration) {
+        if let ExecutionTracing::Enabled(state) = self {
+            state.trace(log, result, duration);
+        }
+    }
+}
+
 // Represent a paused sandbox execution.
 struct PausedSandboxExecution {
     canister_id: CanisterId,
@@ -465,6 +530,7 @@ struct PausedSandboxExecution {
     message_instruction_limit: NumInstructions,
     api_type_label: &'static str,
     controller: Arc<SandboxedExecutionController>,
+    execution_tracing: ExecutionTracing,
 }
 
 impl std::fmt::Debug for PausedSandboxExecution {
@@ -482,6 +548,7 @@ impl PausedWasmExecution for PausedSandboxExecution {
         // Create channel through which we will receive the execution
         // output from closure (running by IPC thread at end of
         // execution).
+        let timer = std::time::Instant::now();
         let (tx, rx) = std::sync::mpsc::sync_channel(1);
         let sandbox_process = Arc::clone(&self.sandbox_process);
         self.sandbox_process
@@ -515,6 +582,8 @@ impl PausedWasmExecution for PausedSandboxExecution {
             self.message_instruction_limit,
             self.api_type_label,
             self.sandbox_process,
+            self.execution_tracing,
+            timer,
         )
     }
 
@@ -561,6 +630,7 @@ pub struct SandboxedExecutionController {
     min_sandbox_count: usize,
     max_sandbox_count: usize,
     max_sandbox_idle_time: Duration,
+    trace_execution: FlagStatus,
     logger: ReplicaLogger,
     /// Executable and arguments to be passed to `canister_sandbox` which are
     /// the same for all canisters.
@@ -599,6 +669,7 @@ impl WasmExecutor for SandboxedExecutionController {
     ) -> (Option<CompilationResult>, WasmExecutionResult) {
         let message_instruction_limit = execution_parameters.instruction_limits.message();
         let api_type_label = api_type.as_str();
+        let execution_start = std::time::Instant::now();
         let _execute_timer = self
             .metrics
             .sandboxed_execution_replica_execute_duration
@@ -610,6 +681,17 @@ impl WasmExecutor for SandboxedExecutionController {
             .with_label_values(&[api_type_label])
             .start_timer();
 
+        let execution_tracing = match self.trace_execution {
+            FlagStatus::Enabled => ExecutionTracing::Enabled(ExecutionTracingState {
+                canister_id: sandbox_safe_system_state.canister_id(),
+                function: func_ref.clone(),
+                slices: 0,
+                instructions: NumInstructions::new(0),
+                duration: Duration::from_secs(0),
+            }),
+            FlagStatus::Disabled => ExecutionTracing::Disabled,
+        };
+
         // Determine which process we want to run this on.
         let sandbox_process = self.get_sandbox_process(sandbox_safe_system_state.canister_id());
 
@@ -711,6 +793,8 @@ impl WasmExecutor for SandboxedExecutionController {
             message_instruction_limit,
             api_type_label,
             sandbox_process,
+            execution_tracing,
+            execution_start,
         );
         (compilation_result, execution_result)
     }
@@ -932,6 +1016,7 @@ impl SandboxedExecutionController {
         let min_sandbox_count = embedder_config.min_sandbox_count;
         let max_sandbox_count = embedder_config.max_sandbox_count;
         let max_sandbox_idle_time = embedder_config.max_sandbox_idle_time;
+        let trace_execution = embedder_config.trace_execution;
         let sandbox_exec_argv =
             create_sandbox_argv(embedder_config).expect("No canister_sandbox binary found");
         let backends = Arc::new(Mutex::new(HashMap::new()));
@@ -977,6 +1062,7 @@ impl SandboxedExecutionController {
             min_sandbox_count,
             max_sandbox_count,
             max_sandbox_idle_time,
+            trace_execution,
             logger,
             sandbox_exec_argv,
             metrics,
@@ -1190,9 +1276,12 @@ impl SandboxedExecutionController {
         message_instruction_limit: NumInstructions,
         api_type_label: &'static str,
         sandbox_process: Arc<SandboxProcess>,
+        mut execution_tracing: ExecutionTracing,
+        execution_start: std::time::Instant,
     ) -> WasmExecutionResult {
         let mut exec_output = match result {
             CompletionResult::Paused(slice) => {
+                execution_tracing.observe_slice(&slice, execution_start.elapsed());
                 self.metrics
                     .observe_executed_message_slice(api_type_label, "Paused");
                 let paused = Box::new(PausedSandboxExecution {
@@ -1204,6 +1293,7 @@ impl SandboxedExecutionController {
                     message_instruction_limit,
                     api_type_label,
                     controller: self,
+                    execution_tracing,
                 });
                 return WasmExecutionResult::Paused(slice, paused);
             }
@@ -1244,6 +1334,8 @@ impl SandboxedExecutionController {
             .with_label_values(&[api_type_label])
             .observe(exec_output.execute_run_duration.as_secs_f64());
 
+        execution_tracing.trace(&self.logger, &exec_output, execution_start.elapsed());
+
         WasmExecutionResult::Finished(exec_output.slice, exec_output.wasm, canister_state_changes)
     }
 

rs/config/src/embedders.rs

@@ -150,6 +150,10 @@ pub struct Config {
     /// replaced with the correct value at runtime when the hypervisor is
     /// created.
     pub dirty_page_overhead: NumInstructions,
+
+    /// If this flag is enabled, then execution of a slice will produce a log
+    /// entry with the number of executed instructions and the duration.
+    pub trace_execution: FlagStatus,
 }
 
 impl Config {
@@ -173,6 +177,7 @@ impl Config {
             max_sandbox_idle_time: DEFAULT_MAX_SANDBOX_IDLE_TIME,
             subnet_type: SubnetType::Application,
             dirty_page_overhead: NumInstructions::new(0),
+            trace_execution: FlagStatus::Disabled,
         }
     }
 }

rs/config/src/execution_environment.rs

@@ -239,6 +239,10 @@ pub struct Config {
 
     /// The capacity of the Wasm compilation cache.
     pub max_compilation_cache_size: NumBytes,
+
+    /// If this flag is enabled, then execution of a slice will produce a log
+    /// entry with the number of executed instructions and the duration.
+    pub trace_execution: FlagStatus,
 }
 
 impl Default for Config {
@@ -310,6 +314,7 @@ impl Default for Config {
                 embedders::STABLE_MEMORY_DIRTY_PAGE_LIMIT,
             ),
             max_compilation_cache_size: MAX_COMPILATION_CACHE_SIZE,
+            trace_execution: FlagStatus::Disabled,
         }
     }
 }

rs/execution_environment/src/hypervisor.rs

@@ -200,6 +200,7 @@ impl Hypervisor {
         embedder_config.stable_memory_dirty_page_limit = config.stable_memory_dirty_page_limit;
         embedder_config.subnet_type = own_subnet_type;
         embedder_config.dirty_page_overhead = dirty_page_overhead;
+        embedder_config.trace_execution = config.trace_execution;
 
         let wasm_executor: Arc<dyn WasmExecutor> = match config.canister_sandboxing_flag {
             FlagStatus::Enabled => {