Feature/execution time in traces

nemo-wasm/src/models/mod.rs

@@ -20,6 +20,8 @@ pub use self::table_query_base_table_entries::TableQueryBaseTableEntries;
 pub mod table_query_base_table_entries_pagination;
 pub use self::table_query_base_table_entries_pagination::TableQueryBaseTableEntriesPagination;
 pub mod table_response_base;
+pub mod table_response_base_meta_information;
+pub use self::table_response_base_meta_information::TableResponseBaseMetaInformation;
 pub mod table_response_base_table_entries;
 pub use self::table_response_base_table_entries::TableResponseBaseTableEntries;
 pub mod table_response_base_table_entries_pagination;

nemo-wasm/src/models/table_entries_for_tree_nodes_response_inner.rs

@@ -10,7 +10,7 @@
 
 use serde::{Deserialize, Serialize};
 
-use super::{Rule, TableResponseBaseTableEntries};
+use super::{Rule, TableResponseBaseMetaInformation, TableResponseBaseTableEntries};
 
 #[derive(Clone, Default, Debug, PartialEq, Serialize, Deserialize)]
 pub struct TableEntriesForTreeNodesResponseInner {
@@ -20,6 +20,8 @@ pub struct TableEntriesForTreeNodesResponseInner {
     pub predicate: String,
     #[serde(rename = "tableEntries")]
     pub table_entries: Box<TableResponseBaseTableEntries>,
+    #[serde(rename = "metaInformation")]
+    pub meta_information: Box<TableResponseBaseMetaInformation>,
     #[serde(rename = "possibleRulesAbove")]
     pub possible_rules_above: Vec<Rule>,
     #[serde(rename = "possibleRulesBelow")]
@@ -53,6 +55,7 @@ impl From<TableEntriesForTreeNodesResponseInner>
                 .map(Into::into)
                 .collect(),
             address: value.address_in_tree.unwrap_or_default(),
+            meta_information: (*value.meta_information).into(),
         }
     }
 }
@@ -82,6 +85,7 @@ impl From<nemo::execution::tracing::node_query::TableEntriesForTreeNodesResponse
                 .into_iter()
                 .map(Into::into)
                 .collect(),
+            meta_information: Box::new(value.meta_information.into()),
         }
     }
 }

nemo-wasm/src/models/table_response_base.rs

@@ -10,7 +10,7 @@
 
 use serde::{Deserialize, Serialize};
 
-use super::{Rule, TableResponseBaseTableEntries};
+use super::{Rule, TableResponseBaseMetaInformation, TableResponseBaseTableEntries};
 
 #[derive(Clone, Default, Debug, PartialEq, Serialize, Deserialize)]
 #[allow(dead_code)]
@@ -19,6 +19,8 @@ pub struct TableResponseBase {
     pub predicate: String,
     #[serde(rename = "tableEntries")]
     pub table_entries: Box<TableResponseBaseTableEntries>,
+    #[serde(rename = "metaInformation")]
+    pub meta_information: Box<TableResponseBaseMetaInformation>,
     #[serde(rename = "possibleRulesAbove")]
     pub possible_rules_above: Vec<Rule>,
     #[serde(rename = "possibleRulesBelow")]

nemo-wasm/src/models/table_response_base_meta_information.rs

@@ -0,0 +1,37 @@
+/*
+ * Generated by cue.
+ *
+ * No description provided (generated by Openapi Generator https://github.com/openapitools/openapi-generator)
+ *
+ * The version of the OpenAPI document: v0.1.0
+ *
+ * Generated by: https://openapi-generator.tech
+ */
+
+use serde::{Deserialize, Serialize};
+
+#[derive(Clone, Default, Debug, PartialEq, Serialize, Deserialize)]
+pub struct TableResponseBaseMetaInformation {
+    #[serde(rename = "executionTime")]
+    pub execution_time: usize,
+}
+
+impl From<TableResponseBaseMetaInformation>
+    for nemo::execution::tracing::shared::ResponseMetaInformation
+{
+    fn from(value: TableResponseBaseMetaInformation) -> Self {
+        Self {
+            execution_time: value.execution_time,
+        }
+    }
+}
+
+impl From<nemo::execution::tracing::shared::ResponseMetaInformation>
+    for TableResponseBaseMetaInformation
+{
+    fn from(value: nemo::execution::tracing::shared::ResponseMetaInformation) -> Self {
+        Self {
+            execution_time: value.execution_time,
+        }
+    }
+}

nemo-wasm/src/models/tree_for_table_response.rs

@@ -10,7 +10,10 @@
 
 use serde::{Deserialize, Serialize};
 
-use super::{Rule, TableResponseBaseTableEntries, TreeForTableResponseChildInformation};
+use super::{
+    Rule, TableResponseBaseMetaInformation, TableResponseBaseTableEntries,
+    TreeForTableResponseChildInformation,
+};
 
 #[derive(Clone, Default, Debug, PartialEq, Serialize, Deserialize)]
 pub struct TreeForTableResponse {
@@ -20,6 +23,8 @@ pub struct TreeForTableResponse {
     pub predicate: String,
     #[serde(rename = "tableEntries")]
     pub table_entries: Box<TableResponseBaseTableEntries>,
+    #[serde(rename = "metaInformation")]
+    pub meta_information: Box<TableResponseBaseMetaInformation>,
     #[serde(rename = "possibleRulesAbove")]
     pub possible_rules_above: Vec<Rule>,
     #[serde(rename = "possibleRulesBelow")]
@@ -51,6 +56,7 @@ impl From<TreeForTableResponse> for nemo::execution::tracing::tree_query::TreeFo
                 .map(Into::into)
                 .collect(),
             next: value.child_information.map(|info| (*info).into()),
+            meta_information: (*value.meta_information).into(),
         }
     }
 }
@@ -76,6 +82,7 @@ impl From<nemo::execution::tracing::tree_query::TreeForTableResponse> for TreeFo
                 .into_iter()
                 .map(Into::into)
                 .collect(),
+            meta_information: Box::new(value.meta_information.into()),
         }
     }
 }

nemo/src/execution/execution_engine.rs

@@ -75,6 +75,8 @@ pub struct ExecutionEngine<RuleSelectionStrategy> {
     rule_infos: Vec<RuleInfo>,
     /// For each step the rule index of the applied rule
     rule_history: Vec<usize>,
+    /// For each step, the execution time in milliseconds
+    step_times_ms: Vec<u128>,
     /// Current step
     current_step: usize,
 }
@@ -130,6 +132,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
             predicate_last_union: HashMap::new(),
             rule_infos,
             rule_history: vec![usize::MAX], // Placeholder, Step counting starts at 1
+            step_times_ms: vec![0],         // Placeholder, Step counting starts at 1
             current_step: 1,
         })
     }
@@ -225,9 +228,13 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
         current_info.step_last_applied = self.current_step;
 
         let rule_duration = TimedCode::instance().sub(&timing_string).stop();
+
+        self.step_times_ms.push(rule_duration.as_millis());
+
         log::info!("Rule duration: {} ms", rule_duration.as_millis());
 
         self.current_step += 1;
+
         Ok(updated_predicates)
     }
 
@@ -377,4 +384,12 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
     pub fn memory_usage(&self) -> MemoryUsage {
         self.table_manager.memory_usage()
     }
+
+    /// For a given iterator over rule execution steps
+    /// returns the sum of execution time for those steps.
+    pub fn steps_time_ms<Iter: Iterator<Item = usize>>(&self, steps: Iter) -> u128 {
+        steps
+            .map(|step| self.step_times_ms.get(step).cloned().unwrap_or_default())
+            .sum()
+    }
 }

nemo/src/execution/execution_engine/tracing/node_query.rs

@@ -30,7 +30,10 @@ use crate::{
                 TableEntriesForTreeNodesResponse, TableEntriesForTreeNodesResponseElement,
                 TreeAddress,
             },
-            shared::{PaginationResponse, Rule as TraceRule, TableEntryQuery, TableEntryResponse},
+            shared::{
+                PaginationResponse, ResponseMetaInformation, Rule as TraceRule, TableEntryQuery,
+                TableEntryResponse,
+            },
         },
     },
     rule_model::components::{atom::Atom, tag::Tag},
@@ -481,20 +484,29 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
             element.pagination.more = element.pagination.start + rows.len()
                 < self.table_manager.database().count_rows_in_memory(table_id);
 
+            let mut steps = HashSet::<usize>::default();
+
             for row in rows {
-                let entry_id = self
+                let (entry_id, step) = self
                     .table_manager
                     .table_row_id(&Tag::new(element.predicate.clone()), &row)
                     .await
                     .expect("if a row appears in an answer it must have an id");
 
+                steps.insert(step);
+
                 let table_response = TableEntryResponse {
                     entry_id,
                     terms: row,
                 };
 
                 element.entries.push(table_response);
             }
+
+            element.meta_information.execution_time = self
+                .steps_time_ms(steps.into_iter())
+                .try_into()
+                .unwrap_or_default();
         }
 
         Some(response)
@@ -511,7 +523,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
         predicate: &Tag,
         program: &NormalizedProgram,
     ) -> Result<(), Error> {
-        // Collect all (syntactly) possible rules
+        // Collect all (syntactically) possible rules
         // that could be triggered by or could trigger
         // the predicate assigned to the current node
 
@@ -539,6 +551,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
 
         let element = TableEntriesForTreeNodesResponseElement {
             predicate: predicate.to_string(),
+            meta_information: ResponseMetaInformation::default(),
             entries: Vec::with_capacity(
                 node.pagination
                     .map(|pagination| pagination.count)
@@ -601,7 +614,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
                 let mut entries = Vec::default();
 
                 for row in rows {
-                    let entry_id = self
+                    let (entry_id, _step) = self
                         .table_manager
                         .table_row_id(&negative_atom.predicate(), &row)
                         .await
@@ -625,6 +638,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
                     possible_rules_above: Vec::default(),
                     possible_rules_below: Vec::default(),
                     address: next_address,
+                    meta_information: ResponseMetaInformation::default(),
                 };
 
                 elements.push(negation_element);

nemo/src/execution/execution_engine/tracing/node_query/manager.rs

@@ -67,7 +67,7 @@ pub(super) struct TraceNodeManager {
     /// For each "valid" table, the variable assignment
     /// used to compute it
     assignment: HashMap<TreeAddress, StepToId>,
-    /// Consolidated version of `assignemnt`
+    /// Consolidated version of `assignment`
     assignment_final: HashMap<TreeAddress, PermanentTableId>,
 
     /// For each node in the query,

nemo/src/execution/execution_engine/tracing/tree_query.rs

@@ -18,7 +18,10 @@ use crate::{
         selection_strategy::strategy::RuleSelectionStrategy,
         tracing::{
             error::TracingError,
-            shared::{PaginationResponse, Rule as TraceRule, TableEntryQuery, TableEntryResponse},
+            shared::{
+                PaginationResponse, ResponseMetaInformation, Rule as TraceRule, TableEntryQuery,
+                TableEntryResponse,
+            },
             tree_query::{TreeForTableQuery, TreeForTableResponse, TreeForTableResponseSuccessor},
         },
     },
@@ -126,7 +129,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
 
                 let mut entries = Vec::default();
                 for row in rows {
-                    let entry_id = self
+                    let (entry_id, _step) = self
                         .table_manager
                         .table_row_id(&negative_atom.predicate(), &row)
                         .await
@@ -142,6 +145,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
 
                 let negative_response = TreeForTableResponse {
                     predicate: negative_atom.predicate().to_string(),
+                    meta_information: ResponseMetaInformation::default(),
                     entries,
                     pagination: PaginationResponse {
                         start: 0,
@@ -196,13 +200,13 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
         // This functions assumes that all facts have the same predicate.
         let predicate = facts.first().map(|fact| fact.predicate())?;
 
-        // Prepare the result, which contains some information independant of tracing results below
+        // Prepare the result, which contains some information independent of tracing results below
         let mut entries = Vec::default();
 
         for fact in facts.iter() {
             let terms = fact.terms().map(|term| term.value()).collect::<Vec<_>>();
 
-            let entry_id = self
+            let (entry_id, _step) = self
                 .table_manager
                 .table_row_id(&fact.predicate(), &terms)
                 .await?;
@@ -230,6 +234,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
 
         let mut result = TreeForTableResponse {
             predicate: predicate.to_string(),
+            meta_information: ResponseMetaInformation::default(),
             entries,
             pagination: PaginationResponse {
                 start: 0,
@@ -265,6 +270,12 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
         // Get the rule that has been applied in each step
         // We can only proceed if every fact has been derived by the same rule
         let rule_index = self.rule_history[steps[0]];
+
+        result.meta_information.execution_time = self
+            .steps_time_ms(steps.iter().cloned())
+            .try_into()
+            .unwrap_or_default();
+
         if steps
             .iter()
             .any(|&step| self.rule_history[step] != rule_index)
@@ -486,6 +497,7 @@ impl<Strategy: RuleSelectionStrategy> ExecutionEngine<Strategy> {
 
             Ok(TreeForTableResponse {
                 predicate: query.predicate,
+                meta_information: ResponseMetaInformation::default(),
                 entries: vec![],
                 pagination: PaginationResponse {
                     start: query

nemo/src/execution/tracing/node_query.rs

@@ -4,6 +4,8 @@ use std::hash::Hash;
 
 use serde::{Deserialize, Serialize};
 
+use crate::execution::tracing::shared::ResponseMetaInformation;
+
 use super::shared::{
     PaginationQuery, PaginationResponse, Rule, RuleId, TableEntryQuery, TableEntryResponse,
 };
@@ -104,6 +106,9 @@ pub struct TableEntriesForTreeNodesResponseElement {
     /// Predicate of the this table
     pub predicate: String,
 
+    /// Meta information about the rule execution
+    pub meta_information: ResponseMetaInformation,
+
     /// Entries contained in this table
     pub entries: Vec<TableEntryResponse>,
     /// [PaginationResponse] specifying whether the response is incomplete

nemo/src/execution/tracing/shared.rs

@@ -184,7 +184,7 @@ mod any_datavalue_serde {
     }
 }
 
-/// Response containig the entries of a table node
+/// Response containing the entries of a table node
 #[derive(Debug, Serialize, Deserialize)]
 pub struct TableEntryResponse {
     /// Identifier of the table entry
@@ -200,7 +200,7 @@ pub struct TableEntryResponse {
 impl TableEntryResponse {
     /// Create a new [TableEntryResponse] with terms given as a list of [String]s.
     ///
-    /// Retrurns `None` if any term cannot be parsed.
+    /// Returns `None` if any term cannot be parsed.
     pub fn new_from_string(entry_id: TableEntryId, terms: &[String]) -> Option<Self> {
         let parsed_terms: Result<Vec<AnyDataValue>, _> = terms
             .iter()
@@ -217,3 +217,10 @@ impl TableEntryResponse {
         self.terms.iter().map(|term| term.to_string()).collect()
     }
 }
+
+/// Contains useful meta information about a rule application
+#[derive(Debug, Default, Copy, Clone, Serialize, Deserialize)]
+pub struct ResponseMetaInformation {
+    /// Execution time in milliseconds
+    pub execution_time: usize,
+}