From 88b8c547e063a8125ce8384eef8af79c88f2c476 Mon Sep 17 00:00:00 2001
From: Bill Thiede <git@xinu.tv>
Date: Sun, 12 Feb 2023 14:09:11 -0800
Subject: [PATCH] rtiow: cleanup elapsed time logging.

---
 rtiow/renderer/src/renderer.rs | 22 +++++++++++-----------
 rtiow/tracer/src/main.rs       |  5 ++++-
 2 files changed, 15 insertions(+), 12 deletions(-)

diff --git a/rtiow/renderer/src/renderer.rs b/rtiow/renderer/src/renderer.rs
index 362b54c..adb875a 100644
--- a/rtiow/renderer/src/renderer.rs
+++ b/rtiow/renderer/src/renderer.rs
@@ -8,7 +8,7 @@ use std::{
         Arc, Mutex,
     },
     thread,
-    time::{self, Instant},
+    time::{Duration, Instant},
 };
 
 use core_affinity;
@@ -363,13 +363,13 @@ fn progress(
     start_time: Instant,
     last_stat: &RenderStats,
     current_stat: &RenderStats,
-    time_diff: time::Duration,
+    time_diff: Duration,
     pixel_total: usize,
 ) -> String {
     let human = human::Formatter::new();
     let pixel_diff = current_stat.pixels - last_stat.pixels;
     let ray_diff = current_stat.rays - last_stat.rays;
-    let now = time::Instant::now();
+    let now = Instant::now();
     let start_diff = now - start_time;
     let ratio = current_stat.pixels as f32 / pixel_total as f32;
     let percent = ratio * 100.;
@@ -577,10 +577,10 @@ pub fn render(scene: Scene, output_dir: &Path) -> std::result::Result<(), std::i
     info!("Rendering with {} subsamples", scene.subsamples);
 
     let pixel_total = scene.width * scene.height;
-    let mut last_time = time::Instant::now();
+    let mut last_time = Instant::now();
     let mut last_stat: RenderStats = Default::default();
     let mut current_stat: RenderStats = Default::default();
-    let start_time = time::Instant::now();
+    let render_start_time = Instant::now();
     for resp in pixel_resp_rx {
         match resp {
             Response::Pixel { x, y, pixel, rs } => {
@@ -595,13 +595,13 @@ pub fn render(scene: Scene, output_dir: &Path) -> std::result::Result<(), std::i
             }
         }
 
-        let now = time::Instant::now();
+        let now = Instant::now();
         let time_diff = now - last_time;
-        if time_diff > time::Duration::from_secs(5) {
+        if time_diff > Duration::from_secs(5) {
             println!(
                 "{}",
                 progress(
-                    start_time,
+                    render_start_time,
                     &last_stat,
                     &current_stat,
                     time_diff,
@@ -615,12 +615,12 @@ pub fn render(scene: Scene, output_dir: &Path) -> std::result::Result<(), std::i
     for thr in handles {
         thr.join().expect("thread join");
     }
-    let time_diff = time::Instant::now() - start_time;
+    let time_diff = Instant::now() - render_start_time;
     println!(
-        "Runtime {} seconds {}",
+        "Render {} seconds {}",
         time_diff.as_secs_f32(),
         progress(
-            start_time,
+            render_start_time,
             &Default::default(),
             &current_stat,
             time_diff,
diff --git a/rtiow/tracer/src/main.rs b/rtiow/tracer/src/main.rs
index f68d499..b6e63b9 100644
--- a/rtiow/tracer/src/main.rs
+++ b/rtiow/tracer/src/main.rs
@@ -1,5 +1,5 @@
 #![warn(unused_extern_crates)]
-use std::fs;
+use std::{fs, time::Instant};
 
 #[cfg(feature = "profile")]
 use cpuprofiler::PROFILER;
@@ -36,6 +36,7 @@ impl MockProfiler {
 static PROFILER: MockProfiler = MockProfiler {};
 
 fn main() -> Result<(), std::io::Error> {
+    let start_time = Instant::now();
     stderrlog::new()
         .verbosity(3)
         .timestamp(stderrlog::Timestamp::Millisecond)
@@ -65,5 +66,7 @@ fn main() -> Result<(), std::io::Error> {
         PROFILER.lock().unwrap().stop().unwrap();
     }
 
+    let time_diff = Instant::now() - start_time;
+    info!("Total runtime {} seconds", time_diff.as_secs_f32());
     res
 }