Parse fractional seconds into a Duration directly.

Parsing into an f64 then separately truncating to an int and multiplying
the fractional part by 1_000_000_000 introduced errors in the fractional
part since frequently abc.xyz cannot produce 0.xyz as an f64, but has
to have 0.xyz0000001 or something like that.

Author: marshallpierce

benches/record.rs

@@ -175,7 +175,9 @@ fn do_add_benchmark<F: Fn() -> Histogram<u64>>(
         addends.push(h);
     }
 
-    b.iter(|| for h in addends.iter() {
-        accum.add(h).unwrap();
+    b.iter(|| {
+        for h in addends.iter() {
+            accum.add(h).unwrap();
+        }
     })
 }

src/serialization/benchmarks.rs

@@ -63,8 +63,10 @@ fn do_varint_write_rand(b: &mut Bencher, range: Range<u64>) {
     }
 
     let mut buf = [0; 9];
-    b.iter(|| for i in vec.iter() {
-        let _ = varint_write(*i, &mut buf);
+    b.iter(|| {
+        for i in vec.iter() {
+            let _ = varint_write(*i, &mut buf);
+        }
     });
 }
 

src/serialization/interval_log/mod.rs

@@ -166,7 +166,7 @@ extern crate base64;
 use std::{fmt, io, ops, str, time};
 use std::fmt::Write;
 
-use nom::{double, IResult};
+use nom::{double, is_digit, ErrorKind, IResult};
 
 use super::super::{Counter, Histogram};
 use super::Serializer;
@@ -450,9 +450,8 @@ impl<'a> ops::Deref for Tag<'a> {
 #[derive(PartialEq, Debug)]
 pub struct IntervalLogHistogram<'a> {
     tag: Option<Tag<'a>>,
-    start_timestamp: f64,
-    // lazily map to Duration to save parsing time and a few bytes of space on ILH
-    duration: f64,
+    start_timestamp: time::Duration,
+    duration: time::Duration,
     max: f64,
     encoded_histogram: &'a str,
 }
@@ -470,12 +469,12 @@ impl<'a> IntervalLogHistogram<'a> {
     /// the log, in which case you may wish to consider this number as a delta vs those timestamps.
     /// See the module-level documentation about timestamps.
     pub fn start_timestamp(&self) -> time::Duration {
-        fp_seconds_as_duration(self.start_timestamp)
+        self.start_timestamp
     }
 
     /// Duration of the interval in seconds.
     pub fn duration(&self) -> time::Duration {
-        fp_seconds_as_duration(self.duration)
+        self.duration
     }
 
     /// Max value in the encoded histogram
@@ -506,9 +505,9 @@ impl<'a> IntervalLogHistogram<'a> {
 #[allow(variant_size_differences)]
 pub enum LogEntry<'a> {
     /// Logs may include a StartTime. If present, it represents seconds since the epoch.
-    StartTime(f64),
+    StartTime(time::Duration),
     /// Logs may include a BaseTime. If present, it represents seconds since the epoch.
-    BaseTime(f64),
+    BaseTime(time::Duration),
     /// An individual interval histogram.
     Interval(IntervalLogHistogram<'a>),
 }
@@ -606,13 +605,6 @@ impl<'a> Iterator for IntervalLogIterator<'a> {
     }
 }
 
-fn fp_seconds_as_duration(fp_secs: f64) -> time::Duration {
-    let secs = fp_secs as u64;
-    // can't overflow because this can be at most 1 billion which is approx 2^30
-    let nsecs = (fp_secs.fract() * 1_000_000_000_f64) as u32;
-    time::Duration::new(secs, nsecs)
-}
-
 fn duration_as_fp_seconds(d: time::Duration) -> f64 {
     d.as_secs() as f64 + d.subsec_nanos() as f64 / 1_000_000_000_f64
 }
@@ -629,19 +621,19 @@ fn system_time_as_fp_seconds(time: time::SystemTime) -> f64 {
 named!(start_time<&[u8], LogEntry>,
     do_parse!(
         tag!("#[StartTime: ") >>
-        n: double >>
+        dur: fract_sec_duration >>
         char!(' ') >>
         take_until_and_consume!("\n") >>
-        (LogEntry::StartTime(n))
+        (LogEntry::StartTime(dur))
 ));
 
 named!(base_time<&[u8], LogEntry>,
     do_parse!(
         tag!("#[BaseTime: ") >>
-        n: double >>
+        dur: fract_sec_duration >>
         char!(' ') >>
         take_until_and_consume!("\n") >>
-        (LogEntry::BaseTime(n))
+        (LogEntry::BaseTime(dur))
 ));
 
 named!(interval_hist<&[u8], LogEntry>,
@@ -652,9 +644,9 @@ named!(interval_hist<&[u8], LogEntry>,
                     map!(pair!(tag!("Tag="), take_until_and_consume!(",")), |p| p.1),
                     str::from_utf8),
                 |s| Tag(s))) >>
-        start_timestamp: double >>
+        start_timestamp: fract_sec_duration >>
         char!(',') >>
-        duration: double >>
+        duration: fract_sec_duration >>
         char!(',') >>
         max: double >>
         char!(',') >>
@@ -669,7 +661,8 @@ named!(interval_hist<&[u8], LogEntry>,
     )
 );
 
-named!(log_entry<&[u8], LogEntry>, alt_complete!(start_time | base_time | interval_hist));
+named!(log_entry<&[u8], LogEntry>,
+    alt_complete!(start_time | base_time | interval_hist));
 
 named!(comment_line<&[u8], ()>,
     do_parse!(tag!("#") >> take_until_and_consume!("\n") >> (()))
@@ -681,5 +674,44 @@ named!(legend<&[u8], ()>,
 
 named!(ignored_line<&[u8], ()>, alt!(comment_line | legend));
 
+fn fract_sec_duration(input: &[u8]) -> IResult<&[u8], time::Duration> {
+    match fract_sec_tuple(input) {
+        IResult::Done(rest, data) => {
+            let (secs, nanos_str) = data;
+
+            // only read up to 9 digits since we can only support nanos, not smaller precision
+            let nanos_parse_res = if nanos_str.len() > 9 {
+                nanos_str[0..9].parse::<u32>()
+            } else if nanos_str.len() == 9 {
+                nanos_str.parse::<u32>()
+            } else {
+                nanos_str
+                    .parse::<u32>()
+                    // subtraction will not overflow because len is < 9
+                    .map(|n| n * 10_u32.pow(9 - nanos_str.len() as u32))
+            };
+
+            if let Ok(nanos) = nanos_parse_res {
+                return IResult::Done(rest, time::Duration::new(secs, nanos));
+            }
+
+            // nanos were invalid utf8. We don't expose these errors, so don't bother defining a
+            // custom error type.
+            return IResult::Error(ErrorKind::Custom(0));
+        }
+        IResult::Error(e) => return IResult::Error(e),
+        IResult::Incomplete(n) => return IResult::Incomplete(n),
+    }
+}
+
+named!(fract_sec_tuple<&[u8], (u64, &str)>,
+    do_parse!(
+        secs: flat_map!(recognize!(take_until!(".")), parse_to!(u64)) >>
+        tag!(".") >>
+        nanos_str: map_res!(take_while1!(is_digit), str::from_utf8) >>
+        (secs, nanos_str)
+    )
+);
+
 #[cfg(test)]
 mod tests;

src/serialization/interval_log/tests.rs

@@ -1,3 +1,7 @@
+extern crate rand;
+
+use self::rand::Rng;
+
 use std::{iter, time};
 use std::ops::Add;
 
@@ -72,7 +76,12 @@ fn write_comment_control_characters_still_parseable() {
     assert_eq!(&expected, str::from_utf8(&buf[..]).unwrap());
 
     let mut i = IntervalLogIterator::new(&buf);
-    assert_eq!(Some(Ok(LogEntry::StartTime(123.456))), i.next());
+    assert_eq!(
+        Some(Ok(
+            LogEntry::StartTime(time::Duration::new(123, 456_000_000))
+        )),
+        i.next()
+    );
     assert_eq!(None, i.next());
 }
 
@@ -214,13 +223,73 @@ fn write_base_time() {
     );
 }
 
+#[test]
+fn parse_duration_full_ns() {
+    let (rest, dur) = fract_sec_duration(b"123456.789012345foo").unwrap();
+
+    assert_eq!(time::Duration::new(123456, 789_012_345), dur);
+    assert_eq!(b"foo", rest);
+}
+
+#[test]
+fn parse_duration_scale_ns() {
+    let (rest, dur) = fract_sec_duration(b"123456.789012foo").unwrap();
+
+    assert_eq!(time::Duration::new(123456, 789_012_000), dur);
+    assert_eq!(b"foo", rest);
+}
+
+#[test]
+fn parse_duration_too_many_ns() {
+    let (rest, dur) = fract_sec_duration(b"123456.7890123456foo").unwrap();
+
+    // consumes all the numbers, but only parses the first 9
+    assert_eq!(time::Duration::new(123456, 789_012_345), dur);
+    assert_eq!(b"foo", rest);
+}
+
+#[test]
+fn duration_fp_roundtrip_accuracy() {
+    let mut rng = rand::thread_rng();
+
+    let mut buf = String::new();
+    let mut errors = Vec::new();
+    for _ in 0..100_000 {
+        buf.clear();
+
+        // pick seconds
+        let secs = rng.gen_range(0, 2_000_000_000);
+        // pick nsecs that only has ms accuracy
+        let nsecs = rng.gen_range(0, 1000) * 1000_000;
+
+        let dur = time::Duration::new(secs, nsecs);
+        let fp_secs = duration_as_fp_seconds(dur);
+
+        write!(&mut buf, "{:.3}", fp_secs).unwrap();
+
+        let (_, dur2) = fract_sec_duration(buf.as_bytes()).unwrap();
+
+        if dur != dur2 {
+            errors.push((dur, dur2));
+        }
+    }
+
+    if !errors.is_empty() {
+        for &(dur, dur2) in &errors {
+            println!("{:?} -> {:?}", dur, dur2);
+        }
+    }
+
+    assert_eq!(0, errors.len());
+}
+
 #[test]
 fn parse_start_time_with_human_date() {
     let (rest, e) = start_time(
         b"#[StartTime: 1441812279.474 (seconds since epoch), Wed Sep 09 08:24:39 PDT 2015]\nfoo",
     ).unwrap();
 
-    let expected = LogEntry::StartTime(1441812279.474);
+    let expected = LogEntry::StartTime(time::Duration::new(1441812279, 474_000_000));
 
     assert_eq!(expected, e);
     assert_eq!(b"foo", rest);
@@ -233,7 +302,7 @@ fn parse_start_time_without_human_date() {
     // Also, BaseTime doesn't have a human-formatted time.
     let (rest, e) = start_time(b"#[StartTime: 1441812279.474 (seconds since epoch)]\nfoo").unwrap();
 
-    let expected = LogEntry::StartTime(1441812279.474);
+    let expected = LogEntry::StartTime(time::Duration::new(1441812279, 474_000_000));
 
     assert_eq!(expected, e);
     assert_eq!(b"foo", rest);
@@ -243,7 +312,7 @@ fn parse_start_time_without_human_date() {
 fn parse_base_time() {
     let (rest, e) = base_time(b"#[BaseTime: 1441812279.474 (seconds since epoch)]\nfoo").unwrap();
 
-    let expected = LogEntry::BaseTime(1441812279.474);
+    let expected = LogEntry::BaseTime(time::Duration::new(1441812279, 474_000_000));
 
     assert_eq!(expected, e);
     assert_eq!(b"foo", rest);
@@ -271,8 +340,8 @@ fn parse_interval_hist_no_tag() {
 
     let expected = LogEntry::Interval(IntervalLogHistogram {
         tag: None,
-        start_timestamp: 0.127,
-        duration: 1.007,
+        start_timestamp: time::Duration::new(0, 127_000_000),
+        duration: time::Duration::new(1, 7_000_000),
         max: 2.769,
         encoded_histogram: "couldBeBase64",
     });
@@ -287,8 +356,8 @@ fn parse_interval_hist_with_tag() {
 
     let expected = LogEntry::Interval(IntervalLogHistogram {
         tag: Some(Tag("t")),
-        start_timestamp: 0.127,
-        duration: 1.007,
+        start_timestamp: time::Duration::new(0, 127_000_000),
+        duration: time::Duration::new(1, 7_000_000),
         max: 2.769,
         encoded_histogram: "couldBeBase64",
     });
@@ -311,13 +380,13 @@ fn iter_with_ignored_prefix() {
 
     let expected0 = LogEntry::Interval(IntervalLogHistogram {
         tag: Some(Tag("t")),
-        start_timestamp: 0.127,
-        duration: 1.007,
+        start_timestamp: time::Duration::new(0, 127_000_000),
+        duration: time::Duration::new(1, 7_000_000),
         max: 2.769,
         encoded_histogram: "couldBeBase64",
     });
 
-    let expected1 = LogEntry::StartTime(1441812279.474);
+    let expected1 = LogEntry::StartTime(time::Duration::new(1441812279, 474_000_000));
 
     assert_eq!(vec![expected0, expected1], entries)
 }
@@ -334,13 +403,13 @@ fn iter_without_ignored_prefix() {
 
     let expected0 = LogEntry::Interval(IntervalLogHistogram {
         tag: Some(Tag("t")),
-        start_timestamp: 0.127,
-        duration: 1.007,
+        start_timestamp: time::Duration::new(0, 127_000_000),
+        duration: time::Duration::new(1, 7_000_000),
         max: 2.769,
         encoded_histogram: "couldBeBase64",
     });
 
-    let expected1 = LogEntry::StartTime(1441812279.474);
+    let expected1 = LogEntry::StartTime(time::Duration::new(1441812279, 474_000_000));
 
     assert_eq!(vec![expected0, expected1], entries)
 }
@@ -363,14 +432,14 @@ fn iter_multiple_entrties_with_interleaved_ignored() {
 
     let expected0 = LogEntry::Interval(IntervalLogHistogram {
         tag: Some(Tag("t")),
-        start_timestamp: 0.127,
-        duration: 1.007,
+        start_timestamp: time::Duration::new(0, 127_000_000),
+        duration: time::Duration::new(1, 7_000_000),
         max: 2.769,
         encoded_histogram: "couldBeBase64",
     });
 
-    let expected1 = LogEntry::StartTime(1441812279.474);
-    let expected2 = LogEntry::BaseTime(1441812279.474);
+    let expected1 = LogEntry::StartTime(time::Duration::new(1441812279, 474_000_000));
+    let expected2 = LogEntry::BaseTime(time::Duration::new(1441812279, 474_000_000));
 
     assert_eq!(vec![expected0, expected1, expected2], entries)
 }