diff --git a/nucliadb_node/src/grpc/middleware/metrics.rs b/nucliadb_node/src/grpc/middleware/metrics.rs index 38920c1f4f..794627f503 100644 --- a/nucliadb_node/src/grpc/middleware/metrics.rs +++ b/nucliadb_node/src/grpc/middleware/metrics.rs @@ -18,13 +18,12 @@ // along with this program. If not, see . use std::task::{Context, Poll}; -use std::time::SystemTime; +use std::time::Instant; use futures::future::BoxFuture; use hyper::Body; use nucliadb_core::metrics; use nucliadb_core::metrics::grpc_ops::GrpcOpKey; -use nucliadb_core::tracing::warn; use tonic::body::BoxBody; use tower::{Layer, Service}; @@ -71,7 +70,7 @@ where let mut inner = std::mem::replace(&mut self.inner, clone); Box::pin(async move { - let start = SystemTime::now(); + let start = Instant::now(); let meter = metrics::get_metrics(); let grpc_method = req.uri().path().to_string(); @@ -86,16 +85,13 @@ where None => call.await, }; - if let Ok(grpc_call_duration) = start.elapsed() { - meter.record_grpc_op( - GrpcOpKey { - method: grpc_method, - }, - grpc_call_duration.as_secs_f64(), - ); - } else { - warn!("Failed to observe gRPC call duration for: {grpc_method}"); - } + let grpc_call_duration = start.elapsed(); + meter.record_grpc_op( + GrpcOpKey { + method: grpc_method, + }, + grpc_call_duration.as_secs_f64(), + ); response }) diff --git a/nucliadb_node/src/replication/replicator.rs b/nucliadb_node/src/replication/replicator.rs index d6af5e7748..1823e46e50 100644 --- a/nucliadb_node/src/replication/replicator.rs +++ b/nucliadb_node/src/replication/replicator.rs @@ -265,7 +265,7 @@ pub async fn connect_to_primary_and_replicate( let no_shards_to_sync = replication_state.shard_states.is_empty(); let no_shards_to_remove = replication_state.shards_to_remove.is_empty(); - let start = std::time::SystemTime::now(); + let start = std::time::Instant::now(); for shard_state in replication_state.shard_states { if shutdown_notified.load(std::sync::atomic::Ordering::Relaxed) { return Ok(()); @@ -349,10 +349,7 @@ pub async fn connect_to_primary_and_replicate( // // 1. If we're healthy, we'll sleep for a while and check again. // 2. If backed up replicating, we'll try replicating again immediately and check again. - let elapsed = start - .elapsed() - .map(|elapsed| elapsed.as_secs_f64()) - .expect("Error getting elapsed time"); + let elapsed = start.elapsed().as_secs_f64(); if elapsed < settings.replication_healthy_delay() as f64 { // only update healthy marker if we're up-to-date in the configured healthy time repl_health_mng.update_healthy(); diff --git a/nucliadb_paragraphs/src/reader.rs b/nucliadb_paragraphs/src/reader.rs index 2da00440cb..e0f8658e09 100644 --- a/nucliadb_paragraphs/src/reader.rs +++ b/nucliadb_paragraphs/src/reader.rs @@ -19,7 +19,7 @@ // use std::fmt::Debug; -use std::time::SystemTime; +use std::time::Instant; use nucliadb_core::prelude::*; use nucliadb_core::protos::order_by::{OrderField, OrderType}; @@ -70,46 +70,42 @@ impl ParagraphReader for ParagraphReaderService { #[measure(actor = "paragraphs", metric = "suggest")] #[tracing::instrument(skip_all)] fn suggest(&self, request: &SuggestRequest) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&request.shard); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating query: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating query: starts at {v} ms"); + let parser = QueryParser::for_index(&self.index, vec![self.schema.text]); let text = self.adapt_text(&parser, &request.body); let (original, termc, fuzzied) = suggest_query(&parser, &text, request, &self.schema, FUZZY_DISTANCE); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating query: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating query: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: starts at {v} ms"); - } let searcher = self.reader.searcher(); let topdocs = TopDocs::with_limit(NUMBER_OF_RESULTS_SUGGEST); let mut results = searcher.search(&original, &topdocs)?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: ends at {v} ms"); if results.is_empty() { - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Trying fuzzy: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Trying fuzzy: starts at {v} ms"); + let topdocs = TopDocs::with_limit(NUMBER_OF_RESULTS_SUGGEST); match searcher.search(&fuzzied, &topdocs) { Ok(mut fuzzied) => results.append(&mut fuzzied), Err(err) => error!("{err:?} during suggest"), } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Trying fuzzy: ends at {v} ms"); - } - } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at: {v} ms"); + let v = time.elapsed().as_millis(); + debug!("{id:?} - Trying fuzzy: ends at {v} ms"); } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at: {v} ms"); Ok(ParagraphSearchResponse::from(SearchBm25Response { total: results.len(), @@ -146,12 +142,12 @@ impl ReaderChild for ParagraphReaderService { #[measure(actor = "paragraphs", metric = "search")] #[tracing::instrument(skip_all)] fn search(&self, request: &Self::Request) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&request.id); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating query: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating query: starts at {v} ms"); + let parser = QueryParser::for_index(&self.index, vec![self.schema.text]); let results = request.result_per_page as usize; let offset = results * request.page_number as usize; @@ -164,13 +160,12 @@ impl ReaderChild for ParagraphReaderService { .cloned() .collect(); let text = self.adapt_text(&parser, &request.body); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating query: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating query: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: starts at {v} ms"); - } let advanced = request .advanced_query .as_ref() @@ -194,37 +189,34 @@ impl ReaderChild for ParagraphReaderService { only_faceted: request.only_faceted, }; let mut response = searcher.do_search(termc.clone(), original, self)?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: ends at {v} ms"); if response.results.is_empty() && request.result_per_page > 0 { - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Applying fuzzy: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Applying fuzzy: starts at {v} ms"); + let fuzzied = searcher.do_search(termc, fuzzied, self)?; response = fuzzied; response.fuzzy_distance = FUZZY_DISTANCE as i32; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Applying fuzzy: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Applying fuzzy: ends at {v} ms"); } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Producing results: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Producing results: starts at {v} ms"); + let total = response.results.len() as f32; response.results.iter_mut().enumerate().for_each(|(i, r)| { if let Some(sc) = &mut r.score { sc.booster = total - (i as f32); } }); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Producing results: starts at {v} ms"); - } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at: {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Producing results: starts at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at: {v} ms"); Ok(response) } @@ -295,7 +287,7 @@ impl BatchProducer { impl Iterator for BatchProducer { type Item = Vec; fn next(&mut self) -> Option { - let time = SystemTime::now(); + let time = Instant::now(); if self.offset >= self.total { debug!("No more batches available"); return None; @@ -325,9 +317,9 @@ impl Iterator for BatchProducer { items.push(ParagraphItem { id, labels }); } self.offset += Self::BATCH; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("New batch created, took {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("New batch created, took {v} ms"); + Some(items) } } diff --git a/nucliadb_paragraphs/src/writer.rs b/nucliadb_paragraphs/src/writer.rs index 14e11c76f1..7ed66e51c0 100644 --- a/nucliadb_paragraphs/src/writer.rs +++ b/nucliadb_paragraphs/src/writer.rs @@ -20,7 +20,7 @@ use std::collections::HashMap; use std::fmt::Debug; use std::fs; -use std::time::SystemTime; +use std::time::Instant; use nucliadb_core::prelude::*; use nucliadb_core::protos::prost::Message; @@ -64,18 +64,17 @@ impl WriterChild for ParagraphWriterService { #[measure(actor = "paragraphs", metric = "count")] #[tracing::instrument(skip_all)] fn count(&self) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id: Option = None; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Count starting at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Count starting at {v} ms"); + let reader = self.index.reader()?; let searcher = reader.searcher(); let count = searcher.search(&AllQuery, &Count)?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at: {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at: {v} ms"); Ok(count) } @@ -83,36 +82,34 @@ impl WriterChild for ParagraphWriterService { #[measure(actor = "paragraphs", metric = "set_resource")] #[tracing::instrument(skip_all)] fn set_resource(&mut self, resource: &Resource) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&resource.shard_id); if resource.status != ResourceStatus::Delete as i32 { - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Indexing paragraphs: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Indexing paragraphs: starts at {v} ms"); + let _ = self.index_paragraph(resource); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Indexing paragraphs: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Indexing paragraphs: ends at {v} ms"); } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Processing paragraphs to delete: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Processing paragraphs to delete: starts at {v} ms"); + for paragraph_id in &resource.paragraphs_to_delete { let uuid_term = Term::from_field_text(self.schema.paragraph, paragraph_id); self.writer.delete_term(uuid_term); } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Processing paragraphs to delete: ends at {v} ms"); - } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Processing paragraphs to delete: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: starts at {v} ms"); + self.writer.commit()?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: ends at {v} ms"); Ok(()) } @@ -120,25 +117,24 @@ impl WriterChild for ParagraphWriterService { #[measure(actor = "paragraphs", metric = "delete_resource")] #[tracing::instrument(skip_all)] fn delete_resource(&mut self, resource_id: &ResourceId) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&resource_id.shard_id); let uuid_field = self.schema.uuid; let uuid_term = Term::from_field_text(uuid_field, &resource_id.uuid); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete term: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete term: starts at {v} ms"); + self.writer.delete_term(uuid_term); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete term: ends at {v} ms"); - } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete term: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: starts at {v} ms"); + self.writer.commit()?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: ends at {v} ms"); Ok(()) } diff --git a/nucliadb_procs/src/lib.rs b/nucliadb_procs/src/lib.rs index e326d42c00..681d13f55a 100644 --- a/nucliadb_procs/src/lib.rs +++ b/nucliadb_procs/src/lib.rs @@ -80,12 +80,12 @@ pub fn measure( let expanded = quote! { #(#attrs)* #vis #sig { - let time = std::time::SystemTime::now(); + let time = std::time::Instant::now(); // execute function body let return_value = #block; - let took = time.elapsed().map(|elapsed| elapsed.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); let metrics = nucliadb_core::metrics::get_metrics(); let metric = nucliadb_core::metrics::request_time::RequestTimeKey::#actor(#metric.to_string()); metrics.record_request_time(metric, took); diff --git a/nucliadb_procs/tests/dont_compile/wrong_actor.rs b/nucliadb_procs/tests/dont_compile/wrong_actor.rs index de84d89c1c..36cfbba7b3 100644 --- a/nucliadb_procs/tests/dont_compile/wrong_actor.rs +++ b/nucliadb_procs/tests/dont_compile/wrong_actor.rs @@ -18,11 +18,10 @@ // along with this program. If not, see . // -use nucliadb_procs::{measure}; +use nucliadb_procs::measure; #[measure(actor = "wrong", metric = "my-test")] fn test_wrong_actor() {} - // Make trybuild happy and avoid errors due to not having a main function fn main() {} diff --git a/nucliadb_procs/tests/dont_compile/wrong_actor.stderr b/nucliadb_procs/tests/dont_compile/wrong_actor.stderr index 6a0e989c8f..947dbe24cd 100644 --- a/nucliadb_procs/tests/dont_compile/wrong_actor.stderr +++ b/nucliadb_procs/tests/dont_compile/wrong_actor.stderr @@ -5,7 +5,3 @@ error[E0599]: no function or associated item named `wrong` found for struct `Req | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ function or associated item not found in `RequestTimeKey` | = note: this error originates in the attribute macro `measure` (in Nightly builds, run with -Z macro-backtrace for more info) -help: you are looking for the module in `std`, not the primitive type - | -23 | std::#[measure(actor = "wrong", metric = "my-test")] - | +++++ diff --git a/nucliadb_relations/src/service/reader.rs b/nucliadb_relations/src/service/reader.rs index 98bb37f6fa..97468faa72 100644 --- a/nucliadb_relations/src/service/reader.rs +++ b/nucliadb_relations/src/service/reader.rs @@ -20,7 +20,7 @@ use std::collections::HashSet; use std::fmt::Debug; -use std::time::SystemTime; +use std::time::Instant; use nucliadb_core::prelude::*; use nucliadb_core::protos::*; @@ -53,14 +53,14 @@ impl RelationsReaderService { }; let id = Some(&request.shard_id); - let time = SystemTime::now(); + let time = Instant::now(); let reader = self.index.start_reading()?; let depth = bfs_request.depth.map(|v| v as usize).unwrap_or(usize::MAX); let mut entry_points = Vec::with_capacity(bfs_request.entry_points.len()); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating entry points: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating entry points: starts {v} ms"); + for node in bfs_request.entry_points.iter() { let name = node.value.clone(); let type_info = node_type_parsing(node.ntype(), &node.subtype); @@ -73,20 +73,18 @@ impl RelationsReaderService { Err(e) => error!("{e:?} during {node:?}"), } } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating entry points: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating entry points: ends {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - adding query type filters: starts {v} ms"); - } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - adding query type filters: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - adding query type filters: starts {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - adding query type filters: ends {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - running the search: starts {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - running the search: starts {v} ms"); - } let guide = GrpcGuide { node_filters: HashSet::new(), edge_filters: HashSet::new(), @@ -116,13 +114,12 @@ impl RelationsReaderService { })?; subgraph.push(relation); } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - running the search: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - running the search: ends {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at {v} ms"); - } Ok(Some(EntitiesSubgraphResponse { relations: subgraph, })) @@ -139,24 +136,22 @@ impl RelationsReaderService { }; let id = Some(&request.shard_id); - let time = SystemTime::now(); + let time = Instant::now(); let prefix = &prefix_request.prefix; let reader = self.index.start_reading()?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - running prefix search: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - running prefix search: starts {v} ms"); + let prefixes = reader .prefix_search(&self.rmode, prefix)? .into_iter() .flat_map(|key| reader.get_node_id(&key).ok().flatten()); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - running prefix search: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - running prefix search: ends {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - generating results: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - generating results: starts {v} ms"); let mut node_filters = HashSet::new(); prefix_request.node_filters.iter().for_each(|filter| { @@ -186,13 +181,12 @@ impl RelationsReaderService { ntype: string_to_node_type(node.xtype()) as i32, }) }); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - generating results: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - generating results: ends {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at {v} ms"); - } Ok(Some(RelationPrefixSearchResponse { nodes: nodes.collect::, _>>()?, })) @@ -222,7 +216,7 @@ impl RelationReader for RelationsReaderService { #[measure(actor = "relations", metric = "get_edges")] #[tracing::instrument(skip_all)] fn get_edges(&self) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id: Option = None; let reader = self.index.start_reading()?; @@ -244,9 +238,8 @@ impl RelationReader for RelationsReaderService { }); } } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at {v} ms"); Ok(EdgeList { list: edges }) } @@ -254,7 +247,7 @@ impl RelationReader for RelationsReaderService { #[measure(actor = "relations", metric = "get_node_types")] #[tracing::instrument(skip_all)] fn get_node_types(&self) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id: Option = None; let mut found = HashSet::new(); @@ -276,9 +269,8 @@ impl RelationReader for RelationsReaderService { }); } } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at {v} ms"); Ok(TypeList { list: types }) } diff --git a/nucliadb_relations/src/service/writer.rs b/nucliadb_relations/src/service/writer.rs index fd6be083f0..81bd1eee2a 100644 --- a/nucliadb_relations/src/service/writer.rs +++ b/nucliadb_relations/src/service/writer.rs @@ -19,7 +19,7 @@ // use std::collections::HashMap; -use std::time::SystemTime; +use std::time::Instant; use nucliadb_core::prelude::*; use nucliadb_core::protos::resource::ResourceStatus; @@ -38,7 +38,7 @@ pub struct RelationsWriterService { impl RelationsWriterService { #[tracing::instrument(skip_all)] fn delete_node(&self, writer: &mut GraphWriter, id: Entity) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let affects = writer.delete_node(&self.wmode, id)?; for affected in affects { let affected_value = writer.get_node(affected)?; @@ -48,9 +48,9 @@ impl RelationsWriterService { writer.delete_node(&self.wmode, affected)?; } } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at {v} ms") - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at {v} ms"); + Ok(()) } } @@ -67,18 +67,17 @@ impl WriterChild for RelationsWriterService { #[measure(actor = "relations", metric = "count")] #[tracing::instrument(skip_all)] fn count(&self) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); + + let v = time.elapsed().as_millis(); + debug!("Count starting at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("Count starting at {v} ms"); - } let count = self .index .start_reading() .and_then(|reader| reader.no_nodes())?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("Ending at {v} ms") - } + let v = time.elapsed().as_millis(); + debug!("Ending at {v} ms"); Ok(count as usize) } @@ -86,7 +85,7 @@ impl WriterChild for RelationsWriterService { #[measure(actor = "relations", metric = "delete_resource")] #[tracing::instrument(skip_all)] fn delete_resource(&mut self, x: &ResourceId) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&x.shard_id); let node = IoNode::new(x.uuid.clone(), dictionary::ENTITY.to_string(), None); @@ -94,9 +93,8 @@ impl WriterChild for RelationsWriterService { if let Some(id) = writer.get_node_id(node.hash())? { self.delete_node(&mut writer, id)?; } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at {v} ms") - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at {v} ms"); Ok(()) } @@ -104,13 +102,13 @@ impl WriterChild for RelationsWriterService { #[measure(actor = "relations", metric = "set_resource")] #[tracing::instrument(skip_all)] fn set_resource(&mut self, resource: &Resource) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&resource.shard_id); if resource.status != ResourceStatus::Delete as i32 { - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Populating the graph: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Populating the graph: starts {v} ms"); + let iter = resource .relations .iter() @@ -137,13 +135,11 @@ impl WriterChild for RelationsWriterService { writer.connect(&self.wmode, &from, &to, &edge, metadata.as_ref())?; } writer.commit(&mut self.wmode)?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Populating the graph: ends {v} ms"); - } - } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at {v} ms") + let v = time.elapsed().as_millis(); + debug!("{id:?} - Populating the graph: ends {v} ms"); } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at {v} ms"); Ok(()) } diff --git a/nucliadb_texts/src/reader.rs b/nucliadb_texts/src/reader.rs index 8c83ff81ac..e6f6782949 100644 --- a/nucliadb_texts/src/reader.rs +++ b/nucliadb_texts/src/reader.rs @@ -202,12 +202,12 @@ impl FieldReader for TextReaderService { #[tracing::instrument(skip_all)] fn count(&self) -> NodeResult { let id: Option = None; - let time = SystemTime::now(); + let time = Instant::now(); let searcher = self.reader.searcher(); let count = searcher.search(&AllQuery, &Count)?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at: {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at: {v} ms"); + Ok(count) } } @@ -432,11 +432,11 @@ impl TextReaderService { fn do_search(&self, request: &DocumentSearchRequest) -> NodeResult { use crate::search_query::create_query; let id = Some(&request.id); - let time = SystemTime::now(); + let time = Instant::now(); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating query: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating query: starts at {v} ms"); - } let query_parser = { let mut query_parser = QueryParser::for_index(&self.index, vec![self.schema.text]); query_parser.set_conjunction_by_default(); @@ -467,17 +467,16 @@ impl TextReaderService { facets.push(facet.clone()); facet_collector.add_facet(Facet::from(facet)); } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating query: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating query: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: starts at {v} ms"); - } let searcher = self.reader.searcher(); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: ends at {v} ms"); + match maybe_order { _ if request.only_faceted => { // Just a facet search @@ -548,7 +547,7 @@ impl BatchProducer { impl Iterator for BatchProducer { type Item = Vec; fn next(&mut self) -> Option { - let time = SystemTime::now(); + let time = Instant::now(); if self.offset >= self.total { debug!("No more batches available"); return None; @@ -585,9 +584,9 @@ impl Iterator for BatchProducer { }); } self.offset += Self::BATCH; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("New batch created, took {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("New batch created, took {v} ms"); + Some(items) } } diff --git a/nucliadb_texts/src/writer.rs b/nucliadb_texts/src/writer.rs index 9e459512b5..c8ff727b4e 100644 --- a/nucliadb_texts/src/writer.rs +++ b/nucliadb_texts/src/writer.rs @@ -22,7 +22,7 @@ use std::collections::HashMap; use std::fmt::Debug; use std::fs; use std::path::Path; -use std::time::SystemTime; +use std::time::Instant; use nucliadb_core::prelude::*; use nucliadb_core::protos::resource::ResourceStatus; @@ -61,14 +61,14 @@ impl WriterChild for TextWriterService { #[measure(actor = "texts", metric = "count")] #[tracing::instrument(skip_all)] fn count(&self) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id: Option = None; let reader = self.index.reader()?; let searcher = reader.searcher(); let count = searcher.search(&AllQuery, &Count)?; - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took}"); Ok(count) @@ -80,35 +80,35 @@ impl WriterChild for TextWriterService { let id = Some(&resource.shard_id); let resource_id = resource.resource.as_ref().expect("Missing resource ID"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete existing uuid: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete existing uuid: starts at {v} ms"); + let uuid_field = self.schema.uuid; let uuid_term = Term::from_field_text(uuid_field, &resource_id.uuid); self.writer.delete_term(uuid_term); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete existing uuid: ends at {v} ms"); - } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Indexing document: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete existing uuid: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Indexing document: starts at {v} ms"); + if resource.status != ResourceStatus::Delete as i32 { self.index_document(resource); } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Indexing document: starts at {v} ms"); - } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Indexing document: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: starts at {v} ms"); + self.writer.commit()?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: ends at {v} ms"); - } - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: ends at {v} ms"); + + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took}"); Ok(()) @@ -117,28 +117,24 @@ impl WriterChild for TextWriterService { #[measure(actor = "texts", metric = "delete_resource")] #[tracing::instrument(skip_all)] fn delete_resource(&mut self, resource_id: &ResourceId) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&resource_id.shard_id); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete existing uuid: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete existing uuid: starts at {v} ms"); let uuid_field = self.schema.uuid; let uuid_term = Term::from_field_text(uuid_field, &resource_id.uuid); self.writer.delete_term(uuid_term); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete existing uuid: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete existing uuid: ends at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: starts at {v} ms"); self.writer.commit()?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: ends at {v} ms"); - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took}"); Ok(()) diff --git a/nucliadb_texts2/src/reader.rs b/nucliadb_texts2/src/reader.rs index 9f604cf745..73ad371a2b 100644 --- a/nucliadb_texts2/src/reader.rs +++ b/nucliadb_texts2/src/reader.rs @@ -229,12 +229,12 @@ impl FieldReader for TextReaderService { #[tracing::instrument(skip_all)] fn count(&self) -> NodeResult { let id: Option = None; - let time = SystemTime::now(); + let time = Instant::now(); let searcher = self.reader.searcher(); let count = searcher.search(&AllQuery, &Count)?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Ending at: {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Ending at: {v} ms"); + Ok(count) } } @@ -459,11 +459,11 @@ impl TextReaderService { fn do_search(&self, request: &DocumentSearchRequest) -> NodeResult { use crate::search_query::create_query; let id = Some(&request.id); - let time = SystemTime::now(); + let time = Instant::now(); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating query: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating query: starts at {v} ms"); - } let query_parser = { let mut query_parser = QueryParser::for_index(&self.index, vec![self.schema.text]); query_parser.set_conjunction_by_default(); @@ -494,17 +494,16 @@ impl TextReaderService { facets.push(facet.clone()); facet_collector.add_facet(Facet::from(facet)); } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating query: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating query: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: starts at {v} ms"); - } let searcher = self.reader.searcher(); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: ends at {v} ms"); + match maybe_order { _ if request.only_faceted => { // Just a facet search @@ -575,7 +574,7 @@ impl BatchProducer { impl Iterator for BatchProducer { type Item = Vec; fn next(&mut self) -> Option { - let time = SystemTime::now(); + let time = Instant::now(); if self.offset >= self.total { debug!("No more batches available"); return None; @@ -612,9 +611,9 @@ impl Iterator for BatchProducer { }); } self.offset += Self::BATCH; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("New batch created, took {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("New batch created, took {v} ms"); + Some(items) } } diff --git a/nucliadb_texts2/src/writer.rs b/nucliadb_texts2/src/writer.rs index 9a0c506b5c..05403db72a 100644 --- a/nucliadb_texts2/src/writer.rs +++ b/nucliadb_texts2/src/writer.rs @@ -22,7 +22,7 @@ use std::collections::HashMap; use std::fmt::Debug; use std::fs; use std::path::Path; -use std::time::SystemTime; +use std::time::Instant; use nucliadb_core::prelude::*; use nucliadb_core::protos::resource::ResourceStatus; @@ -61,14 +61,14 @@ impl WriterChild for TextWriterService { #[measure(actor = "texts", metric = "count")] #[tracing::instrument(skip_all)] fn count(&self) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id: Option = None; let reader = self.index.reader()?; let searcher = reader.searcher(); let count = searcher.search(&AllQuery, &Count)?; - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took}"); Ok(count) @@ -80,35 +80,32 @@ impl WriterChild for TextWriterService { let id = Some(&resource.shard_id); let resource_id = resource.resource.as_ref().expect("Missing resource ID"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete existing uuid: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete existing uuid: starts at {v} ms"); + let uuid_field = self.schema.uuid; let uuid_term = Term::from_field_text(uuid_field, &resource_id.uuid); self.writer.delete_term(uuid_term); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete existing uuid: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete existing uuid: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Indexing document: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Indexing document: starts at {v} ms"); - } if resource.status != ResourceStatus::Delete as i32 { self.index_document(resource); } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Indexing document: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Indexing document: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: starts at {v} ms"); - } self.writer.commit()?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: ends at {v} ms"); - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took}"); Ok(()) @@ -117,28 +114,26 @@ impl WriterChild for TextWriterService { #[measure(actor = "texts", metric = "delete_resource")] #[tracing::instrument(skip_all)] fn delete_resource(&mut self, resource_id: &ResourceId) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&resource_id.shard_id); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete existing uuid: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete existing uuid: starts at {v} ms"); + let uuid_field = self.schema.uuid; let uuid_term = Term::from_field_text(uuid_field, &resource_id.uuid); self.writer.delete_term(uuid_term); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete existing uuid: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete existing uuid: ends at {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: starts at {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: starts at {v} ms"); - } self.writer.commit()?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Commit: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Commit: ends at {v} ms"); - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took}"); Ok(()) diff --git a/nucliadb_vectors/src/service/reader.rs b/nucliadb_vectors/src/service/reader.rs index 526991925e..df069b2419 100644 --- a/nucliadb_vectors/src/service/reader.rs +++ b/nucliadb_vectors/src/service/reader.rs @@ -18,7 +18,7 @@ // along with this program. If not, see . use std::fmt::Debug; -use std::time::SystemTime; +use std::time::Instant; use nucliadb_core::prelude::*; use nucliadb_core::protos::prost::Message; @@ -87,7 +87,7 @@ impl ReaderChild for VectorReaderService { #[measure(actor = "vectors", metric = "search")] #[tracing::instrument(skip_all)] fn search(&self, request: &Self::Request) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&request.id); let offset = request.result_per_page * request.page_number; @@ -123,9 +123,9 @@ impl ReaderChild for VectorReaderService { } let search_request = (total_to_get, request, formula); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: starts at {v} ms"); + let result = if request.vector_set.is_empty() { debug!("{id:?} - No vectorset specified, searching in the main index"); self.index.search(&search_request, &index_slock)? @@ -143,16 +143,15 @@ impl ReaderChild for VectorReaderService { ); vec![] }; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Searching: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Searching: ends at {v} ms"); std::mem::drop(indexet_slock); std::mem::drop(index_slock); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating results: starts at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating results: starts at {v} ms"); + let documents = result .into_iter() .enumerate() @@ -160,11 +159,10 @@ impl ReaderChild for VectorReaderService { .map(|(_, v)| v) .flat_map(DocumentScored::try_from) .collect::>(); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating results: ends at {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating results: ends at {v} ms"); - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took} ms"); Ok(VectorSearchResponse { @@ -177,12 +175,12 @@ impl ReaderChild for VectorReaderService { #[measure(actor = "vectors", metric = "stored_ids")] #[tracing::instrument(skip_all)] fn stored_ids(&self) -> NodeResult> { - let time = SystemTime::now(); + let time = Instant::now(); let lock = self.index.get_slock().unwrap(); let result = self.index.get_keys(&lock)?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("Ending at {v} ms") - } + let v = time.elapsed().as_millis(); + debug!("Ending at {v} ms"); + Ok(result) } } diff --git a/nucliadb_vectors/src/service/writer.rs b/nucliadb_vectors/src/service/writer.rs index b6af703e08..3c8b279c2a 100644 --- a/nucliadb_vectors/src/service/writer.rs +++ b/nucliadb_vectors/src/service/writer.rs @@ -20,7 +20,7 @@ use std::collections::HashMap; use std::fmt::Debug; use std::fs; use std::path::PathBuf; -use std::time::SystemTime; +use std::time::Instant; use nucliadb_core::metrics::request_time; use nucliadb_core::prelude::*; @@ -59,14 +59,14 @@ impl VectorWriter for VectorWriterService { #[measure(actor = "vectors", metric = "list_vectorsets")] #[tracing::instrument(skip_all)] fn list_vectorsets(&self) -> NodeResult> { - let time = SystemTime::now(); + let time = Instant::now(); let id: Option = None; let mut collector = Vec::new(); let indexset_slock = self.indexset.get_slock()?; self.indexset.index_keys(&mut collector, &indexset_slock); - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took} ms"); Ok(collector) @@ -79,7 +79,7 @@ impl VectorWriter for VectorWriterService { setid: &VectorSetId, similarity: VectorSimilarity, ) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = setid.shard.as_ref().map(|s| &s.id); let set = &setid.vectorset; @@ -90,7 +90,7 @@ impl VectorWriter for VectorWriterService { .get_or_create(indexid, similarity, &indexset_elock)?; self.indexset.commit(indexset_elock)?; - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?}/{set} - Ending at {took} ms"); Ok(()) @@ -99,7 +99,7 @@ impl VectorWriter for VectorWriterService { #[measure(actor = "vectors", metric = "remove_vectorset")] #[tracing::instrument(skip_all)] fn remove_vectorset(&mut self, setid: &VectorSetId) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = setid.shard.as_ref().map(|s| &s.id); let set = &setid.vectorset; @@ -108,7 +108,7 @@ impl VectorWriter for VectorWriterService { self.indexset.remove_index(indexid, &indexset_elock)?; self.indexset.commit(indexset_elock)?; - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?}/{set} - Ending at {took} ms"); Ok(()) @@ -119,14 +119,14 @@ impl WriterChild for VectorWriterService { #[measure(actor = "vectors", metric = "count")] #[tracing::instrument(skip_all)] fn count(&self) -> NodeResult { - let time = SystemTime::now(); + let time = Instant::now(); let id: Option = None; let lock = self.index.get_slock()?; let no_nodes = self.index.no_nodes(&lock); std::mem::drop(lock); - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took} ms"); Ok(no_nodes) @@ -135,7 +135,7 @@ impl WriterChild for VectorWriterService { #[measure(actor = "vectors", metric = "delete_resource")] #[tracing::instrument(skip_all)] fn delete_resource(&mut self, resource_id: &ResourceId) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = Some(&resource_id.shard_id); let temporal_mark = TemporalMark::now(); @@ -143,7 +143,7 @@ impl WriterChild for VectorWriterService { self.index.delete(&resource_id.uuid, temporal_mark, &lock); self.index.commit(&lock)?; - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("{id:?} - Ending at {took} ms"); Ok(()) @@ -152,13 +152,12 @@ impl WriterChild for VectorWriterService { #[measure(actor = "vectors", metric = "set_resource")] #[tracing::instrument(skip_all)] fn set_resource(&mut self, resource: &Resource) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let id = resource.resource.as_ref().map(|i| &i.shard_id); debug!("{id:?} - Updating main index"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating elements for the main index: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating elements for the main index: starts {v} ms"); let temporal_mark = TemporalMark::now(); let mut lengths: HashMap> = HashMap::new(); @@ -188,13 +187,11 @@ impl WriterChild for VectorWriterService { } } } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating elements for the main index: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating elements for the main index: ends {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Datapoint creation: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Datapoint creation: starts {v} ms"); if lengths.len() > 1 { return Ok(tracing::error!("{}", self.dimensions_report(lengths))); @@ -212,38 +209,35 @@ impl WriterChild for VectorWriterService { None }; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Datapoint creation: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Datapoint creation: ends {v} ms"); let lock = self.index.get_slock()?; - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Processing Sentences to delete: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Processing Sentences to delete: starts {v} ms"); + for to_delete in &resource.sentences_to_delete { self.index.delete(to_delete, temporal_mark, &lock) } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Processing Sentences to delete: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Processing Sentences to delete: ends {v} ms"); + + let v = time.elapsed().as_millis(); + debug!("{id:?} - Indexing datapoint: starts {v} ms"); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Indexing datapoint: starts {v} ms"); - } match new_dp.map(|i| self.index.add(i, &lock)).unwrap_or(Ok(())) { Ok(_) => self.index.commit(&lock)?, Err(e) => tracing::error!("{id:?}/default could insert vectors: {e:?}"), } std::mem::drop(lock); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Indexing datapoint: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Indexing datapoint: ends {v} ms"); // Updating existing indexes // Perform delete operations over the vector set - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete requests for indexes in the set: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete requests for indexes in the set: starts {v} ms"); + let indexset_slock = self.indexset.get_slock()?; let index_iter = resource.vectors_to_delete.iter().flat_map(|(k, v)| { self.indexset @@ -260,15 +254,14 @@ impl WriterChild for VectorWriterService { index.commit(&index_lock)?; } std::mem::drop(indexset_slock); - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Delete requests for indexes in the set: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Delete requests for indexes in the set: ends {v} ms"); // Perform add operations over the vector set // New indexes may be created. - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating and geting indexes in the set: starts {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating and geting indexes in the set: starts {v} ms"); + let indexset_elock = self.indexset.get_elock()?; let indexes = resource .vectors @@ -309,12 +302,11 @@ impl WriterChild for VectorWriterService { } } } - if let Ok(v) = time.elapsed().map(|s| s.as_millis()) { - debug!("{id:?} - Creating and geting indexes in the set: ends {v} ms"); - } + let v = time.elapsed().as_millis(); + debug!("{id:?} - Creating and geting indexes in the set: ends {v} ms"); let metrics = metrics::get_metrics(); - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); let metric = request_time::RequestTimeKey::vectors("set_resource".to_string()); metrics.record_request_time(metric, took); debug!("{id:?} - Ending at {took} ms"); @@ -325,7 +317,7 @@ impl WriterChild for VectorWriterService { #[measure(actor = "vectors", metric = "garbage_collection")] #[tracing::instrument(skip_all)] fn garbage_collection(&mut self) -> NodeResult<()> { - let time = SystemTime::now(); + let time = Instant::now(); let lock = match self.index.try_elock() { Ok(lock) => lock, @@ -337,7 +329,7 @@ impl WriterChild for VectorWriterService { }; self.index.collect_garbage(&lock)?; - let took = time.elapsed().map(|i| i.as_secs_f64()).unwrap_or(f64::NAN); + let took = time.elapsed().as_secs_f64(); debug!("Garbage collection {took} ms"); Ok(())