Add a logging_timer macro to te criterion next methods

Cargo.lock

@@ -53,8 +53,8 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "ca2925c4c290382f9d2fa3d1c1b6a63fa1427099721ecca4749b154cc9c25522"
 dependencies = [
  "askama_shared",
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "syn",
+ "syn 1.0.60",
 ]
 
 [[package]]
@@ -74,10 +74,10 @@ dependencies = [
  "nom",
  "num-traits",
  "percent-encoding",
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
  "serde",
- "syn",
+ "syn 1.0.60",
  "toml",
 ]
 
@@ -622,9 +622,9 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c287d25add322d9f9abdcdc5927ca398917996600182178774032e9f8258fedd"
 dependencies = [
  "proc-macro-hack",
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
 ]
 
 [[package]]
@@ -1184,6 +1184,28 @@ dependencies = [
  "cfg-if 1.0.0",
 ]
 
+[[package]]
+name = "logging_timer"
+version = "1.0.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "40d0c249955c17c2f8f86b5f501b16d2509ebbe775f7b1d1d2b1ba85ade2a793"
+dependencies = [
+ "log",
+ "logging_timer_proc_macros",
+]
+
+[[package]]
+name = "logging_timer_proc_macros"
+version = "1.0.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "482c2c28e6bcfe7c4274f82f701774d755e6aa873edfd619460fcd0966e0eb07"
+dependencies = [
+ "log",
+ "proc-macro2 0.4.30",
+ "quote 0.6.13",
+ "syn 0.15.44",
+]
+
 [[package]]
 name = "loom"
 version = "0.4.0"
@@ -1269,6 +1291,7 @@ dependencies = [
  "levenshtein_automata",
  "linked-hash-map",
  "log",
+ "logging_timer",
  "maplit",
  "meilisearch-tokenizer",
  "memmap",
@@ -1554,9 +1577,9 @@ checksum = "99b8db626e31e5b81787b9783425769681b347011cc59471e33ea46d2ea0cf55"
 dependencies = [
  "pest 2.1.3 (registry+https://github.com/rust-lang/crates.io-index)",
  "pest_meta",
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
 ]
 
 [[package]]
@@ -1632,9 +1655,9 @@ version = "0.4.27"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "65ad2ae56b6abe3a1ee25f15ee605bacadb9a764edaba9c2bf4103800d4a1895"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
 ]
 
 [[package]]
@@ -1643,9 +1666,9 @@ version = "1.0.5"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "758669ae3558c6f74bd2a18b41f7ac0b5a195aea6639d6a9b5e5d1ad5ba24c0b"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
 ]
 
 [[package]]
@@ -1713,9 +1736,9 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "da25490ff9892aab3fcf7c36f08cfb902dd3e71ca0f9f9517bea02a73a5ce38c"
 dependencies = [
  "proc-macro-error-attr",
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
  "version_check",
 ]
 
@@ -1725,8 +1748,8 @@ version = "1.0.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "a1be40180e52ecc98ad80b184934baf3d0d29f979574e439af5a55274b35f869"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
  "version_check",
 ]
 
@@ -1742,13 +1765,22 @@ version = "0.1.7"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "bc881b2c22681370c6a780e47af9840ef841837bc98118431d4e1868bd0c1086"
 
+[[package]]
+name = "proc-macro2"
+version = "0.4.30"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "cf3d2011ab5c909338f7887f4fc896d35932e29146c12c8d01da6b22a80ba759"
+dependencies = [
+ "unicode-xid 0.1.0",
+]
+
 [[package]]
 name = "proc-macro2"
 version = "1.0.24"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "1e0704ee1a7e00d7bb417d0770ea303c1bccbabf0ef1667dae92b5967f5f8a71"
 dependencies = [
- "unicode-xid",
+ "unicode-xid 0.2.1",
 ]
 
 [[package]]
@@ -1757,13 +1789,22 @@ version = "1.2.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0"
 
+[[package]]
+name = "quote"
+version = "0.6.13"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6ce23b6b870e8f94f81fb0a363d65d86675884b34a09043c81e5562f11c1f8e1"
+dependencies = [
+ "proc-macro2 0.4.30",
+]
+
 [[package]]
 name = "quote"
 version = "1.0.9"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c3d0b9745dc2debf507c8422de05d7226cc1f0644216dfdfead988f9b1ab32a7"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
 ]
 
 [[package]]
@@ -2047,9 +2088,9 @@ version = "1.0.123"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "9391c295d64fc0abb2c556bad848f33cb8296276b1ad2677d1ae1ace4f258f31"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
 ]
 
 [[package]]
@@ -2199,9 +2240,20 @@ checksum = "5ba9cdfda491b814720b6b06e0cac513d922fc407582032e8706e9f137976f90"
 dependencies = [
  "heck",
  "proc-macro-error",
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
+]
+
+[[package]]
+name = "syn"
+version = "0.15.44"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9ca4b3b69a77cbe1ffc9e198781b7acb0c7365a883670e8f1c1bc66fba79a5c5"
+dependencies = [
+ "proc-macro2 0.4.30",
+ "quote 0.6.13",
+ "unicode-xid 0.1.0",
 ]
 
 [[package]]
@@ -2210,9 +2262,9 @@ version = "1.0.60"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c700597eca8a5a762beb35753ef6b94df201c81cca676604f547495a0d7f0081"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "unicode-xid",
+ "unicode-xid 0.2.1",
 ]
 
 [[package]]
@@ -2230,10 +2282,10 @@ version = "0.12.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "b834f2d66f734cb897113e34aaff2f1ab4719ca946f9a7358dba8f8064148701"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
- "unicode-xid",
+ "unicode-xid 0.2.1",
 ]
 
 [[package]]
@@ -2359,9 +2411,9 @@ version = "0.2.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e44da00bfc73a25f814cd8d7e57a68a5c31b74b3152a0a1d1f590c97ed06265a"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
 ]
 
 [[package]]
@@ -2522,6 +2574,12 @@ version = "0.1.8"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "9337591893a19b88d8d87f2cec1e73fad5cdfd10e5a6f349f498ad6ea2ffb1e3"
 
+[[package]]
+name = "unicode-xid"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "fc72304796d0818e357ead4e000d19c9c174ab23dc11093ac919054d20a6a7fc"
+
 [[package]]
 name = "unicode-xid"
 version = "0.2.1"
@@ -2653,9 +2711,9 @@ dependencies = [
  "bumpalo",
  "lazy_static",
  "log",
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
  "wasm-bindgen-shared",
 ]
 
@@ -2665,7 +2723,7 @@ version = "0.2.70"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "3b8853882eef39593ad4174dd26fc9865a64e84026d223f63bb2c42affcbba2c"
 dependencies = [
- "quote",
+ "quote 1.0.9",
  "wasm-bindgen-macro-support",
 ]
 
@@ -2675,9 +2733,9 @@ version = "0.2.70"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "4133b5e7f2a531fa413b3a1695e925038a05a71cf67e87dafa295cb645a01385"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "quote",
+ "quote 1.0.9",
- "syn",
+ "syn 1.0.60",
  "wasm-bindgen-backend",
  "wasm-bindgen-shared",
 ]
@@ -2782,8 +2840,8 @@ version = "0.2.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "d498dbd1fd7beb83c86709ae1c33ca50942889473473d287d56ce4770a18edfb"
 dependencies = [
- "proc-macro2",
+ "proc-macro2 1.0.24",
- "syn",
+ "syn 1.0.60",
  "synstructure",
 ]
 

milli/Cargo.toml

@@ -45,6 +45,7 @@ itertools = "0.10.0"
 
 # logging
 log = "0.4.14"
+logging_timer = "1.0.0"
 
 # We temporarily depend on this crate just to fix this issue
 # https://github.com/bheisler/TinyTemplate/pull/17

milli/src/search/criteria/asc_desc.rs

@@ -146,6 +146,7 @@ impl<'t> AscDesc<'t> {
 }
 
 impl<'t> Criterion for AscDesc<'t> {
+    #[logging_timer::time("AscDesc::{}")]
     fn next(&mut self, wdcache: &mut WordDerivationsCache) -> anyhow::Result<Option<CriterionResult>> {
         loop {
             debug!("Facet {}({}) iteration",

milli/src/search/criteria/fetcher.rs

@@ -48,6 +48,7 @@ impl<'t> Fetcher<'t> {
 }
 
 impl<'t> Criterion for Fetcher<'t> {
+    #[logging_timer::time("Fetcher::{}")]
     fn next(&mut self, wdcache: &mut WordDerivationsCache) -> anyhow::Result<Option<CriterionResult>> {
         use Candidates::{Allowed, Forbidden};
         loop {

milli/src/search/criteria/proximity.rs

@@ -56,6 +56,7 @@ impl<'t> Proximity<'t> {
 }
 
 impl<'t> Criterion for Proximity<'t> {
+    #[logging_timer::time("Proximity::{}")]
     fn next(&mut self, wdcache: &mut WordDerivationsCache) -> anyhow::Result<Option<CriterionResult>> {
         use Candidates::{Allowed, Forbidden};
         loop {

milli/src/search/criteria/typo.rs

@@ -53,6 +53,7 @@ impl<'t> Typo<'t> {
 }
 
 impl<'t> Criterion for Typo<'t> {
+    #[logging_timer::time("Typo::{}")]
     fn next(&mut self, wdcache: &mut WordDerivationsCache) -> anyhow::Result<Option<CriterionResult>> {
         use Candidates::{Allowed, Forbidden};
         loop {

milli/src/search/criteria/words.rs

@@ -47,6 +47,7 @@ impl<'t> Words<'t> {
 }
 
 impl<'t> Criterion for Words<'t> {
+    #[logging_timer::time("Words::{}")]
     fn next(&mut self, wdcache: &mut WordDerivationsCache) -> anyhow::Result<Option<CriterionResult>> {
         use Candidates::{Allowed, Forbidden};
         loop {