Adding detailled Docker profile times to local_run() in brane-cli

brane-cli/src/repl.rs

@@ -31,6 +31,7 @@ use rustyline::history::DefaultHistory;
 use rustyline::validate::{self, MatchingBracketValidator, Validator};
 use rustyline::{CompletionType, Config, Context, EditMode, Editor};
 use rustyline_derive::Helper;
+use specifications::profiling::ProfileScopeHandle;
 
 pub use crate::errors::ReplError as Error;
 use crate::instance::InstanceInfo;
@@ -388,10 +389,12 @@ async fn local_repl(
                 let snippet = Snippet { lines: line_count, workflow };
 
                 // Next, we run the VM (one snippet only ayway)
-                let res: FullValue = run_offline_vm(&mut state, snippet).await.map_err(|source| Error::RunError { what: "offline VM", source })?;
+                let res: FullValue = run_offline_vm(&mut state, snippet, ProfileScopeHandle::dummy())
+                    .await
+                    .map_err(|source| Error::RunError { what: "offline VM", source })?;
 
                 // Then, we collect and process the result
-                if let Err(source) = process_offline_result(res) {
+                if let Err(source) = process_offline_result(res, ProfileScopeHandle::dummy()) {
                     error!("{}", Error::ProcessError { what: "offline VM", source });
                     continue;
                 }

brane-cli/src/run.rs

@@ -14,7 +14,7 @@
 
 use std::borrow::Cow;
 use std::fs;
-use std::io::{Read, Stderr, Stdout, Write};
+use std::io::{Read, Stderr, Stdout, Write, stdout};
 use std::path::{Path, PathBuf};
 use std::str::FromStr;
 use std::sync::Arc;
@@ -33,6 +33,7 @@ use parking_lot::{Mutex, MutexGuard};
 use specifications::data::{AccessKind, DataIndex, DataInfo};
 use specifications::driving::{CreateSessionRequest, DriverServiceClient, ExecuteRequest};
 use specifications::package::PackageIndex;
+use specifications::profiling::{ProfileReport, ProfileScopeHandle};
 use tempfile::{TempDir, tempdir};
 use tonic::Code;
 
@@ -558,17 +559,18 @@ pub async fn run_dummy_vm(state: &mut DummyVmState, what: impl AsRef<str>, snipp
 ///
 /// # Arguments
 /// - `state`: The OfflineVmState that we use to run the local VM.
-/// - `what`: The thing we're running. Either a filename, or something like stdin.
 /// - `snippet`: The snippet to compile and run.
+/// - `scope`: Some [`ProfileScopeHandle`] to report profile timings in. Use a
+///   [`ProfileScopeHandle::dummy()`] if you don't care.
 ///
 /// # Returns
 /// The FullValue that the workflow returned, if any. If there was no value, returns FullValue::Void instead.
 ///
 /// # Errors
 /// This function errors if we failed to compile or run the workflow somehow.
-pub async fn run_offline_vm(state: &mut OfflineVmState, snippet: Snippet) -> Result<FullValue, Error> {
+pub async fn run_offline_vm(state: &mut OfflineVmState, snippet: Snippet, scope: ProfileScopeHandle) -> Result<FullValue, Error> {
     // Run it in the local VM (which is a bit ugly do to the need to consume the VM itself)
-    let res: (OfflineVm, Result<FullValue, OfflineVmError>) = state.vm.take().unwrap().exec(snippet.workflow).await;
+    let res: (OfflineVm, Result<FullValue, OfflineVmError>) = state.vm.take().unwrap().exec(snippet.workflow, scope).await;
     state.vm = Some(res.0);
     let res: FullValue = match res.1 {
         Ok(res) => res,
@@ -645,16 +647,17 @@ pub fn process_dummy_result(result: FullValue) {
 /// Processes the given result of an offline workflow execution.
 ///
 /// # Arguments
-/// - `result_dir`: The directory where temporary results are stored.
 /// - `result`: The value to process.
+/// - `scope`: Some [`ProfileScopeHandle`] to write profile timings in.
 ///
 /// # Returns
 /// Nothing, but does print any result to stdout.
 ///
 /// # Errors
 /// This function may error if we failed to get an up-to-date data index.
-pub fn process_offline_result(result: FullValue) -> Result<(), Error> {
+pub fn process_offline_result(result: FullValue, scope: ProfileScopeHandle) -> Result<(), Error> {
     // We only print
+    let guard = scope.time(format!("Processing of {result:?}"));
     if result != FullValue::Void {
         println!("\nWorkflow returned value {}", style(format!("'{result}'")).bold().cyan());
 
@@ -671,9 +674,12 @@ pub fn process_offline_result(result: FullValue) -> Result<(), Error> {
                 let datasets_dir = ensure_datasets_dir(false).map_err(|source| Error::DatasetsDirError { source })?;
 
                 // Fetch a new, local DataIndex to get up-to-date entries
-                let index: DataIndex = brane_tsk::local::get_data_index(datasets_dir).map_err(|source| Error::LocalDataIndexError { source })?;
+                let index: DataIndex = scope.time_func("Collecting local data index", || {
+                    brane_tsk::local::get_data_index(datasets_dir).map_err(|source| Error::LocalDataIndexError { source })
+                })?;
 
                 // Fetch the method of its availability
+                let _guard = scope.time(format!("Finding dataset \"{name}\" in local data index"));
                 let info: &DataInfo = index.get(&name).ok_or_else(|| Error::UnknownDataset { name: name.clone().into() })?;
                 let access: &AccessKind = info
                     .access
@@ -690,6 +696,7 @@ pub fn process_offline_result(result: FullValue) -> Result<(), Error> {
             _ => {},
         }
     }
+    drop(guard);
 
     // DOne
     Ok(())
@@ -782,7 +789,7 @@ pub async fn handle(
             // Run the thing
             remote_run(info, use_case, proxy_addr, options, source, source_code, profile).await
         } else {
-            local_run(options, docker_opts, source, source_code, keep_containers).await
+            local_run(options, docker_opts, source, source_code, keep_containers, profile).await
         }
     } else {
         dummy_run(options, source, source_code).await
@@ -823,6 +830,7 @@ async fn dummy_run(options: ParserOptions, what: impl AsRef<str>, source: impl A
 /// - `what`: A description of the source we're reading (e.g., the filename or stdin)
 /// - `source`: The source code to read.
 /// - `keep_containers`: Whether to keep containers after execution or not.
+/// - `profile`: Whether to print profile timings (true) or not (false).
 ///
 /// # Returns
 /// Nothing, but does print results and such to stdout. Might also produce new datasets.
@@ -832,6 +840,7 @@ async fn local_run(
     what: impl AsRef<str>,
     source: impl AsRef<str>,
     keep_containers: bool,
+    profile: bool,
 ) -> Result<(), Error> {
     let what: &str = what.as_ref();
     let source: &str = source.as_ref();
@@ -843,11 +852,16 @@ async fn local_run(
     let snippet = Snippet::from_source(&mut state.state, &mut state.source, &state.pindex, &state.dindex, None, &state.options, what, source)
         .map_err(Error::CompileError)?;
 
+    // Get a report
+    let report: Option<ProfileReport<Stdout>> = if profile { Some(ProfileReport::auto_reporting("brane_cli::local_run", stdout())) } else { None };
+
     // Next, we run the VM (one snippet only ayway)
-    let res: FullValue = run_offline_vm(&mut state, snippet).await?;
+    let res: FullValue =
+        run_offline_vm(&mut state, snippet, report.as_ref().map(|r| r.nest("run_offline_vm()")).unwrap_or_else(|| ProfileScopeHandle::dummy()))
+            .await?;
 
     // Then, we collect and process the result
-    process_offline_result(res)?;
+    process_offline_result(res, report.as_ref().map(|r| r.nest("process_offline_result()")).unwrap_or_else(|| ProfileScopeHandle::dummy()))?;
 
     // Done
     Ok(())

brane-cli/src/test.rs

@@ -23,6 +23,7 @@ use brane_tsk::input::prompt_for_input;
 use console::style;
 use specifications::data::DataIndex;
 use specifications::package::PackageInfo;
+use specifications::profiling::ProfileScopeHandle;
 use specifications::version::Version;
 
 use crate::errors::TestError;
@@ -178,7 +179,8 @@ pub async fn test_generic(
     )
     .map_err(|source| TestError::RunError { source: run::Error::CompileError(source) })?;
 
-    let result: FullValue = run_offline_vm(&mut state, snippet).await.map_err(|source| TestError::RunError { source })?;
+    let result: FullValue =
+        run_offline_vm(&mut state, snippet, ProfileScopeHandle::dummy()).await.map_err(|source| TestError::RunError { source })?;
 
     // Write the intermediate result if told to do so
     if let Some(file) = show_result {

brane-cli/src/vm.rs

@@ -68,7 +68,7 @@ impl VmPlugin for OfflinePlugin {
         _loc: Location,
         name: DataName,
         preprocess: PreprocessKind,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<AccessKind, Self::PreprocessError> {
         info!("Preprocessing data '{name}' for call at {pc} in an offline environment");
         debug!("Method of preprocessing: {preprocess:?}");
@@ -84,7 +84,7 @@ impl VmPlugin for OfflinePlugin {
         global: &Arc<RwLock<Self::GlobalState>>,
         _local: &Self::LocalState,
         info: TaskInfo<'_>,
-        prof: ProfileScopeHandle<'_>,
+        prof: ProfileScopeHandle,
     ) -> Result<Option<FullValue>, Self::ExecuteError> {
         let mut info = info;
         info!("Calling task '{}' in an offline environment", info.name);
@@ -112,7 +112,7 @@ impl VmPlugin for OfflinePlugin {
 
         // Resolve the input arguments, generating the folders we have to bind
         let binds: Vec<VolumeBind> = prof
-            .time_fut("argument preprocessing", docker::preprocess_args(&mut info.args, &info.input, info.result, None::<String>, results_dir))
+            .time_fut("Argument preprocessing", docker::preprocess_args(&mut info.args, &info.input, info.result, None::<String>, results_dir))
             .await?;
         let params: String = serde_json::to_string(&info.args).map_err(|source| ExecuteError::ArgsEncodeError { source })?;
 
@@ -143,7 +143,7 @@ impl VmPlugin for OfflinePlugin {
         // We can now execute the task on the local Docker daemon
         debug!("Executing task '{}'...", info.name);
         let (code, stdout, stderr) = prof
-            .time_fut("execution", docker::run_and_wait(docker_opts, einfo, keep_container))
+            .nest_fut("Execution", |scope| docker::run_and_wait(docker_opts, einfo, keep_container, scope))
             .await
             .map_err(|source| ExecuteError::DockerError { name: info.name.into(), image: Box::new(image.clone()), source })?;
         debug!("Container return code: {}", code);
@@ -171,7 +171,7 @@ impl VmPlugin for OfflinePlugin {
         _local: &Self::LocalState,
         text: &str,
         newline: bool,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<(), Self::StdoutError> {
         info!("Writing '{}' to stdout (newline: {}) in an offline environment...", text, if newline { "yes" } else { "no" });
 
@@ -192,7 +192,7 @@ impl VmPlugin for OfflinePlugin {
         _loc: &Location,
         name: &str,
         path: &Path,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<(), Self::CommitError> {
         info!("Publicizing intermediate result '{}' in an offline environment...", name);
         debug!("Physical file(s): {}", path.display());
@@ -210,7 +210,7 @@ impl VmPlugin for OfflinePlugin {
         name: &str,
         path: &Path,
         data_name: &str,
-        prof: ProfileScopeHandle<'_>,
+        prof: ProfileScopeHandle,
     ) -> Result<(), Self::CommitError> {
         info!("Committing intermediate result '{}' to '{}' in an offline environment...", name, data_name);
         debug!("Physical file(s): {}", path.display());
@@ -344,10 +344,11 @@ impl OfflineVm {
     ///
     /// # Arguments
     /// - `workflow`: The Workflow to execute.
+    /// - `scope`: Some [`ProfileScopeHandle`] to report any profile information in.
     ///
     /// # Returns
     /// The result of the workflow, if any. It also returns `self` again for subsequent runs.
-    pub async fn exec(self, workflow: Workflow) -> (Self, Result<FullValue, Error>) {
+    pub async fn exec(self, workflow: Workflow, scope: ProfileScopeHandle) -> (Self, Result<FullValue, Error>) {
         // Step 1: Plan
         let plan: Result<Workflow, Error> = {
             let planner: OfflinePlanner = {
@@ -372,7 +373,7 @@ impl OfflineVm {
         let this: Arc<RwLock<Self>> = Arc::new(RwLock::new(self));
 
         // Run the VM and get self back
-        let result: Result<FullValue, VmError> = Self::run::<OfflinePlugin>(this.clone(), plan, ProfileScopeHandle::dummy()).await;
+        let result: Result<FullValue, VmError> = Self::run::<OfflinePlugin>(this.clone(), plan, scope).await;
         let this: Self = match Arc::try_unwrap(this) {
             Ok(this) => this.into_inner().unwrap(),
             Err(_) => {

brane-ctl/src/download.rs

@@ -25,6 +25,7 @@ use enum_debug::EnumDebug as _;
 use log::{debug, info, warn};
 use specifications::arch::Arch;
 use specifications::container::Image;
+use specifications::profiling::ProfileScopeHandle;
 use specifications::version::Version;
 use tempfile::TempDir;
 
@@ -272,7 +273,7 @@ pub async fn services(
 
                 // Make sure the image is pulled
                 println!("Downloading auxillary image {}...", style(image).bold().green());
-                ensure_image(&docker, Image::new(name, None::<&str>, None::<&str>), ImageSource::Registry(image.into()))
+                ensure_image(&docker, Image::new(name, None::<&str>, None::<&str>), ImageSource::Registry(image.into()), ProfileScopeHandle::dummy())
                     .await
                     .map_err(|source| Error::PullError { name: name.into(), image: image.into(), source })?;
 

brane-ctl/src/lifetime.rs

@@ -37,6 +37,7 @@ use rand::Rng;
 use rand::distr::Alphanumeric;
 use serde::{Deserialize, Serialize};
 use specifications::container::Image;
+use specifications::profiling::ProfileScopeHandle;
 use specifications::version::Version;
 
 pub use crate::errors::LifetimeError as Error;
@@ -487,7 +488,7 @@ async fn load_images(docker: &Docker, images: HashMap<impl AsRef<str>, ImageSour
         };
 
         // Simply rely on ensure_image
-        ensure_image(docker, &image, &image_source).await.map_err(|source| Error::ImageLoadError {
+        ensure_image(docker, &image, &image_source, ProfileScopeHandle::dummy()).await.map_err(|source| Error::ImageLoadError {
             image: Box::new(image),
             image_source: Box::new(image_source),
             source,

brane-drv/src/planner.rs

@@ -41,7 +41,7 @@ impl InstancePlanner {
     ///
     /// # Returns
     /// The same workflow as given, but now with all tasks and data transfers planned.
-    pub async fn plan(plr: &Address, app_id: AppId, workflow: Workflow, prof: ProfileScopeHandle<'_>) -> Result<Workflow, PlanError> {
+    pub async fn plan(plr: &Address, app_id: AppId, workflow: Workflow, prof: ProfileScopeHandle) -> Result<Workflow, PlanError> {
         // Generate the ID
         let task_id: String = format!("{}", TaskId::generate());
 

brane-drv/src/vm.rs

@@ -81,7 +81,7 @@ impl VmPlugin for InstancePlugin {
         loc: Location,
         name: DataName,
         preprocess: PreprocessKind,
-        prof: ProfileScopeHandle<'_>,
+        prof: ProfileScopeHandle,
     ) -> Result<AccessKind, Self::PreprocessError> {
         info!("Preprocessing {} '{}' on '{}' in a distributed environment...", name.variant(), name.name(), loc);
         debug!("Preprocessing to be done: {:?}", preprocess);
@@ -159,7 +159,7 @@ impl VmPlugin for InstancePlugin {
         global: &Arc<RwLock<Self::GlobalState>>,
         _local: &Self::LocalState,
         info: TaskInfo<'_>,
-        prof: ProfileScopeHandle<'_>,
+        prof: ProfileScopeHandle,
     ) -> Result<Option<FullValue>, Self::ExecuteError> {
         info!("Executing task '{}' at '{}' in a distributed environment...", info.name, info.location);
         debug!("Package: '{}' v{}", info.package_name, info.package_version);
@@ -376,7 +376,7 @@ impl VmPlugin for InstancePlugin {
         _local: &Self::LocalState,
         text: &str,
         newline: bool,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<(), Self::StdoutError> {
         info!("Writing '{}' to stdout in a distributed environment...", text);
         debug!("Newline: {}", if newline { "yes" } else { "no" });
@@ -409,7 +409,7 @@ impl VmPlugin for InstancePlugin {
         loc: &Location,
         name: &str,
         path: &Path,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<(), Self::CommitError> {
         info!("Publicizing intermediate result '{}' living at '{}' in a distributed environment...", name, loc);
         debug!("File: '{}'", path.display());
@@ -426,7 +426,7 @@ impl VmPlugin for InstancePlugin {
         name: &str,
         path: &Path,
         data_name: &str,
-        prof: ProfileScopeHandle<'_>,
+        prof: ProfileScopeHandle,
     ) -> Result<(), Self::CommitError> {
         info!("Committing intermediate result '{}' living at '{}' as '{}' in a distributed environment...", name, loc, data_name);
         debug!("File: '{}'", path.display());
@@ -519,7 +519,7 @@ impl InstanceVm {
         tx: Sender<Result<driving_grpc::ExecuteReply, Status>>,
         id: AppId,
         workflow: Workflow,
-        prof: ProfileScopeHandle<'_>,
+        prof: ProfileScopeHandle,
     ) -> (Self, Result<FullValue, Error>) {
         // Step 0: Load files
         let plr_addr: Address = {

brane-exe/src/dummy.rs

@@ -143,7 +143,7 @@ impl VmPlugin for DummyPlugin {
         _loc: Location,
         name: DataName,
         _preprocess: specifications::data::PreprocessKind,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<AccessKind, Self::PreprocessError> {
         info!("Processing dummy `DummyVm::preprocess()` call for intermediate result '{name}' in {pc}");
 
@@ -155,7 +155,7 @@ impl VmPlugin for DummyPlugin {
         global: &Arc<RwLock<Self::GlobalState>>,
         _local: &Self::LocalState,
         info: TaskInfo<'_>,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<Option<FullValue>, Self::ExecuteError> {
         info!(
             "Processing dummy call to '{}'@'{}' with {} in {}[{}]...",
@@ -179,7 +179,7 @@ impl VmPlugin for DummyPlugin {
         _local: &Self::LocalState,
         text: &str,
         newline: bool,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<(), Self::StdoutError> {
         info!("Processing dummy stdout write (newline: {})...", if newline { "yes" } else { "no" },);
 
@@ -198,7 +198,7 @@ impl VmPlugin for DummyPlugin {
         _loc: &Location,
         name: &str,
         path: &Path,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<(), Self::CommitError> {
         info!("Processing dummy publicize for result '{}' @ '{:?}'...", name, path.display(),);
 
@@ -213,7 +213,7 @@ impl VmPlugin for DummyPlugin {
         name: &str,
         path: &Path,
         data_name: &str,
-        _prof: ProfileScopeHandle<'_>,
+        _prof: ProfileScopeHandle,
     ) -> Result<(), Self::CommitError> {
         info!("Processing dummy commit for result '{}' @ '{:?}' to '{}'...", name, path.display(), data_name,);