From d8c63411ca80ca8f7f98b094fa1bac710277c4af Mon Sep 17 00:00:00 2001 From: monsterkrampe Date: Sat, 15 Nov 2025 01:54:10 +0100 Subject: [PATCH 1/3] Prepare DTOs for carrying execution time --- nemo-wasm/src/models/mod.rs | 4 ++++ ...ble_entries_for_tree_nodes_response_inner.rs | 4 +++- nemo-wasm/src/models/table_response_base.rs | 4 +++- .../table_response_base_meta_information.rs | 17 +++++++++++++++++ nemo-wasm/src/models/tree_for_table_response.rs | 7 ++++++- 5 files changed, 33 insertions(+), 3 deletions(-) create mode 100644 nemo-wasm/src/models/table_response_base_meta_information.rs diff --git a/nemo-wasm/src/models/mod.rs b/nemo-wasm/src/models/mod.rs index 5a82a9bdc..44fb6914e 100644 --- a/nemo-wasm/src/models/mod.rs +++ b/nemo-wasm/src/models/mod.rs @@ -15,11 +15,15 @@ pub use self::table_entry_query::TableEntryQuery; pub mod table_entry_response; pub use self::table_entry_response::TableEntryResponse; pub mod table_query_base; +pub use self::table_query_base::TableQueryBase; pub mod table_query_base_table_entries; 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 use self::table_response_base::TableResponseBase; +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; diff --git a/nemo-wasm/src/models/table_entries_for_tree_nodes_response_inner.rs b/nemo-wasm/src/models/table_entries_for_tree_nodes_response_inner.rs index 5b416b5e6..0c5b3e5cf 100644 --- a/nemo-wasm/src/models/table_entries_for_tree_nodes_response_inner.rs +++ b/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, + #[serde(rename = "metaInformation")] + pub meta_information: Box, #[serde(rename = "possibleRulesAbove")] pub possible_rules_above: Vec, #[serde(rename = "possibleRulesBelow")] diff --git a/nemo-wasm/src/models/table_response_base.rs b/nemo-wasm/src/models/table_response_base.rs index 3a1be524a..70e27f24f 100644 --- a/nemo-wasm/src/models/table_response_base.rs +++ b/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, + #[serde(rename = "metaInformation")] + pub meta_information: Box, #[serde(rename = "possibleRulesAbove")] pub possible_rules_above: Vec, #[serde(rename = "possibleRulesBelow")] diff --git a/nemo-wasm/src/models/table_response_base_meta_information.rs b/nemo-wasm/src/models/table_response_base_meta_information.rs new file mode 100644 index 000000000..a252977d3 --- /dev/null +++ b/nemo-wasm/src/models/table_response_base_meta_information.rs @@ -0,0 +1,17 @@ +/* + * 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, +} diff --git a/nemo-wasm/src/models/tree_for_table_response.rs b/nemo-wasm/src/models/tree_for_table_response.rs index 40dcb8550..32e7ecabc 100644 --- a/nemo-wasm/src/models/tree_for_table_response.rs +++ b/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, + #[serde(rename = "metaInformation")] + pub meta_information: Box, #[serde(rename = "possibleRulesAbove")] pub possible_rules_above: Vec, #[serde(rename = "possibleRulesBelow")] From 4548e90f2944d6d4010f6cba2f57eb3fac96c3f7 Mon Sep 17 00:00:00 2001 From: Alex Ivliev Date: Mon, 24 Nov 2025 13:27:25 +0100 Subject: [PATCH 2/3] Add execution time to advanced tracing output --- ...e_entries_for_tree_nodes_response_inner.rs | 2 ++ .../table_response_base_meta_information.rs | 20 +++++++++++++++++ .../src/models/tree_for_table_response.rs | 2 ++ nemo/src/execution/execution_engine.rs | 15 +++++++++++++ .../execution_engine/tracing/node_query.rs | 22 +++++++++++++++---- .../tracing/node_query/manager.rs | 2 +- .../execution_engine/tracing/tree_query.rs | 20 +++++++++++++---- nemo/src/execution/tracing/node_query.rs | 5 +++++ nemo/src/execution/tracing/shared.rs | 11 ++++++++-- nemo/src/execution/tracing/tree_query.rs | 5 +++++ nemo/src/table_manager.rs | 12 ++++++---- 11 files changed, 101 insertions(+), 15 deletions(-) diff --git a/nemo-wasm/src/models/table_entries_for_tree_nodes_response_inner.rs b/nemo-wasm/src/models/table_entries_for_tree_nodes_response_inner.rs index 0c5b3e5cf..dce6234d6 100644 --- a/nemo-wasm/src/models/table_entries_for_tree_nodes_response_inner.rs +++ b/nemo-wasm/src/models/table_entries_for_tree_nodes_response_inner.rs @@ -55,6 +55,7 @@ impl From .map(Into::into) .collect(), address: value.address_in_tree.unwrap_or_default(), + meta_information: (*value.meta_information).into(), } } } @@ -84,6 +85,7 @@ impl From + for nemo::execution::tracing::shared::ResponseMetaInformation +{ + fn from(value: TableResponseBaseMetaInformation) -> Self { + Self { + execution_time: value.execution_time, + } + } +} + +impl From + for TableResponseBaseMetaInformation +{ + fn from(value: nemo::execution::tracing::shared::ResponseMetaInformation) -> Self { + Self { + execution_time: value.execution_time, + } + } +} diff --git a/nemo-wasm/src/models/tree_for_table_response.rs b/nemo-wasm/src/models/tree_for_table_response.rs index 32e7ecabc..152e08e48 100644 --- a/nemo-wasm/src/models/tree_for_table_response.rs +++ b/nemo-wasm/src/models/tree_for_table_response.rs @@ -56,6 +56,7 @@ impl From 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(), } } } @@ -81,6 +82,7 @@ impl From for TreeFo .into_iter() .map(Into::into) .collect(), + meta_information: Box::new(value.meta_information.into()), } } } diff --git a/nemo/src/execution/execution_engine.rs b/nemo/src/execution/execution_engine.rs index 0280c2f6f..c4c923027 100644 --- a/nemo/src/execution/execution_engine.rs +++ b/nemo/src/execution/execution_engine.rs @@ -75,6 +75,8 @@ pub struct ExecutionEngine { rule_infos: Vec, /// For each step the rule index of the applied rule rule_history: Vec, + /// For each step, the execution time in milliseconds + step_times_ms: Vec, /// Current step current_step: usize, } @@ -130,6 +132,7 @@ impl ExecutionEngine { 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 ExecutionEngine { 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 ExecutionEngine { 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>(&self, steps: Iter) -> u128 { + steps + .map(|step| self.step_times_ms.get(step).cloned().unwrap_or_default()) + .sum() + } } diff --git a/nemo/src/execution/execution_engine/tracing/node_query.rs b/nemo/src/execution/execution_engine/tracing/node_query.rs index 3eeecd153..80afebbde 100644 --- a/nemo/src/execution/execution_engine/tracing/node_query.rs +++ b/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,13 +484,17 @@ impl ExecutionEngine { element.pagination.more = element.pagination.start + rows.len() < self.table_manager.database().count_rows_in_memory(table_id); + let mut steps = HashSet::::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, @@ -495,6 +502,11 @@ impl ExecutionEngine { 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 ExecutionEngine { 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 ExecutionEngine { 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 ExecutionEngine { 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 ExecutionEngine { possible_rules_above: Vec::default(), possible_rules_below: Vec::default(), address: next_address, + meta_information: ResponseMetaInformation::default(), }; elements.push(negation_element); diff --git a/nemo/src/execution/execution_engine/tracing/node_query/manager.rs b/nemo/src/execution/execution_engine/tracing/node_query/manager.rs index 876a18c64..ea01e6968 100644 --- a/nemo/src/execution/execution_engine/tracing/node_query/manager.rs +++ b/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, - /// Consolidated version of `assignemnt` + /// Consolidated version of `assignment` assignment_final: HashMap, /// For each node in the query, diff --git a/nemo/src/execution/execution_engine/tracing/tree_query.rs b/nemo/src/execution/execution_engine/tracing/tree_query.rs index 6d13075a2..3b5958f30 100644 --- a/nemo/src/execution/execution_engine/tracing/tree_query.rs +++ b/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 ExecutionEngine { 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 ExecutionEngine { let negative_response = TreeForTableResponse { predicate: negative_atom.predicate().to_string(), + meta_information: ResponseMetaInformation::default(), entries, pagination: PaginationResponse { start: 0, @@ -196,13 +200,13 @@ impl ExecutionEngine { // 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::>(); - let entry_id = self + let (entry_id, _step) = self .table_manager .table_row_id(&fact.predicate(), &terms) .await?; @@ -230,6 +234,7 @@ impl ExecutionEngine { let mut result = TreeForTableResponse { predicate: predicate.to_string(), + meta_information: ResponseMetaInformation::default(), entries, pagination: PaginationResponse { start: 0, @@ -265,6 +270,12 @@ impl ExecutionEngine { // 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 ExecutionEngine { Ok(TreeForTableResponse { predicate: query.predicate, + meta_information: ResponseMetaInformation::default(), entries: vec![], pagination: PaginationResponse { start: query diff --git a/nemo/src/execution/tracing/node_query.rs b/nemo/src/execution/tracing/node_query.rs index a09597a53..b4df6534a 100644 --- a/nemo/src/execution/tracing/node_query.rs +++ b/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, /// [PaginationResponse] specifying whether the response is incomplete diff --git a/nemo/src/execution/tracing/shared.rs b/nemo/src/execution/tracing/shared.rs index 3660e5995..de2f132c1 100644 --- a/nemo/src/execution/tracing/shared.rs +++ b/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 { let parsed_terms: Result, _> = 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, +} diff --git a/nemo/src/execution/tracing/tree_query.rs b/nemo/src/execution/tracing/tree_query.rs index 8bdee2993..57742f18b 100644 --- a/nemo/src/execution/tracing/tree_query.rs +++ b/nemo/src/execution/tracing/tree_query.rs @@ -2,6 +2,8 @@ use serde::{Deserialize, Serialize}; +use crate::execution::tracing::shared::ResponseMetaInformation; + use super::shared::{ PaginationQuery, PaginationResponse, Rule, TableEntryQuery, TableEntryResponse, }; @@ -42,6 +44,9 @@ pub struct TreeForTableResponse { /// Predicate of this table pub predicate: String, + /// Meta information about the rule execution + pub meta_information: ResponseMetaInformation, + /// Entries contained in this table pub entries: Vec, /// [PaginationResponse] specifying whether the response is incomplete diff --git a/nemo/src/table_manager.rs b/nemo/src/table_manager.rs index 11e936ea4..7693f0654 100644 --- a/nemo/src/table_manager.rs +++ b/nemo/src/table_manager.rs @@ -721,16 +721,20 @@ impl TableManager { None } - /// Return an id for a given row and predicate, if it exists. + /// Return an id for a given row and predicate and the step it was derived in, if it exists. /// /// Returns `None` if there is no such row for this predicate. - pub async fn table_row_id(&mut self, predicate: &Tag, row: &[AnyDataValue]) -> Option { + pub async fn table_row_id( + &mut self, + predicate: &Tag, + row: &[AnyDataValue], + ) -> Option<(usize, usize)> { let handler = self.predicate_subtables.get(predicate)?; let mut skipped: usize = 0; - for (_, id) in &handler.single { + for (step, id) in &handler.single { if let Some(row_index) = self.database.table_row_position(*id, row).await { - return Some(skipped + row_index); + return Some((skipped + row_index, *step)); } skipped += self.database.count_rows_in_memory(*id); From da3101f6c51331c8e0882e5c2653414e1827c0ce Mon Sep 17 00:00:00 2001 From: Alex Ivliev Date: Mon, 24 Nov 2025 13:42:08 +0100 Subject: [PATCH 3/3] Remove unneeded use statements --- nemo-wasm/src/models/mod.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/nemo-wasm/src/models/mod.rs b/nemo-wasm/src/models/mod.rs index 44fb6914e..7527e6699 100644 --- a/nemo-wasm/src/models/mod.rs +++ b/nemo-wasm/src/models/mod.rs @@ -15,13 +15,11 @@ pub use self::table_entry_query::TableEntryQuery; pub mod table_entry_response; pub use self::table_entry_response::TableEntryResponse; pub mod table_query_base; -pub use self::table_query_base::TableQueryBase; pub mod table_query_base_table_entries; 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 use self::table_response_base::TableResponseBase; pub mod table_response_base_meta_information; pub use self::table_response_base_meta_information::TableResponseBaseMetaInformation; pub mod table_response_base_table_entries;