Use slow or imprecise clock

Cargo.toml

@@ -1,23 +1,6 @@
-[workspace]
-members = [
-  "./",
-  "examples/counter_timer_gauge/",
-  "examples/multi_outs/",
-  "examples/macro_outs/",
-  "examples/aggregate_print/",
-  "examples/summary_print/",
-  "examples/async_print/",
-  "examples/custom_publish/",
-  "examples/raw_log/",
-  "examples/graphite/",
-  "examples/static_metrics/",
-  "examples/scoped_print/",
-  "examples/sampling/",
-]
-
 [package]
 name = "dipstick"
-version = "0.6.5"
+version = "0.6.6"
 authors = ["Francis Lalonde <fralalonde@gmail.com>"]
 
 description = """A fast and modular metrics library decoupling app instrumentation from reporting backend.

README.md

@@ -98,7 +98,7 @@ For better performance and easy maintenance, metrics should usually be predefine
 #[macro_use] extern crate lazy_static;
 use dipstick::*;
 
-app_metric!(String, APP_METRICS, app_metrics(to_stdout()));
+app_metrics!(String, APP_METRICS = app_metrics(to_stdout()));
 app_counter!(String, APP_METRICS, {
     COUNTER_A: "counter_a",
 });

README.md.skt.md

@@ -18,7 +18,7 @@ fn main() {{
     run().ok();
 }}
 
-fn run() -> Result<(), Error> {{
+fn run() -> Result<(), dipstick::error::Error> {{
     {}
     Ok(())
 }}

examples/aggregate_print/Cargo.toml

@@ -1,7 +0,0 @@
-[package]
-name = "aggregate_print"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }

examples/async_print/Cargo.toml

@@ -1,7 +0,0 @@
-[package]
-name = "queued"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }

examples/counter_timer_gauge/Cargo.toml

@@ -1,7 +0,0 @@
-[package]
-name = "counter_timer_gauge"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }

examples/custom_publish/Cargo.toml

@@ -1,8 +0,0 @@
-[package]
-name = "custom_publish"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }
-

examples/graphite.rs

@@ -1,14 +1,11 @@
 //! A sample application sending ad-hoc counter values both to statsd _and_ to stdout.
 
-extern crate badlog;
 extern crate dipstick;
 
 use dipstick::*;
 use std::time::Duration;
 
 fn main() {
-    badlog::init(Some("info"));
-
     let metrics = app_metrics(
         to_graphite("localhost:2003").expect("Connecting")
             .with_namespace(&["my", "app"][..]));

examples/graphite/Cargo.toml

@@ -1,8 +0,0 @@
-[package]
-name = "graphite"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }
-badlog = "1.0"

examples/macro_outs/Cargo.toml

@@ -1,8 +0,0 @@
-[package]
-name = "macro_outs"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }
-lazy_static = "0.2"

examples/multi_outs/Cargo.toml

@@ -1,7 +0,0 @@
-[package]
-name = "multi_print"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }

examples/raw_log/Cargo.toml

@@ -1,7 +0,0 @@
-[package]
-name = "raw_sink"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }

examples/raw_log/src/main.rs

@@ -1,19 +0,0 @@
-//! Use the metrics backend directly to log a metric value.
-//! Applications should use the metrics()-provided instruments instead.
-
-extern crate dipstick;
-
-use dipstick::*;
-
-fn main() {
-    raw_write()
-}
-
-pub fn raw_write() {
-    // setup dual metric channels
-    let metrics_log = to_log();
-
-    // define and send metrics using raw channel API
-    let counter = metrics_log.define_metric(Kind::Counter, "count_a", FULL_SAMPLING_RATE);
-    metrics_log.open_scope(true).write(&counter, 1);
-}

examples/sampling/Cargo.toml

@@ -1,7 +0,0 @@
-[package]
-name = "sampling"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }

examples/scoped_print/Cargo.toml

@@ -1,7 +0,0 @@
-[package]
-name = "scoped_print"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }

examples/static_metrics/Cargo.toml

@@ -1,8 +0,0 @@
-[package]
-name = "static_metrics"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }
-lazy_static = "0.2.9"

examples/summary_print/Cargo.toml

@@ -1,7 +0,0 @@
-[package]
-name = "summary_print"
-version = "0.0.0"
-workspace = "../../"
-
-[dependencies]
-dipstick = { path = '../../' }

src/core.rs

@@ -5,8 +5,9 @@
 use self::Kind::*;
 use self::ScopeCmd::*;
 
-use time;
 use std::sync::Arc;
+use chrono::{Local, DateTime};
+use time;
 
 // TODO define an 'AsValue' trait + impl for supported number types, then drop 'num' crate
 pub use num::ToPrimitive;
@@ -18,18 +19,43 @@ pub type Value = u64;
 #[derive(Debug, Copy, Clone)]
 /// A handle to the start time of a counter.
 /// Wrapped so it may be changed safely later.
-pub struct TimeHandle(u64);
+pub struct TimeHandle(i64);
+
+/// takes 250ns but works every time
+pub fn slow_clock_micros() -> i64 {
+    let local: DateTime<Local> = Local::now();
+    let mut micros = local.timestamp() * 1_000_000;
+    micros += local.timestamp_subsec_micros() as i64;
+    micros
+}
+
+/// takes 25ns but fails to advance time on occasion
+pub fn imprecise_clock_micros() -> i64 {
+    (time::precise_time_ns() / 1000) as i64
+}
+
+// another quick way
+//fn now_micros() -> i64 {
+//    let t = time::get_time();
+//    (t.sec * 1_000_000) + (t.nsec as i64 / 1000)
+//}
 
 impl TimeHandle {
+
     /// Get a handle on current time.
     /// Used by the TimerMetric start_time() method.
     pub fn now() -> TimeHandle {
-        TimeHandle(time::precise_time_ns())
+        TimeHandle(imprecise_clock_micros())
     }
 
     /// Get the elapsed time in microseconds since TimeHandle was obtained.
     pub fn elapsed_us(self) -> Value {
-        (TimeHandle::now().0 - self.0) / 1_000
+        (TimeHandle::now().0 - self.0) as Value
+    }
+
+    /// Get the elapsed time in microseconds since TimeHandle was obtained.
+    pub fn elapsed_ms(self) -> Value {
+        self.elapsed_us() / 1_000
     }
 }
 
@@ -393,3 +419,79 @@ impl<M: Clone> ScopeTimer<M> {
         value
     }
 }
+
+//#[cfg(test)]
+//mod test {
+//    use core::*;
+//    use test;
+//    use std::f64;
+//
+//    const ITER: i64 = 5_000;
+//    const LOOP: i64 = 50000;
+//
+//    // a retarded, dirty and generally incorrect tentative at jitter measurement
+//    fn jitter(clock: fn() -> i64) {
+//        let mut first = 0;
+//        let mut last = 0;
+//        let mut min = 999_000_000;
+//        let mut max = -8888888;
+//        let mut delta_sum = 0;
+//        let mut dev2_sum = 0;
+//
+//        for i in 1..ITER {
+//            let ts = clock();
+//            test::black_box(for _j in 0..LOOP {});
+//            last = clock();
+//            let delta = last - ts;
+//
+//            delta_sum += delta;
+//            let mean = delta_sum / i;
+//
+//            let dev2 = (delta - mean) ^ 2;
+//            dev2_sum += dev2;
+//
+//            if delta > max {
+//                max = delta
+//            }
+//            if delta < min {
+//                min = delta
+//            }
+//        }
+//
+//        println!("runt {}", last - first);
+//        println!("mean {}", delta_sum / ITER);
+//        println!("dev2 {}", (dev2_sum as f64).sqrt() / ITER as f64);
+//        println!("min {}", min);
+//        println!("max {}", max);
+//    }
+//
+//
+//    #[test]
+//    fn jitter_local_now() {
+//        jitter(|| super::slow_clock_micros())
+//    }
+//
+//    #[test]
+//    fn jitter_precise_time_ns() {
+//        jitter(|| super::imprecise_clock_micros())
+//    }
+//
+//}
+
+#[cfg(feature = "bench")]
+mod bench {
+
+    use super::*;
+    use test;
+
+    #[bench]
+    fn get_slow_time(b: &mut test::Bencher) {
+        b.iter(|| test::black_box(slow_clock_micros()));
+    }
+
+    #[bench]
+    fn get_imprecise_time(b: &mut test::Bencher) {
+        b.iter(|| test::black_box(imprecise_clock_micros()));
+    }
+
+}

src/lib.rs

@@ -40,9 +40,6 @@ pub mod macros;
 pub mod core;
 pub use core::*;
 
-//pub mod dispatch;
-//pub use dispatch::*;
-
 mod output;
 pub use output::*;
 

src/scores.rs

@@ -1,5 +1,4 @@
 use std::mem;
-use chrono::{Local, DateTime};
 
 use core::*;
 use core::Kind::*;
@@ -43,20 +42,13 @@ pub struct Scoreboard {
     scores: [AtomicUsize; 5],
 }
 
-fn now() -> usize {
-    let local: DateTime<Local> = Local::now();
-    let mut millis = local.timestamp() as usize * 1000;
-    millis += local.timestamp_subsec_millis() as usize;
-    millis
-}
-
 impl Scoreboard {
     /// Create a new Scoreboard to track summary values of a metric
     pub fn new(kind: Kind, name: String) -> Self {
         Scoreboard {
             kind,
             name,
-            scores: unsafe { mem::transmute(Scoreboard::blank(now())) },
+            scores: unsafe { mem::transmute(Scoreboard::blank(slow_clock_micros() as usize)) },
         }
     }
 
@@ -100,10 +92,10 @@ impl Scoreboard {
 
     /// Map raw scores (if any) to applicable statistics
     pub fn reset(&self) -> Option<ScoreSnapshot> {
-        let now = now();
+        let now = slow_clock_micros() as usize;
         let mut scores = Scoreboard::blank(now);
         if self.snapshot(now, &mut scores) {
-            let duration_seconds = (now - scores[0]) as f64 / 1_000.0;
+            let duration_seconds = (now - scores[0]) as f64 / 1_000_000.0;
 
             let mut snapshot = Vec::new();
             match self.kind {
@@ -133,13 +125,8 @@ impl Scoreboard {
     }
 }
 
-fn average_rate(count: usize, time: f64, scores: &[usize], now: usize) -> f64 {
-    let avg = count as f64 / time;
-    if avg > 10_000_000.0 {
-        eprintln!("Computed anomalous rate of '{}'/s, count '{}'  / time '{}'s, start {}, stop {}", avg, count, time, scores[0], now);
-        return 0.0
-    }
-    avg
+fn average_rate(count: usize, time: f64, _scores: &[usize], _now: usize) -> f64 {
+    count as f64 / time
 }
 
 /// Spinlock until success or clear loss to concurrent update.
@@ -159,7 +146,8 @@ fn swap_if(counter: &AtomicUsize, new_value: usize, compare: fn(usize, usize) ->
 #[cfg(feature = "bench")]
 mod bench {
 
-    use super::*;
+    use scores::Scoreboard;
+    use core::Kind::*;
     use test;
 
     #[bench]
@@ -177,9 +165,8 @@ mod bench {
     #[bench]
     fn bench_score_snapshot(b: &mut test::Bencher) {
         let metric = Scoreboard::new(Counter, "event_a".to_string());
-        let now = time::precise_time_ns() as usize;
-        let mut scores = Scoreboard::blank(now);
-        b.iter(|| test::black_box(metric.snapshot(now, &mut scores)));
+        let mut scores = Scoreboard::blank(0);
+        b.iter(|| test::black_box(metric.snapshot(0, &mut scores)));
     }
 
 }