Refactor logging levels to debug for improved performance and clarity

- Changed several logging statements from `info` to `debug` across various modules, including `StdBackend`, `RefPathIndex`, `ServeSession`, and `syncback_loop_with_stats`.
- This adjustment aims to reduce log verbosity during normal operations while retaining detailed logs for debugging purposes, enhancing overall performance and maintainability.
This commit is contained in:
Joe 2026-02-19 04:12:44 -06:00
parent 56e1ab4a06
commit 1c25b928a8
5 changed files with 44 additions and 42 deletions

View file

@ -344,7 +344,7 @@ impl VfsBackend for StdBackend {
// This prevents a failed watch from permanently marking the path as "watched" // This prevents a failed watch from permanently marking the path as "watched"
match self.debouncer.watch(path, RecursiveMode::Recursive) { match self.debouncer.watch(path, RecursiveMode::Recursive) {
Ok(()) => { Ok(()) => {
log::info!("Watching path: {}", path.display()); log::debug!("Watching path: {}", path.display());
self.watches.insert(path.to_path_buf()); self.watches.insert(path.to_path_buf());
Ok(()) Ok(())
} }

View file

@ -182,22 +182,28 @@ fn patch_set_affects_sourcemap(
fn recurse_create_node<'a>( fn recurse_create_node<'a>(
tree: &'a RojoTree, tree: &'a RojoTree,
referent: Ref, referent: Ref,
project_dir: &Path, canonical_project_dir: &Path,
filter: fn(&InstanceWithMeta) -> bool, filter: fn(&InstanceWithMeta) -> bool,
use_absolute_paths: bool, use_absolute_paths: bool,
) -> Option<SourcemapNode<'a>> { ) -> Option<SourcemapNode<'a>> {
let instance = tree.get_instance(referent).expect("instance did not exist"); let instance = tree.get_instance(referent).expect("instance did not exist");
let children: Vec<_> = instance let results: Vec<Option<SourcemapNode<'a>>> = instance
.children() .children()
.par_iter() .par_iter()
.filter_map(|&child_id| { .map(|&child_id| {
recurse_create_node(tree, child_id, project_dir, filter, use_absolute_paths) recurse_create_node(
tree,
child_id,
canonical_project_dir,
filter,
use_absolute_paths,
)
}) })
.collect(); .collect();
// If this object has no children and doesn't pass the filter, it doesn't let children: Vec<_> = results.into_iter().flatten().collect();
// contain any information we're looking for.
if children.is_empty() && !filter(&instance) { if children.is_empty() && !filter(&instance) {
return None; return None;
} }
@ -206,25 +212,19 @@ fn recurse_create_node<'a>(
.metadata() .metadata()
.relevant_paths .relevant_paths
.iter() .iter()
// Not all paths listed as relevant are guaranteed to exist.
.filter(|path| path.is_file()) .filter(|path| path.is_file())
.map(|path| path.as_path()); .map(|path| path.as_path());
let mut output_file_paths: Vec<Cow<'a, Path>> = let mut output_file_paths: Vec<Cow<'a, Path>> =
Vec::with_capacity(instance.metadata().relevant_paths.len()); Vec::with_capacity(instance.metadata().relevant_paths.len());
// Canonicalize project_dir once to normalize Windows \\?\ prefixes
let canonical_project_dir =
std::fs::canonicalize(project_dir).unwrap_or_else(|_| project_dir.to_path_buf());
for val in file_paths { for val in file_paths {
if use_absolute_paths { if use_absolute_paths {
let abs_path = path::absolute(val).expect(ABSOLUTE_PATH_FAILED_ERR); let abs_path = path::absolute(val).expect(ABSOLUTE_PATH_FAILED_ERR);
output_file_paths.push(Cow::Owned(abs_path)); output_file_paths.push(Cow::Owned(abs_path));
} else { } else {
let canonical_val = std::fs::canonicalize(val).unwrap_or_else(|_| val.to_path_buf());
output_file_paths.push(Cow::Owned( output_file_paths.push(Cow::Owned(
pathdiff::diff_paths(&canonical_val, &canonical_project_dir) pathdiff::diff_paths(val, canonical_project_dir)
.expect("Failed to compute relative path from project dir"), .expect("Failed to compute relative path from project dir"),
)); ));
} }
@ -247,10 +247,13 @@ pub(crate) fn write_sourcemap(
) -> anyhow::Result<()> { ) -> anyhow::Result<()> {
let tree = session.tree(); let tree = session.tree();
let canonical_project_dir = std::fs::canonicalize(session.root_dir())
.unwrap_or_else(|_| session.root_dir().to_path_buf());
let root_node = recurse_create_node( let root_node = recurse_create_node(
&tree, &tree,
tree.get_root_id(), tree.get_root_id(),
session.root_dir(), &canonical_project_dir,
filter, filter,
use_absolute_paths, use_absolute_paths,
); );
@ -324,10 +327,7 @@ fn recurse_create_node_from_dom<'a>(
.map(|paths| { .map(|paths| {
paths paths
.iter() .iter()
.filter_map(|p| { .filter_map(|p| pathdiff::diff_paths(p, project_dir).map(Cow::Owned))
let canonical = std::fs::canonicalize(p).unwrap_or_else(|_| p.clone());
pathdiff::diff_paths(&canonical, project_dir).map(Cow::Owned)
})
.collect() .collect()
}) })
.unwrap_or_default(); .unwrap_or_default();

View file

@ -428,7 +428,7 @@ impl RefPathIndex {
} }
if count > 0 { if count > 0 {
log::info!( log::debug!(
"RefPathIndex: populated {} Rojo_Ref_* entries from existing meta/model files", "RefPathIndex: populated {} Rojo_Ref_* entries from existing meta/model files",
count count
); );

View file

@ -174,7 +174,7 @@ fn prefetch_project_files(project: &Project) -> io::Result<PrefetchCache> {
let file_count = entries.iter().filter(|e| e.file_type().is_file()).count(); let file_count = entries.iter().filter(|e| e.file_type().is_file()).count();
let dir_count = entries.len() - file_count; let dir_count = entries.len() - file_count;
log::info!( log::debug!(
"Prefetch walk: {} files + {} dirs from {} root(s) in {:.1?}", "Prefetch walk: {} files + {} dirs from {} root(s) in {:.1?}",
file_count, file_count,
dir_count, dir_count,
@ -206,7 +206,7 @@ fn prefetch_project_files(project: &Project) -> io::Result<PrefetchCache> {
let canon_elapsed = canon_start.elapsed(); let canon_elapsed = canon_start.elapsed();
log::info!( log::debug!(
"Prefetch I/O: read {} files in {:.1?}, canonicalize {} paths in {:.1?}", "Prefetch I/O: read {} files in {:.1?}, canonicalize {} paths in {:.1?}",
file_data.len(), file_data.len(),
read_elapsed, read_elapsed,
@ -235,7 +235,7 @@ fn prefetch_project_files(project: &Project) -> io::Result<PrefetchCache> {
children.sort_by(|a, b| a.file_name().cmp(&b.file_name())); children.sort_by(|a, b| a.file_name().cmp(&b.file_name()));
} }
log::info!( log::debug!(
"Prefetch maps: {} is_file + {} children dirs built", "Prefetch maps: {} is_file + {} children dirs built",
is_file_map.len(), is_file_map.len(),
children_map.len(), children_map.len(),
@ -293,7 +293,7 @@ impl ServeSession {
let snap_start = Instant::now(); let snap_start = Instant::now();
log::trace!("Generating snapshot of instances from VFS"); log::trace!("Generating snapshot of instances from VFS");
let snapshot = snapshot_from_vfs(&instance_context, vfs, start_path)?; let snapshot = snapshot_from_vfs(&instance_context, vfs, start_path)?;
log::info!("Snapshot built in {:.1?}", snap_start.elapsed()); log::debug!("Snapshot built in {:.1?}", snap_start.elapsed());
vfs.clear_prefetch_cache(); vfs.clear_prefetch_cache();
@ -303,7 +303,7 @@ impl ServeSession {
log::trace!("Applying initial patch set"); log::trace!("Applying initial patch set");
apply_patch_set(&mut tree, patch_set); apply_patch_set(&mut tree, patch_set);
log::info!("Patch computed + applied in {:.1?}", patch_start.elapsed()); log::debug!("Patch computed + applied in {:.1?}", patch_start.elapsed());
Ok((root_project, tree)) Ok((root_project, tree))
} }

View file

@ -132,7 +132,7 @@ pub fn syncback_loop_with_stats(
// (references to instances that will be pruned, like SoundGroups in SoundService). // (references to instances that will be pruned, like SoundGroups in SoundService).
log::debug!("Collecting instance paths before pruning..."); log::debug!("Collecting instance paths before pruning...");
let pre_prune_paths = collect_all_paths(&new_tree); let pre_prune_paths = collect_all_paths(&new_tree);
log::info!( log::debug!(
"syncback: collect_all_paths in {:.1?}", "syncback: collect_all_paths in {:.1?}",
phase_timer.elapsed() phase_timer.elapsed()
); );
@ -171,12 +171,12 @@ pub fn syncback_loop_with_stats(
if ignore_hidden { if ignore_hidden {
strip_hidden_services(&mut new_tree); strip_hidden_services(&mut new_tree);
} }
log::info!("syncback: prune + filter in {:.1?}", phase_timer.elapsed()); log::debug!("syncback: prune + filter in {:.1?}", phase_timer.elapsed());
let phase_timer = std::time::Instant::now(); let phase_timer = std::time::Instant::now();
let mut deferred_referents = collect_referents(&new_tree, &pre_prune_paths, None); let mut deferred_referents = collect_referents(&new_tree, &pre_prune_paths, None);
let placeholder_map = std::mem::take(&mut deferred_referents.placeholder_to_source_and_target); let placeholder_map = std::mem::take(&mut deferred_referents.placeholder_to_source_and_target);
log::info!( log::debug!(
"syncback: collect_referents in {:.1?}", "syncback: collect_referents in {:.1?}",
phase_timer.elapsed() phase_timer.elapsed()
); );
@ -235,7 +235,7 @@ pub fn syncback_loop_with_stats(
if !ignore_referents { if !ignore_referents {
link_referents(deferred_referents, &mut new_tree)?; link_referents(deferred_referents, &mut new_tree)?;
} }
log::info!( log::debug!(
"syncback: filter props + link refs in {:.1?}", "syncback: filter props + link refs in {:.1?}",
phase_timer.elapsed() phase_timer.elapsed()
); );
@ -247,7 +247,7 @@ pub fn syncback_loop_with_stats(
|| hash_tree(project, old_tree.inner(), old_tree.get_root_id()), || hash_tree(project, old_tree.inner(), old_tree.get_root_id()),
|| hash_tree(project, &new_tree, new_tree.root_ref()), || hash_tree(project, &new_tree, new_tree.root_ref()),
); );
log::info!( log::debug!(
"syncback: hash both trees (parallel) in {:.1?}", "syncback: hash both trees (parallel) in {:.1?}",
phase_timer.elapsed() phase_timer.elapsed()
); );
@ -381,13 +381,13 @@ pub fn syncback_loop_with_stats(
} }
} }
log::trace!( if log::log_enabled!(log::Level::Trace) {
"dirs_to_scan: {:?}", let dirs_str: Vec<_> = dirs_to_scan
dirs_to_scan
.iter() .iter()
.map(|p| p.display().to_string()) .map(|p| p.display().to_string())
.collect::<Vec<_>>() .collect();
); log::trace!("dirs_to_scan: {:?}", dirs_str);
}
for dir in &dirs_to_scan { for dir in &dirs_to_scan {
if !dir.is_dir() { if !dir.is_dir() {
@ -439,7 +439,7 @@ pub fn syncback_loop_with_stats(
} else { } else {
HashSet::new() HashSet::new()
}; };
log::info!( log::debug!(
"syncback: orphan scan in {:.1?} ({} paths)", "syncback: orphan scan in {:.1?} ({} paths)",
phase_timer.elapsed(), phase_timer.elapsed(),
existing_paths.len() existing_paths.len()
@ -605,7 +605,7 @@ pub fn syncback_loop_with_stats(
snapshots.extend(syncback.children); snapshots.extend(syncback.children);
} }
log::info!("syncback: main walk loop in {:.1?}", phase_timer.elapsed()); log::debug!("syncback: main walk loop in {:.1?}", phase_timer.elapsed());
let phase_timer = std::time::Instant::now(); let phase_timer = std::time::Instant::now();
{ {
@ -625,7 +625,7 @@ pub fn syncback_loop_with_stats(
let relative = crate::compute_relative_ref_path(&source_abs, &target_abs); let relative = crate::compute_relative_ref_path(&source_abs, &target_abs);
substitutions.push((placeholder.clone(), relative)); substitutions.push((placeholder.clone(), relative));
} }
log::info!( log::debug!(
"syncback: built {} ref substitutions in {:.1?}", "syncback: built {} ref substitutions in {:.1?}",
substitutions.len(), substitutions.len(),
phase_timer.elapsed() phase_timer.elapsed()
@ -635,7 +635,7 @@ pub fn syncback_loop_with_stats(
if !substitutions.is_empty() { if !substitutions.is_empty() {
fs_snapshot.fix_ref_paths(&substitutions); fs_snapshot.fix_ref_paths(&substitutions);
} }
log::info!( log::debug!(
"syncback: applied ref substitutions in {:.1?}", "syncback: applied ref substitutions in {:.1?}",
sub_timer.elapsed() sub_timer.elapsed()
); );
@ -738,8 +738,10 @@ pub fn syncback_loop_with_stats(
&mut protected_paths, &mut protected_paths,
&mut path_to_instance_prefix, &mut path_to_instance_prefix,
); );
log::trace!("Protected $path references: {:?}", protected_paths); if log::log_enabled!(log::Level::Trace) {
log::trace!("Path to instance mappings: {:?}", path_to_instance_prefix); log::trace!("Protected $path references: {:?}", protected_paths);
log::trace!("Path to instance mappings: {:?}", path_to_instance_prefix);
}
// Helper to convert a filesystem path to an instance path using the mappings // Helper to convert a filesystem path to an instance path using the mappings
let fs_path_to_instance_path = |fs_path: &Path| -> Option<String> { let fs_path_to_instance_path = |fs_path: &Path| -> Option<String> {
@ -906,7 +908,7 @@ pub fn syncback_loop_with_stats(
} }
} }
log::info!("syncback: orphan removal in {:.1?}", phase_timer.elapsed()); log::debug!("syncback: orphan removal in {:.1?}", phase_timer.elapsed());
if external_stats.is_none() { if external_stats.is_none() {
stats.log_summary(); stats.log_summary();