changeset 49986:c15b415d1bff

rust: use `logging_timer` instead of `micro_timer`

I am the author of `micro_timer`.
I built it at the time because I couldn't find a crate that was simple to use
and flexible to do function timing with. Turns out I just couldn't find it
because crates.io's search isn't all that great, or maybe I didn't look hard
enough.

`logging_timer` is better in every way:
    - supports changing the logging level
    - supports start and end logging
    - supports intermediary messages
    - supports inline macros
    - supports formatting the output
    - better IDE/tree-sitter integration thanks to a more robust proc macro

I also changed all uses to one-liners, so it's easier to copy-paste.

--- a/rust/Cargo.lock	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/Cargo.lock	Fri Jan 06 18:52:04 2023 +0100
@@ -536,8 +536,8 @@
  "lazy_static",
  "libc",
  "log",
+ "logging_timer",
  "memmap2",
- "micro-timer",
  "once_cell",
  "ouroboros",
  "pretty_assertions",
@@ -705,6 +705,28 @@
 ]
 
 [[package]]
+name = "logging_timer"
+version = "1.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "64e96f261d684b7089aa576bb74e823241dccd994b27d30fabf1dcb3af284fe9"
+dependencies = [
+ "log",
+ "logging_timer_proc_macros",
+]
+
+[[package]]
+name = "logging_timer_proc_macros"
+version = "1.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "10a9062912d7952c5588cc474795e0b9ee008e7e6781127945b85413d4b99d81"
+dependencies = [
+ "log",
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
+[[package]]
 name = "memchr"
 version = "2.5.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -730,28 +752,6 @@
 ]
 
 [[package]]
-name = "micro-timer"
-version = "0.4.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "5de32cb59a062672560d6f0842c4aa7714727457b9fe2daf8987d995a176a405"
-dependencies = [
- "micro-timer-macros",
- "scopeguard",
-]
-
-[[package]]
-name = "micro-timer-macros"
-version = "0.4.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "cee948b94700125b52dfb68dd17c19f6326696c1df57f92c05ee857463c93ba1"
-dependencies = [
- "proc-macro2",
- "quote",
- "scopeguard",
- "syn",
-]
-
-[[package]]
 name = "miniz_oxide"
 version = "0.5.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1094,7 +1094,7 @@
  "home",
  "lazy_static",
  "log",
- "micro-timer",
+ "logging_timer",
  "rayon",
  "regex",
  "users",

--- a/rust/hg-core/Cargo.toml	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/hg-core/Cargo.toml	Fri Jan 06 18:52:04 2023 +0100
@@ -19,6 +19,7 @@
 itertools = "0.10.5"
 lazy_static = "1.4.0"
 libc = "0.2.137"
+logging_timer = "1.1.0"
 ouroboros = "0.15.5"
 rand = "0.8.5"
 rand_pcg = "0.3.1"
@@ -31,7 +32,6 @@
 tempfile = "3.3.0"
 thread_local = "1.1.4"
 crossbeam-channel = "0.5.6"
-micro-timer = "0.4.0"
 log = "0.4.17"
 memmap2 = { version = "0.5.8", features = ["stable_deref_trait"] }
 zstd = "0.11.2"

--- a/rust/hg-core/src/dirstate/parsers.rs	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/hg-core/src/dirstate/parsers.rs	Fri Jan 06 18:52:04 2023 +0100
@@ -8,7 +8,6 @@
 use crate::{dirstate::EntryState, DirstateEntry, DirstateParents};
 use byteorder::{BigEndian, WriteBytesExt};
 use bytes_cast::{unaligned, BytesCast};
-use micro_timer::timed;
 
 /// Parents are stored in the dirstate as byte hashes.
 pub const PARENT_SIZE: usize = 20;
@@ -29,7 +28,7 @@
     Ok(parents)
 }
 
-#[timed]
+#[logging_timer::time("trace")]
 pub fn parse_dirstate(contents: &[u8]) -> Result<ParseResult, HgError> {
     let mut copies = Vec::new();
     let mut entries = Vec::new();

--- a/rust/hg-core/src/dirstate_tree/dirstate_map.rs	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/hg-core/src/dirstate_tree/dirstate_map.rs	Fri Jan 06 18:52:04 2023 +0100
@@ -1,5 +1,4 @@
 use bytes_cast::BytesCast;
-use micro_timer::timed;
 use std::borrow::Cow;
 use std::path::PathBuf;
 
@@ -454,7 +453,7 @@
         }
     }
 
-    #[timed]
+    #[logging_timer::time("trace")]
     pub fn new_v2(
         on_disk: &'on_disk [u8],
         data_size: usize,
@@ -467,7 +466,7 @@
         }
     }
 
-    #[timed]
+    #[logging_timer::time("trace")]
     pub fn new_v1(
         on_disk: &'on_disk [u8],
     ) -> Result<(Self, Option<DirstateParents>), DirstateError> {
@@ -1208,7 +1207,7 @@
         })
     }
 
-    #[timed]
+    #[logging_timer::time("trace")]
     pub fn pack_v1(
         &self,
         parents: DirstateParents,
@@ -1248,7 +1247,7 @@
     /// appended to the existing data file whose content is at
     /// `map.on_disk` (true), instead of written to a new data file
     /// (false), and the previous size of data on disk.
-    #[timed]
+    #[logging_timer::time("trace")]
     pub fn pack_v2(
         &self,
         can_append: bool,

--- a/rust/hg-core/src/dirstate_tree/status.rs	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/hg-core/src/dirstate_tree/status.rs	Fri Jan 06 18:52:04 2023 +0100
@@ -19,7 +19,6 @@
 use crate::PatternFileWarning;
 use crate::StatusError;
 use crate::StatusOptions;
-use micro_timer::timed;
 use once_cell::sync::OnceCell;
 use rayon::prelude::*;
 use sha1::{Digest, Sha1};
@@ -39,7 +38,7 @@
 /// and its use of `itertools::merge_join_by`. When reaching a path that only
 /// exists in one of the two trees, depending on information requested by
 /// `options` we may need to traverse the remaining subtree.
-#[timed]
+#[logging_timer::time("trace")]
 pub fn status<'dirstate>(
     dmap: &'dirstate mut DirstateMap,
     matcher: &(dyn Matcher + Sync),

--- a/rust/hg-core/src/lib.rs	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/hg-core/src/lib.rs	Fri Jan 06 18:52:04 2023 +0100
@@ -48,10 +48,6 @@
 use std::fmt;
 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

--- a/rust/hg-core/src/matchers.rs	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/hg-core/src/matchers.rs	Fri Jan 06 18:52:04 2023 +0100
@@ -30,8 +30,6 @@
 use std::ops::Deref;
 use std::path::{Path, PathBuf};
 
-use micro_timer::timed;
-
 #[derive(Debug, PartialEq)]
 pub enum VisitChildrenSet {
     /// Don't visit anything
@@ -611,7 +609,7 @@
 /// This can fail when the pattern is invalid or not supported by the
 /// underlying engine (the `regex` crate), for instance anything with
 /// back-references.
-#[timed]
+#[logging_timer::time("trace")]
 fn re_matcher(pattern: &[u8]) -> PatternResult<RegexMatcher> {
     use std::io::Write;
 

--- a/rust/rhg/Cargo.toml	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/rhg/Cargo.toml	Fri Jan 06 18:52:04 2023 +0100
@@ -16,7 +16,7 @@
 home = "0.5.4"
 lazy_static = "1.4.0"
 log = "0.4.17"
-micro-timer = "0.4.0"
+logging_timer = "1.1.0"
 regex = "1.7.0"
 env_logger = "0.9.3"
 format-bytes = "0.3.0"

--- a/rust/rhg/src/commands/cat.rs	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/rhg/src/commands/cat.rs	Fri Jan 06 18:52:04 2023 +0100
@@ -3,7 +3,6 @@
 use format_bytes::format_bytes;
 use hg::operations::cat;
 use hg::utils::hg_path::HgPathBuf;
-use micro_timer::timed;
 use std::ffi::OsString;
 use std::os::unix::prelude::OsStrExt;
 
@@ -31,7 +30,7 @@
         .about(HELP_TEXT)
 }
 
-#[timed]
+#[logging_timer::time("trace")]
 pub fn run(invocation: &crate::CliInvocation) -> Result<(), CommandError> {
     let cat_enabled_default = true;
     let cat_enabled = invocation.config.get_option(b"rhg", b"cat")?;

--- a/rust/rhg/src/commands/debugdata.rs	Thu Jan 12 16:15:51 2023 +0000
+++ b/rust/rhg/src/commands/debugdata.rs	Fri Jan 06 18:52:04 2023 +0100
@@ -2,7 +2,6 @@
 use clap::Arg;
 use clap::ArgGroup;
 use hg::operations::{debug_data, DebugDataKind};
-use micro_timer::timed;
 
 pub const HELP_TEXT: &str = "
 Dump the contents of a data file revision
@@ -36,7 +35,7 @@
         .about(HELP_TEXT)
 }
 
-#[timed]
+#[logging_timer::time("trace")]
 pub fn run(invocation: &crate::CliInvocation) -> Result<(), CommandError> {
     let args = invocation.subcommand_args;
     let rev = args