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

@@ -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"

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(())
     }