Patchwork D8253: hg-core: add function timing information

login
register
mail settings
Submitter phabricator
Date March 6, 2020, 5:52 p.m.
Message ID <differential-rev-PHID-DREV-rvzjc46hkxgtfmqy5e3e-req@mercurial-scm.org>
Download mbox | patch
Permalink /patch/45569/
State Superseded
Headers show

Comments

phabricator - March 6, 2020, 5:52 p.m.
Alphare created this revision.
Herald added a subscriber: mercurial-devel.
Herald added a reviewer: hg-reviewers.

REVISION SUMMARY
  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.

REPOSITORY
  rHG Mercurial

BRANCH
  default

REVISION DETAIL
  https://phab.mercurial-scm.org/D8253

AFFECTED FILES
  rust/Cargo.lock
  rust/hg-core/Cargo.toml
  rust/hg-core/src/dirstate/parsers.rs
  rust/hg-core/src/dirstate/status.rs
  rust/hg-core/src/lib.rs
  rust/hg-core/src/matchers.rs

CHANGE DETAILS




To: Alphare, #hg-reviewers
Cc: mercurial-devel

Patch

diff --git a/rust/hg-core/src/matchers.rs b/rust/hg-core/src/matchers.rs
--- a/rust/hg-core/src/matchers.rs
+++ b/rust/hg-core/src/matchers.rs
@@ -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<Path>],
     root_dir: impl AsRef<Path>,
diff --git a/rust/hg-core/src/lib.rs b/rust/hg-core/src/lib.rs
--- a/rust/hg-core/src/lib.rs
+++ b/rust/hg-core/src/lib.rs
@@ -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 --git a/rust/hg-core/src/dirstate/status.rs b/rust/hg-core/src/dirstate/status.rs
--- a/rust/hg-core/src/dirstate/status.rs
+++ b/rust/hg-core/src/dirstate/status.rs
@@ -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<Path> + 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<Path> + Sync + Send,
@@ -630,6 +634,7 @@ 
     pub bad: Vec<(Cow<'a, HgPath>, BadMatch)>,
 }
 
+#[timed]
 fn build_response<'a>(
     results: impl IntoIterator<Item = (Cow<'a, HgPath>, Dispatch)>,
 ) -> (Vec<Cow<'a, HgPath>>, 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 --git a/rust/hg-core/src/dirstate/parsers.rs b/rust/hg-core/src/dirstate/parsers.rs
--- a/rust/hg-core/src/dirstate/parsers.rs
+++ b/rust/hg-core/src/dirstate/parsers.rs
@@ -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 --git a/rust/hg-core/Cargo.toml b/rust/hg-core/Cargo.toml
--- a/rust/hg-core/Cargo.toml
+++ b/rust/hg-core/Cargo.toml
@@ -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 --git a/rust/Cargo.lock b/rust/Cargo.lock
--- a/rust/Cargo.lock
+++ b/rust/Cargo.lock
@@ -243,6 +243,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)",
@@ -317,6 +318,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"
@@ -783,6 +794,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"