Add tracing timers logs

This commit is contained in:
ManyTheFish 2024-09-05 17:36:19 +02:00
parent f6b3d1f9a5
commit 8fd99b111b
4 changed files with 115 additions and 50 deletions

View File

@ -17,6 +17,7 @@ mod extract_facets;
mod facet_document; mod facet_document;
pub trait FacetedExtractor { pub trait FacetedExtractor {
#[tracing::instrument(level = "trace", skip_all, target = "indexing::extract::faceted")]
fn run_extraction( fn run_extraction(
index: &Index, index: &Index,
fields_ids_map: &GlobalFieldsIdsMap, fields_ids_map: &GlobalFieldsIdsMap,

View File

@ -63,8 +63,11 @@ where
thread::scope(|s| { thread::scope(|s| {
// TODO manage the errors correctly // TODO manage the errors correctly
let current_span = tracing::Span::current();
let handle = Builder::new().name(S("indexer-extractors")).spawn_scoped(s, move || { let handle = Builder::new().name(S("indexer-extractors")).spawn_scoped(s, move || {
pool.in_place_scope(|_s| { pool.in_place_scope(|_s| {
let span = tracing::trace_span!(target: "indexing::documents", parent: &current_span, "extract");
let _entered = span.enter();
let document_changes = document_changes.into_par_iter(); let document_changes = document_changes.into_par_iter();
// document but we need to create a function that collects and compresses documents. // document but we need to create a function that collects and compresses documents.
@ -95,56 +98,85 @@ where
max_memory: Some(max_memory), max_memory: Some(max_memory),
..GrenadParameters::default() ..GrenadParameters::default()
}; };
extract_and_send_docids::<WordDocidsExtractor, WordDocids>( {
index, let span = tracing::trace_span!(target: "indexing::documents::extract", "word_docids");
&global_fields_ids_map, let _entered = span.enter();
grenad_parameters, extract_and_send_docids::<WordDocidsExtractor, WordDocids>(
document_changes.clone(), index,
&extractor_sender, &global_fields_ids_map,
)?; grenad_parameters,
document_changes.clone(),
&extractor_sender,
)?;
}
extract_and_send_docids::<WordFidDocidsExtractor, WordFidDocids>( {
index, let span = tracing::trace_span!(target: "indexing::documents::extract", "word_fid_docids");
&global_fields_ids_map, let _entered = span.enter();
grenad_parameters, extract_and_send_docids::<WordFidDocidsExtractor, WordFidDocids>(
document_changes.clone(), index,
&extractor_sender, &global_fields_ids_map,
)?; grenad_parameters,
document_changes.clone(),
&extractor_sender,
)?;
}
{
let span = tracing::trace_span!(target: "indexing::documents::extract", "exact_word_docids");
let _entered = span.enter();
extract_and_send_docids::<ExactWordDocidsExtractor, ExactWordDocids>(
index,
&global_fields_ids_map,
grenad_parameters,
document_changes.clone(),
&extractor_sender,
)?;
}
extract_and_send_docids::<ExactWordDocidsExtractor, ExactWordDocids>( {
index, let span = tracing::trace_span!(target: "indexing::documents::extract", "word_position_docids");
&global_fields_ids_map, let _entered = span.enter();
grenad_parameters, extract_and_send_docids::<WordPositionDocidsExtractor, WordPositionDocids>(
document_changes.clone(), index,
&extractor_sender, &global_fields_ids_map,
)?; grenad_parameters,
document_changes.clone(),
&extractor_sender,
)?;
}
extract_and_send_docids::<WordPositionDocidsExtractor, WordPositionDocids>( {
index, let span = tracing::trace_span!(target: "indexing::documents::extract", "fid_word_count_docids");
&global_fields_ids_map, let _entered = span.enter();
grenad_parameters, extract_and_send_docids::<FidWordCountDocidsExtractor, FidWordCountDocids>(
document_changes.clone(), index,
&extractor_sender, &global_fields_ids_map,
)?; GrenadParameters::default(),
document_changes.clone(),
&extractor_sender,
)?;
}
extract_and_send_docids::<FidWordCountDocidsExtractor, FidWordCountDocids>( {
index, let span = tracing::trace_span!(target: "indexing::documents::extract", "word_pair_proximity_docids");
&global_fields_ids_map, let _entered = span.enter();
GrenadParameters::default(), extract_and_send_docids::<
document_changes.clone(), WordPairProximityDocidsExtractor,
&extractor_sender, WordPairProximityDocids,
)?; >(
index,
&global_fields_ids_map,
grenad_parameters,
document_changes.clone(),
&extractor_sender,
)?;
}
extract_and_send_docids::< {
WordPairProximityDocidsExtractor, let span = tracing::trace_span!(target: "indexing::documents::extract", "FINISH");
WordPairProximityDocids, let _entered = span.enter();
>( }
index,
&global_fields_ids_map,
grenad_parameters,
document_changes.clone(),
&extractor_sender,
)?;
// TODO THIS IS TOO MUCH // TODO THIS IS TOO MUCH
// Extract fieldid docid facet number // Extract fieldid docid facet number
@ -166,7 +198,11 @@ where
})?; })?;
// TODO manage the errors correctly // TODO manage the errors correctly
let current_span = tracing::Span::current();
let handle2 = Builder::new().name(S("indexer-merger")).spawn_scoped(s, move || { let handle2 = Builder::new().name(S("indexer-merger")).spawn_scoped(s, move || {
let span =
tracing::trace_span!(target: "indexing::documents", parent: &current_span, "merge");
let _entered = span.enter();
let rtxn = index.read_txn().unwrap(); let rtxn = index.read_txn().unwrap();
merge_grenad_entries(merger_receiver, merger_sender, &rtxn, index) merge_grenad_entries(merger_receiver, merger_sender, &rtxn, index)
})?; })?;

View File

@ -16,6 +16,7 @@ use crate::update::MergeDeladdCboRoaringBitmaps;
use crate::{CboRoaringBitmapCodec, Index, Result}; use crate::{CboRoaringBitmapCodec, Index, Result};
/// TODO We must return some infos/stats /// TODO We must return some infos/stats
#[tracing::instrument(level = "trace", skip_all, target = "indexing::documents", name = "merge")]
pub fn merge_grenad_entries( pub fn merge_grenad_entries(
receiver: MergerReceiver, receiver: MergerReceiver,
sender: MergerSender, sender: MergerSender,
@ -28,6 +29,9 @@ pub fn merge_grenad_entries(
for merger_operation in receiver { for merger_operation in receiver {
match merger_operation { match merger_operation {
MergerOperation::ExactWordDocidsMerger(merger) => { MergerOperation::ExactWordDocidsMerger(merger) => {
let span =
tracing::trace_span!(target: "indexing::documents::merge", "exact_word_docids");
let _entered = span.enter();
merge_and_send_docids( merge_and_send_docids(
merger, merger,
/// TODO do a MergerOperation::database(&Index) -> Database<Bytes, Bytes>. /// TODO do a MergerOperation::database(&Index) -> Database<Bytes, Bytes>.
@ -40,6 +44,8 @@ pub fn merge_grenad_entries(
)?; )?;
} }
MergerOperation::FidWordCountDocidsMerger(merger) => { MergerOperation::FidWordCountDocidsMerger(merger) => {
let span = tracing::trace_span!(target: "indexing::documents::merge", "fid_word_count_docids");
let _entered = span.enter();
merge_and_send_docids( merge_and_send_docids(
merger, merger,
index.field_id_word_count_docids.remap_types(), index.field_id_word_count_docids.remap_types(),
@ -51,6 +57,9 @@ pub fn merge_grenad_entries(
)?; )?;
} }
MergerOperation::WordDocidsMerger(merger) => { MergerOperation::WordDocidsMerger(merger) => {
let span =
tracing::trace_span!(target: "indexing::documents::merge", "word_docids");
let _entered = span.enter();
let mut add_words_fst = SetBuilder::new(tempfile()?)?; let mut add_words_fst = SetBuilder::new(tempfile()?)?;
let mut del_words_fst = SetBuilder::new(tempfile()?)?; let mut del_words_fst = SetBuilder::new(tempfile()?)?;
@ -70,6 +79,9 @@ pub fn merge_grenad_entries(
sender.main().write_words_fst(mmap).unwrap(); sender.main().write_words_fst(mmap).unwrap();
} }
MergerOperation::WordFidDocidsMerger(merger) => { MergerOperation::WordFidDocidsMerger(merger) => {
let span =
tracing::trace_span!(target: "indexing::documents::merge", "word_fid_docids");
let _entered = span.enter();
merge_and_send_docids( merge_and_send_docids(
merger, merger,
index.word_fid_docids.remap_types(), index.word_fid_docids.remap_types(),
@ -81,6 +93,8 @@ pub fn merge_grenad_entries(
)?; )?;
} }
MergerOperation::WordPairProximityDocidsMerger(merger) => { MergerOperation::WordPairProximityDocidsMerger(merger) => {
let span = tracing::trace_span!(target: "indexing::documents::merge", "word_pair_proximity_docids");
let _entered = span.enter();
merge_and_send_docids( merge_and_send_docids(
merger, merger,
index.word_pair_proximity_docids.remap_types(), index.word_pair_proximity_docids.remap_types(),
@ -92,6 +106,8 @@ pub fn merge_grenad_entries(
)?; )?;
} }
MergerOperation::WordPositionDocidsMerger(merger) => { MergerOperation::WordPositionDocidsMerger(merger) => {
let span = tracing::trace_span!(target: "indexing::documents::merge", "word_position_docids");
let _entered = span.enter();
merge_and_send_docids( merge_and_send_docids(
merger, merger,
index.word_position_docids.remap_types(), index.word_position_docids.remap_types(),
@ -103,10 +119,16 @@ pub fn merge_grenad_entries(
)?; )?;
} }
MergerOperation::InsertDocument { docid, document } => { MergerOperation::InsertDocument { docid, document } => {
let span =
tracing::trace_span!(target: "indexing::documents::merge", "insert_document");
let _entered = span.enter();
documents_ids.insert(docid); documents_ids.insert(docid);
sender.documents().uncompressed(docid, &document).unwrap(); sender.documents().uncompressed(docid, &document).unwrap();
} }
MergerOperation::DeleteDocument { docid } => { MergerOperation::DeleteDocument { docid } => {
let span =
tracing::trace_span!(target: "indexing::documents::merge", "delete_document");
let _entered = span.enter();
if !documents_ids.remove(docid) { if !documents_ids.remove(docid) {
unreachable!("Tried deleting a document that we do not know about"); unreachable!("Tried deleting a document that we do not know about");
} }
@ -115,10 +137,15 @@ pub fn merge_grenad_entries(
} }
} }
// Send the documents ids unionized with the current one {
/// TODO return the slice of bytes directly let span = tracing::trace_span!(target: "indexing::documents::merge", "documents_ids");
serialize_bitmap_into_vec(&documents_ids, &mut buffer); let _entered = span.enter();
sender.send_documents_ids(&buffer).unwrap();
// Send the documents ids unionized with the current one
/// TODO return the slice of bytes directly
serialize_bitmap_into_vec(&documents_ids, &mut buffer);
sender.send_documents_ids(&buffer).unwrap();
}
// ... // ...
@ -149,6 +176,7 @@ fn compute_new_words_fst(
Ok(words_fst_mmap) Ok(words_fst_mmap)
} }
#[tracing::instrument(level = "trace", skip_all, target = "indexing::merge")]
fn merge_and_send_docids<D: DatabaseType>( fn merge_and_send_docids<D: DatabaseType>(
merger: Merger<File, MergeDeladdCboRoaringBitmaps>, merger: Merger<File, MergeDeladdCboRoaringBitmaps>,
database: Database<Bytes, Bytes>, database: Database<Bytes, Bytes>,

View File

@ -1,6 +1,6 @@
{ {
"name": "movies.json", "name": "movies.json",
"run_count": 10, "run_count": 1,
"extra_cli_args": [], "extra_cli_args": [],
"assets": { "assets": {
"movies.json": { "movies.json": {