Added timer output so you can see how long things take.

Cargo.lock

@@ -11,6 +11,7 @@ dependencies = [
  "rustc-serialize 0.3.19 (registry+https://github.com/rust-lang/crates.io-index)",
  "scoped_threadpool 0.1.7 (registry+https://github.com/rust-lang/crates.io-index)",
  "simd 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)",
+ "time 0.1.35 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
 [[package]]
@@ -159,6 +160,16 @@ dependencies = [
  "thread-id 2.0.0 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
+[[package]]
+name = "time"
+version = "0.1.35"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "kernel32-sys 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)",
+ "libc 0.2.14 (registry+https://github.com/rust-lang/crates.io-index)",
+ "winapi 0.2.8 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "unreachable"
 version = "0.1.1"

Cargo.toml

@@ -10,6 +10,7 @@ simd_perf = ["simd"]
 debug = true
 
 [dependencies]
+time = "0.1"
 docopt = "0.6"
 rustc-serialize = "0.3"
 nom = "1.2"

src/main.rs

@@ -1,4 +1,5 @@
 extern crate rustc_serialize;
+extern crate time;
 extern crate docopt;
 extern crate scoped_threadpool;
 extern crate crossbeam;
@@ -12,6 +13,7 @@ extern crate simd;
 #[macro_use]
 extern crate nom;
 
+mod timer;
 mod math;
 mod hilbert;
 mod algorithm;
@@ -45,6 +47,7 @@ use std::fs::File;
 
 use docopt::Docopt;
 
+use timer::Timer;
 use ray::{Ray, AccelRay};
 use renderer::LightPath;
 use parse::{parse_scene, DataTree};
@@ -82,6 +85,8 @@ struct Args {
 // ----------------------------------------------------------------
 
 fn main() {
+    let mut t = Timer::new();
+
     // Parse command line arguments.
     let args: Args = Docopt::new(USAGE.replace("<VERSION>", VERSION))
         .and_then(|d| d.decode())
@@ -93,7 +98,13 @@ fn main() {
         return;
     }
 
+    // Print some misc useful dev info.
+    println!("Ray size:       {} bytes", mem::size_of::<Ray>());
+    println!("AccelRay size:  {} bytes", mem::size_of::<AccelRay>());
+    println!("LightPath size: {} bytes", mem::size_of::<LightPath>());
+
     // Parse data tree of scene file
+    t.tick();
     let mut s = String::new();
     let dt = if let Some(fp) = args.flag_input {
         let mut f = io::BufReader::new(File::open(fp).unwrap());
@@ -103,16 +114,15 @@ fn main() {
     } else {
         panic!()
     };
+    println!("Parsed scene file in {:.3}s\n", t.tick());
 
-    println!("Ray size:       {} bytes", mem::size_of::<Ray>());
-    println!("AccelRay size:  {} bytes", mem::size_of::<AccelRay>());
-    println!("LightPath size: {} bytes", mem::size_of::<LightPath>());
 
     // Iterate through scenes and render them
     if let DataTree::Internal { ref children, .. } = dt {
         for child in children {
+            t.tick();
             if child.type_name() == "Scene" {
-                println!("Parsing scene...");
+                println!("Building scene...");
                 let mut r = parse_scene(child).unwrap();
 
                 if let Some(spp) = args.flag_spp {
@@ -126,8 +136,11 @@ fn main() {
                     num_cpus::get() as u32
                 };
 
+                println!("Built scene in {:.3}s\n", t.tick());
+
                 println!("Rendering scene with {} threads...", thread_count);
                 r.render(thread_count);
+                println!("Rendered scene in {:.3}s", t.tick());
             }
         }
     }

src/timer.rs

@@ -0,0 +1,44 @@
+#![allow(dead_code)]
+
+use time;
+use std::time::Duration;
+use std::thread;
+
+#[derive(Copy, Clone)]
+pub struct Timer {
+    last_time: u64,
+}
+
+impl Timer {
+    pub fn new() -> Timer {
+        Timer { last_time: time::precise_time_ns() }
+    }
+
+    /// Marks a new tick time and returns the time elapsed in seconds since
+    /// the last call to tick().
+    pub fn tick(&mut self) -> f32 {
+        let n = time::precise_time_ns();
+        let dt = n - self.last_time;
+        self.last_time = n;
+
+        dt as f32 / 1000000000.0
+    }
+
+    /// Returns the time elapsed in seconds since the last call to tick().
+    pub fn elapsed(&self) -> f32 {
+        let dt = time::precise_time_ns() - self.last_time;
+        dt as f32 / 1000000000.0
+    }
+
+    /// Sleeps the current thread until n seconds after the last tick.
+    pub fn sleep_until(&self, n: f32) {
+        let dt = time::precise_time_ns() - self.last_time;
+        let target_dt = ((n as f64) * 1000000000.0) as u64;
+        if dt < target_dt {
+            let delay = target_dt - dt;
+            let seconds = delay / 1000000000;
+            let nanoseconds = delay % 1000000000;
+            thread::sleep(Duration::new(seconds, nanoseconds as u32));
+        }
+    }
+}