# HG changeset patch # User Raphaël Gomès # Date 1583514503 -3600 # Node ID d880805d5442c2c3418e94e0cebe59a6951c3f42 # Parent 82f51ab7a2dd855fc7045b1fdf67defaf7653f8b hg-core: add function timing information This change makes use of the newly added logging infrastructure to trace the execution time of some important calls. This approach is very much complementary to using a profiler and will not guard against out-of-order execution or other kinds of compiler optimizations. That said, it is useful to get a rough high-level idea of where time is spent. Differential Revision: https://phab.mercurial-scm.org/D8253 diff -r 82f51ab7a2dd -r d880805d5442 rust/Cargo.lock --- a/rust/Cargo.lock Fri Mar 06 18:08:13 2020 +0100 +++ b/rust/Cargo.lock Fri Mar 06 18:08:23 2020 +0100 @@ -235,6 +235,7 @@ "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", "memchr 2.3.3 (registry+https://github.com/rust-lang/crates.io-index)", "memmap 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)", + "micro-timer 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)", "pretty_assertions 0.6.1 (registry+https://github.com/rust-lang/crates.io-index)", "rand 0.6.5 (registry+https://github.com/rust-lang/crates.io-index)", "rand_pcg 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)", @@ -301,6 +302,16 @@ ] [[package]] +name = "micro-timer" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +dependencies = [ + "proc-macro2 1.0.9 (registry+https://github.com/rust-lang/crates.io-index)", + "quote 1.0.3 (registry+https://github.com/rust-lang/crates.io-index)", + "syn 1.0.16 (registry+https://github.com/rust-lang/crates.io-index)", +] + +[[package]] name = "num-integer" version = "0.1.42" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -766,6 +777,7 @@ "checksum memchr 2.3.3 (registry+https://github.com/rust-lang/crates.io-index)" = "3728d817d99e5ac407411fa471ff9800a778d88a24685968b36824eaf4bee400" "checksum memmap 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)" = "6585fd95e7bb50d6cc31e20d4cf9afb4e2ba16c5846fc76793f11218da9c475b" "checksum memoffset 0.5.3 (registry+https://github.com/rust-lang/crates.io-index)" = "75189eb85871ea5c2e2c15abbdd541185f63b408415e5051f5cac122d8c774b9" +"checksum micro-timer 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)" = "16439fea388f712c1df7737ceb8f784d407844624b4796faf1e1bf8bbaa97445" "checksum num-integer 0.1.42 (registry+https://github.com/rust-lang/crates.io-index)" = "3f6ea62e9d81a77cd3ee9a2a5b9b609447857f3d358704331e4ef39eb247fcba" "checksum num-traits 0.2.11 (registry+https://github.com/rust-lang/crates.io-index)" = "c62be47e61d1842b9170f0fdeec8eba98e60e90e5446449a0545e5152acd7096" "checksum num_cpus 1.12.0 (registry+https://github.com/rust-lang/crates.io-index)" = "46203554f085ff89c235cd12f7075f3233af9b11ed7c9e16dfe2560d03313ce6" diff -r 82f51ab7a2dd -r d880805d5442 rust/hg-core/Cargo.toml --- a/rust/hg-core/Cargo.toml Fri Mar 06 18:08:13 2020 +0100 +++ b/rust/hg-core/Cargo.toml Fri Mar 06 18:08:23 2020 +0100 @@ -22,6 +22,7 @@ twox-hash = "1.5.0" same-file = "1.0.6" crossbeam = "0.7.3" +micro-timer = "0.1.2" log = "0.4.8" [dev-dependencies] diff -r 82f51ab7a2dd -r d880805d5442 rust/hg-core/src/dirstate/parsers.rs --- a/rust/hg-core/src/dirstate/parsers.rs Fri Mar 06 18:08:13 2020 +0100 +++ b/rust/hg-core/src/dirstate/parsers.rs Fri Mar 06 18:08:23 2020 +0100 @@ -9,6 +9,7 @@ DirstateEntry, DirstatePackError, DirstateParents, DirstateParseError, }; use byteorder::{BigEndian, ReadBytesExt, WriteBytesExt}; +use micro_timer::timed; use std::convert::{TryFrom, TryInto}; use std::io::Cursor; use std::time::Duration; @@ -20,6 +21,7 @@ // TODO parse/pack: is mutate-on-loop better for performance? +#[timed] pub fn parse_dirstate( state_map: &mut StateMap, copy_map: &mut CopyMap, diff -r 82f51ab7a2dd -r d880805d5442 rust/hg-core/src/dirstate/status.rs --- a/rust/hg-core/src/dirstate/status.rs Fri Mar 06 18:08:13 2020 +0100 +++ b/rust/hg-core/src/dirstate/status.rs Fri Mar 06 18:08:23 2020 +0100 @@ -25,6 +25,7 @@ PatternError, }; use lazy_static::lazy_static; +use micro_timer::timed; use rayon::prelude::*; use std::{ borrow::Cow, @@ -211,6 +212,7 @@ /// Get stat data about the files explicitly specified by match. /// TODO subrepos +#[timed] fn walk_explicit<'a>( files: Option<&'a HashSet<&HgPath>>, dmap: &'a DirstateMap, @@ -513,6 +515,7 @@ /// /// This takes a mutable reference to the results to account for the `extend` /// in timings +#[timed] fn traverse<'a>( matcher: &'a (impl Matcher + Sync), root_dir: impl AsRef + Sync + Send + Copy, @@ -606,6 +609,7 @@ /// This takes a mutable reference to the results to account for the `extend` /// in timings +#[timed] fn extend_from_dmap<'a>( dmap: &'a DirstateMap, root_dir: impl AsRef + Sync + Send, @@ -630,6 +634,7 @@ pub bad: Vec<(Cow<'a, HgPath>, BadMatch)>, } +#[timed] fn build_response<'a>( results: impl IntoIterator, Dispatch)>, ) -> (Vec>, DirstateStatus<'a>) { @@ -710,6 +715,7 @@ /// This takes a mutable reference to the results to account for the `extend` /// in timings +#[timed] fn handle_unknowns<'a>( dmap: &'a DirstateMap, matcher: &(impl Matcher + Sync), @@ -792,6 +798,7 @@ /// This is the current entry-point for `hg-core` and is realistically unusable /// outside of a Python context because its arguments need to provide a lot of /// information that will not be necessary in the future. +#[timed] pub fn status<'a: 'c, 'b: 'c, 'c>( dmap: &'a DirstateMap, matcher: &'b (impl Matcher + Sync), diff -r 82f51ab7a2dd -r d880805d5442 rust/hg-core/src/lib.rs --- a/rust/hg-core/src/lib.rs Fri Mar 06 18:08:13 2020 +0100 +++ b/rust/hg-core/src/lib.rs Fri Mar 06 18:08:23 2020 +0100 @@ -35,6 +35,10 @@ use std::collections::HashMap; use twox_hash::RandomXxHashBuilder64; +/// This is a contract between the `micro-timer` crate and us, to expose +/// the `log` crate as `crate::log`. +use log; + pub type LineNumber = usize; /// Rust's default hasher is too slow because it tries to prevent collision diff -r 82f51ab7a2dd -r d880805d5442 rust/hg-core/src/matchers.rs --- a/rust/hg-core/src/matchers.rs Fri Mar 06 18:08:13 2020 +0100 +++ b/rust/hg-core/src/matchers.rs Fri Mar 06 18:08:23 2020 +0100 @@ -24,6 +24,7 @@ PatternSyntax, }; +use micro_timer::timed; use std::collections::HashSet; use std::fmt::{Display, Error, Formatter}; use std::iter::FromIterator; @@ -548,6 +549,7 @@ /// Parses all "ignore" files with their recursive includes and returns a /// function that checks whether a given file (in the general sense) should be /// ignored. +#[timed] pub fn get_ignore_function<'a>( all_pattern_files: &[impl AsRef], root_dir: impl AsRef,