From 730228c8cb2c9fa5a01a565619b692528645fc30 Mon Sep 17 00:00:00 2001
From: Alex Crichton <alex@alexcrichton.com>
Date: Thu, 18 Jan 2018 13:00:53 -0600
Subject: [PATCH] Add debug logs for how long dispatch takes (#81)

I've often found this to be quite useful when debugging why event loops are
stuck or some other bug looks to be in play.
---
 Cargo.toml         |  2 +-
 src/reactor/mod.rs | 19 ++++++++++++++++++-
 2 files changed, 19 insertions(+), 2 deletions(-)

diff --git a/Cargo.toml b/Cargo.toml
index 70c02a405..bbade1ee3 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -18,7 +18,7 @@ appveyor = { repository = "alexcrichton/tokio" }
 
 [dependencies]
 bytes = "0.4"
-log = "0.3"
+log = "0.4"
 mio = "0.6.11"
 slab = "0.4"
 iovec = "0.1"
diff --git a/src/reactor/mod.rs b/src/reactor/mod.rs
index 33ea4cf11..c1daec477 100644
--- a/src/reactor/mod.rs
+++ b/src/reactor/mod.rs
@@ -26,8 +26,9 @@ use std::mem;
 use std::sync::atomic::Ordering::{Relaxed, SeqCst};
 use std::sync::atomic::{AtomicUsize, ATOMIC_USIZE_INIT};
 use std::sync::{Arc, Weak, RwLock};
-use std::time::{Duration};
+use std::time::{Duration, Instant};
 
+use log::Level;
 use futures::task::AtomicTask;
 use mio;
 use mio::event::Evented;
@@ -170,8 +171,16 @@ impl Reactor {
             Err(e) => return Err(e),
         }
 
+        let start = if log_enabled!(Level::Debug) {
+            Some(Instant::now())
+        } else {
+            None
+        };
+
         // Process all the events that came in, dispatching appropriately
+        let mut events = 0;
         for event in self.events.iter() {
+            events += 1;
             let token = event.token();
             trace!("event {:?} {:?}", event.readiness(), event.token());
 
@@ -182,6 +191,14 @@ impl Reactor {
             }
         }
 
+        if let Some(start) = start {
+            let dur = start.elapsed();
+            debug!("loop process - {} events, {}.{:03}s",
+                   events,
+                   dur.as_secs(),
+                   dur.subsec_nanos() / 1_000_000);
+        }
+
         Ok(())
     }